8237857: LogDecorations::uptimenanos is implemented incorrectly

Reviewed-by: dcubed, kbarrett

src/hotspot/share/logging/logConfiguration.cpp

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2015, 2019, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2015, 2020, Oracle and/or its affiliates. All rights reserved.
  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
  *
  * This code is free software; you can redistribute it and/or modify it
@@ -102,7 +102,6 @@ void LogConfiguration::post_initialize() {
 
 void LogConfiguration::initialize(jlong vm_start_time) {
   LogFileOutput::set_file_name_parameters(vm_start_time);
-  LogDecorations::initialize(vm_start_time);
   assert(_outputs == NULL, "Should not initialize _outputs before this function, initialize called twice?");
   _outputs = NEW_C_HEAP_ARRAY(LogOutput*, 2, mtLogging);
   _outputs[0] = &StdoutLog;

src/hotspot/share/logging/logDecorations.cpp

@@ -30,18 +30,13 @@
 #include "runtime/thread.inline.hpp"
 #include "services/management.hpp"
 
-jlong LogDecorations::_vm_start_time_millis = 0;
 const char* volatile LogDecorations::_host_name = NULL;
 
 LogDecorations::LogDecorations(LogLevelType level, const LogTagSet &tagset, const LogDecorators &decorators)
     : _level(level), _tagset(tagset) {
   create_decorations(decorators);
 }
 
-void LogDecorations::initialize(jlong vm_start_time) {
-  _vm_start_time_millis = vm_start_time;
-}
-
 const char* LogDecorations::host_name() {
   const char* host_name = Atomic::load_acquire(&_host_name);
   if (host_name == NULL) {
@@ -97,9 +92,14 @@ char * LogDecorations::create_timemillis_decoration(char* pos) {
   ASSERT_AND_RETURN(written, pos)
 }
 
+// Small helper for uptime conversion
+static jlong elapsed_time(int unit_multiplier) {
+  return (jlong)(os::elapsedTime() * unit_multiplier);
+}
+
 char * LogDecorations::create_uptimemillis_decoration(char* pos) {
   int written = jio_snprintf(pos, DecorationsBufferSize - (pos - _decorations_buffer),
-                             INT64_FORMAT "ms", nanos_to_millis(os::elapsed_counter()));
+                             INT64_FORMAT "ms", elapsed_time(MILLIUNITS));
   ASSERT_AND_RETURN(written, pos)
 }
 
@@ -109,7 +109,7 @@ char * LogDecorations::create_timenanos_decoration(char* pos) {
 }
 
 char * LogDecorations::create_uptimenanos_decoration(char* pos) {
-  int written = jio_snprintf(pos, DecorationsBufferSize - (pos - _decorations_buffer), INT64_FORMAT "ns", os::elapsed_counter());
+  int written = jio_snprintf(pos, DecorationsBufferSize - (pos - _decorations_buffer), INT64_FORMAT "ns", elapsed_time(NANOUNITS));
   ASSERT_AND_RETURN(written, pos)
 }
 

src/hotspot/share/logging/logDecorations.hpp

@@ -36,7 +36,6 @@ class LogDecorations {
   char* _decoration_offset[LogDecorators::Count];
   LogLevelType _level;
   const LogTagSet& _tagset;
-  static jlong _vm_start_time_millis;
   static const char* volatile _host_name;
 
   const char* host_name();
@@ -47,8 +46,6 @@ class LogDecorations {
 #undef DECORATOR
 
  public:
-  static void initialize(jlong vm_start_time);
-
   LogDecorations(LogLevelType level, const LogTagSet& tagset, const LogDecorators& decorators);
 
   void set_level(LogLevelType level) {

test/hotspot/gtest/logging/test_logDecorations.cpp

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2016, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2016, 2020, Oracle and/or its affiliates. All rights reserved.
  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
  *
  * This code is free software; you can redistribute it and/or modify it
@@ -86,14 +86,16 @@ TEST_VM(LogDecorations, timestamps) {
   struct {
     const LogDecorators::Decorator decorator;
     const char* suffix;
+    const char* desc;
   } test_decorator[] = {
-    { LogDecorators::timemillis_decorator, "ms" },
-    { LogDecorators::uptimemillis_decorator, "ms" },
-    { LogDecorators::timenanos_decorator, "ns" },
-    { LogDecorators::uptimenanos_decorator, "ns" }
+    { LogDecorators::timemillis_decorator, "ms", "timemillis" },
+    { LogDecorators::uptimemillis_decorator, "ms", "uptimemillis" },
+    { LogDecorators::timenanos_decorator, "ns", "timenanos" },
+    { LogDecorators::uptimenanos_decorator, "ns", "uptimenanos" }
   };
 
   for (uint i = 0; i < ARRAY_SIZE(test_decorator); i++) {
+    tty->print_cr("Processing Decorator %s", test_decorator[i].desc);
     LogDecorators::Decorator decorator = test_decorator[i].decorator;
     LogDecorators decorator_selection;
     ASSERT_TRUE(decorator_selection.parse(LogDecorators::name(decorator)));
@@ -112,9 +114,13 @@ TEST_VM(LogDecorations, timestamps) {
     // Verify timestamp values
     julong prev = 0;
     for (int i = 0; i < 3; i++) {
-      os::naked_short_sleep(5);
+      // The sleep needs to be longer than the timer resolution to ensure
+      // we see updates to 'timemillis'. Windows has the lowest resolution
+      // at 15-16ms, so we use 20.
+      os::naked_short_sleep(20);
       LogDecorations d(LogLevel::Info, tagset, decorator_selection);
       julong val = strtoull(d.decoration(decorator), NULL, 10);
+      tty->print_cr("Read value: " UINT64_FORMAT, val);
       ASSERT_LT(prev, val);
       prev = val;
     }