8237857: LogDecorations::uptimenanos is implemented incorrectly

Reviewed-by: dcubed, kbarrett
This commit is contained in:
David Holmes 2020-01-29 23:53:16 -05:00
parent 0b45b7a291
commit c4b708b255
4 changed files with 20 additions and 18 deletions

View File

@ -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;

View File

@ -30,7 +30,6 @@
#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)
@ -38,10 +37,6 @@ LogDecorations::LogDecorations(LogLevelType level, const LogTagSet &tagset, cons
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)
}

View File

@ -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) {

View File

@ -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;
}