Skip to content
Permalink
Browse files
8266503: [UL] Make Decorations safely copy-able and reduce their size
Reviewed-by: simonis, ysuenaga
  • Loading branch information
tstuefe committed May 7, 2021
1 parent 86b8dc9 commit 74fecc070a6462e6a2d061525b53a63de15339f9
@@ -31,11 +31,7 @@
#include "services/management.hpp"

const char* volatile LogDecorations::_host_name = NULL;

LogDecorations::LogDecorations(LogLevelType level, const LogTagSet &tagset, const LogDecorators &decorators)
: _level(level), _tagset(tagset) {
create_decorations(decorators);
}
const int LogDecorations::_pid = os::current_process_id(); // This is safe to call during dynamic initialization.

const char* LogDecorations::host_name() {
const char* host_name = Atomic::load_acquire(&_host_name);
@@ -53,89 +49,95 @@ const char* LogDecorations::host_name() {
return host_name;
}

void LogDecorations::create_decorations(const LogDecorators &decorators) {
char* position = _decorations_buffer;
#define DECORATOR(full_name, abbr) \
if (decorators.is_decorator(LogDecorators::full_name##_decorator)) { \
_decoration_offset[LogDecorators::full_name##_decorator] = position; \
position = create_##full_name##_decoration(position) + 1; \
} else { \
_decoration_offset[LogDecorators::full_name##_decorator] = NULL; \
}
LogDecorations::LogDecorations(LogLevelType level, const LogTagSet &tagset, const LogDecorators &decorators) :
// When constructing the LogDecorations we resolve values for the requested decorators.
//
// _millis: needed for "time", "utctime", "timemillis":
_millis(
(decorators.is_decorator(LogDecorators::time_decorator) ||
decorators.is_decorator(LogDecorators::utctime_decorator) ||
decorators.is_decorator(LogDecorators::timemillis_decorator)) ? os::javaTimeMillis() : 0),
// _nanos: needed for "timenanos"
_nanos(decorators.is_decorator(LogDecorators::timenanos_decorator) ? os::javaTimeNanos() : 0),
// _elapsed_seconds: needed for "uptime", "uptimemillis", "uptimenanos"
_elapsed_seconds(
(decorators.is_decorator(LogDecorators::uptime_decorator) ||
decorators.is_decorator(LogDecorators::uptimemillis_decorator) ||
decorators.is_decorator(LogDecorators::uptimenanos_decorator)) ? os::elapsedTime() : 0),
// tid
_tid(decorators.is_decorator(LogDecorators::tid_decorator) ? os::current_thread_id() : 0),
// the rest is handed down by the caller
_level(level), _tagset(tagset)
#ifdef ASSERT
, _decorators(decorators)
#endif
{
}

void LogDecorations::print_decoration(LogDecorators::Decorator decorator, outputStream* st) const {
assert(_decorators.is_decorator(decorator), "decorator was not part of the decorator set specified at creation.");
switch(decorator) {
#define DECORATOR(name, abbr) case LogDecorators:: name##_decorator: print_##name##_decoration(st); break;
DECORATOR_LIST
#undef DECORATOR
default: ShouldNotReachHere();
}
}

#define ASSERT_AND_RETURN(written, pos) \
assert(written >= 0, "Decorations buffer overflow"); \
return pos + written;

char* LogDecorations::create_time_decoration(char* pos) {
char* buf = os::iso8601_time(pos, 29);
int written = buf == NULL ? -1 : 29;
ASSERT_AND_RETURN(written, pos)
const char* LogDecorations::decoration(LogDecorators::Decorator decorator, char* buf, size_t buflen) const {
stringStream ss(buf, buflen);
print_decoration(decorator, &ss);
return buf;
}

char* LogDecorations::create_utctime_decoration(char* pos) {
char* buf = os::iso8601_time(pos, 29, true);
int written = buf == NULL ? -1 : 29;
ASSERT_AND_RETURN(written, pos)
void LogDecorations::print_time_decoration(outputStream* st) const {
char buf[os::iso8601_timestamp_size];
char* result = os::iso8601_time(_millis, buf, sizeof(buf), false);
st->print_raw(result ? result : "");
}

char * LogDecorations::create_uptime_decoration(char* pos) {
int written = jio_snprintf(pos, DecorationsBufferSize - (pos - _decorations_buffer), "%.3fs", os::elapsedTime());
ASSERT_AND_RETURN(written, pos)
void LogDecorations::print_utctime_decoration(outputStream* st) const {
char buf[os::iso8601_timestamp_size];
char* result = os::iso8601_time(_millis, buf, sizeof(buf), true);
st->print_raw(result ? result : "");
}

char * LogDecorations::create_timemillis_decoration(char* pos) {
int written = jio_snprintf(pos, DecorationsBufferSize - (pos - _decorations_buffer), INT64_FORMAT "ms", os::javaTimeMillis());
ASSERT_AND_RETURN(written, pos)
void LogDecorations::print_uptime_decoration(outputStream* st) const {
st->print("%.3fs", _elapsed_seconds);
}

// Small helper for uptime conversion
static jlong elapsed_time(int unit_multiplier) {
return (jlong)(os::elapsedTime() * unit_multiplier);
void LogDecorations::print_timemillis_decoration(outputStream* st) const {
st->print(INT64_FORMAT "ms", (int64_t)_millis);
}

char * LogDecorations::create_uptimemillis_decoration(char* pos) {
int written = jio_snprintf(pos, DecorationsBufferSize - (pos - _decorations_buffer),
INT64_FORMAT "ms", elapsed_time(MILLIUNITS));
ASSERT_AND_RETURN(written, pos)
void LogDecorations::print_uptimemillis_decoration(outputStream* st) const {
st->print(INT64_FORMAT "ms", (int64_t)(_elapsed_seconds * MILLIUNITS));
}

char * LogDecorations::create_timenanos_decoration(char* pos) {
int written = jio_snprintf(pos, DecorationsBufferSize - (pos - _decorations_buffer), INT64_FORMAT "ns", os::javaTimeNanos());
ASSERT_AND_RETURN(written, pos)
void LogDecorations::print_timenanos_decoration(outputStream* st) const {
st->print(INT64_FORMAT "ns", (int64_t)_nanos);
}

char * LogDecorations::create_uptimenanos_decoration(char* pos) {
int written = jio_snprintf(pos, DecorationsBufferSize - (pos - _decorations_buffer), INT64_FORMAT "ns", elapsed_time(NANOUNITS));
ASSERT_AND_RETURN(written, pos)
void LogDecorations::print_uptimenanos_decoration(outputStream* st) const {
st->print(INT64_FORMAT "ns", (int64_t)(_elapsed_seconds * NANOUNITS));
}

char * LogDecorations::create_pid_decoration(char* pos) {
int written = jio_snprintf(pos, DecorationsBufferSize - (pos - _decorations_buffer), "%d", os::current_process_id());
ASSERT_AND_RETURN(written, pos)
void LogDecorations::print_pid_decoration(outputStream* st) const {
st->print("%d", _pid);
}

char * LogDecorations::create_tid_decoration(char* pos) {
int written = jio_snprintf(pos, DecorationsBufferSize - (pos - _decorations_buffer),
INTX_FORMAT, os::current_thread_id());
ASSERT_AND_RETURN(written, pos)
void LogDecorations::print_tid_decoration(outputStream* st) const {
st->print(INTX_FORMAT, _tid);
}

char* LogDecorations::create_level_decoration(char* pos) {
// Avoid generating the level decoration because it may change.
// The decoration() method has a special case for level decorations.
return pos;
void LogDecorations::print_level_decoration(outputStream* st) const {
st->print_raw(LogLevel::name(_level));
}

char* LogDecorations::create_tags_decoration(char* pos) {
int written = _tagset.label(pos, DecorationsBufferSize - (pos - _decorations_buffer));
ASSERT_AND_RETURN(written, pos)
void LogDecorations::print_tags_decoration(outputStream* st) const {
_tagset.label(st);
}

char* LogDecorations::create_hostname_decoration(char* pos) {
int written = jio_snprintf(pos, DecorationsBufferSize - (pos - _decorations_buffer), "%s", host_name());
ASSERT_AND_RETURN(written, pos)
void LogDecorations::print_hostname_decoration(outputStream* st) const {
st->print_raw(host_name());
}
@@ -27,37 +27,46 @@
#include "logging/logDecorators.hpp"
#include "logging/logTagSet.hpp"

// Temporary object containing the necessary data for a log call's decorations (timestamps, etc).
class outputStream;

// LogDecorations keeps resolved values for decorators, as well as the
// printing code to print them. The values are resolved at the log site (in the
// constructor of LogDecorations); the printing happens when the log message is
// printed. That may happen delayed, and the object may be stored for some time,
// in the context of asynchronous logging. Therefore size of this object matters.
class LogDecorations {
public:
static const int DecorationsBufferSize = 256;
private:
char _decorations_buffer[DecorationsBufferSize];
char* _decoration_offset[LogDecorators::Count];
LogLevelType _level;
const LogTagSet& _tagset;
static const char* volatile _host_name;

const char* host_name();
void create_decorations(const LogDecorators& decorators);
const jlong _millis; // for "time", "utctime", "timemillis"
const jlong _nanos; // for "timenanos"
const double _elapsed_seconds; // for "uptime", "uptimemillis", "uptimenanos"
const intx _tid; // for "tid"
LogLevelType _level; // for "level" (needs to be nonconst)
const LogTagSet& _tagset; // for "tags"
// In debug mode we keep the decorators around for sanity checking when printing
DEBUG_ONLY(const LogDecorators& _decorators;)

static const char* volatile _host_name;
static const char* host_name();
static const int _pid; // for "pid"

#define DECORATOR(name, abbr) char* create_##name##_decoration(char* pos);
#define DECORATOR(name, abbr) void print_##name##_decoration(outputStream* st) const;
DECORATOR_LIST
#undef DECORATOR

public:

// max size of a single decoration.
static const size_t max_decoration_size = 255;

LogDecorations(LogLevelType level, const LogTagSet& tagset, const LogDecorators& decorators);

void set_level(LogLevelType level) {
_level = level;
}

const char* decoration(LogDecorators::Decorator decorator) const {
if (decorator == LogDecorators::level_decorator) {
return LogLevel::name(_level);
}
return _decoration_offset[decorator];
}
void print_decoration(LogDecorators::Decorator decorator, outputStream* st) const;
const char* decoration(LogDecorators::Decorator decorator, char* buf, size_t buflen) const;

};

#endif // SHARE_LOGGING_LOGDECORATIONS_HPP
@@ -53,6 +53,7 @@ LogFileStreamInitializer::LogFileStreamInitializer() {

int LogFileStreamOutput::write_decorations(const LogDecorations& decorations) {
int total_written = 0;
char buf[LogDecorations::max_decoration_size + 1];

for (uint i = 0; i < LogDecorators::Count; i++) {
LogDecorators::Decorator decorator = static_cast<LogDecorators::Decorator>(i);
@@ -62,7 +63,7 @@ int LogFileStreamOutput::write_decorations(const LogDecorations& decorations) {

int written = jio_fprintf(_stream, "[%-*s]",
_decorator_padding[decorator],
decorations.decoration(decorator));
decorations.decoration(decorator, buf, sizeof(buf)));
if (written <= 0) {
return -1;
} else if (static_cast<size_t>(written - 2) > _decorator_padding[decorator]) {
@@ -86,18 +86,20 @@ void LogTagSet::log(const LogMessageBuffer& msg) {
}
}

int LogTagSet::label(char* buf, size_t len, const char* separator) const {
int tot_written = 0;
void LogTagSet::label(outputStream* st, const char* separator) const {
for (size_t i = 0; i < _ntags; i++) {
int written = jio_snprintf(buf + tot_written, len - tot_written, "%s%s",
(i == 0 ? "" : separator),
LogTag::name(_tag[i]));
if (written < 0) {
return -1;
}
tot_written += written;
st->print("%s%s", (i == 0 ? "" : separator), LogTag::name(_tag[i]));
}
}

int LogTagSet::label(char* buf, size_t len, const char* separator) const {
stringStream ss(buf, len);
label(&ss, separator);
size_t written = ss.size();
if (written >= len - 1) {
return -1; // truncation
}
return tot_written;
return (int)written;
}

void LogTagSet::write(LogLevelType level, const char* fmt, ...) {
@@ -172,9 +174,9 @@ static const size_t TagSetBufferSize = 128;
void LogTagSet::describe_tagsets(outputStream* out) {
out->print_cr("Described tag sets:");
for (const LogTagSetDescription* d = tagset_descriptions; d->tagset != NULL; d++) {
char buf[TagSetBufferSize];
d->tagset->label(buf, sizeof(buf), "+");
out->print_cr(" %s: %s", buf, d->descr);
out->sp();
d->tagset->label(out, "+");
out->print_cr(": %s", d->descr);
}
}

@@ -206,4 +208,3 @@ void LogTagSet::list_all_tagsets(outputStream* out) {
out->cr();
FREE_C_HEAP_ARRAY(char*, tagset_labels);
}

@@ -33,6 +33,8 @@

class LogMessageBuffer;

class outputStream;

// The tagset represents a combination of tags that occur in a log call somewhere.
// Tagsets are created automatically by the LogTagSetMappings and should never be
// instantiated directly somewhere else.
@@ -110,6 +112,7 @@ class LogTagSet {
// of its current outputs combined with the given decorators.
void update_decorators(const LogDecorators& decorator = LogDecorators::None);

void label(outputStream* st, const char* separator = ",") const;
int label(char *buf, size_t len, const char* separator = ",") const;
bool has_output(const LogOutput* output);

Loading

1 comment on commit 74fecc0

@openjdk-notifier

This comment has been minimized.

Copy link

@openjdk-notifier openjdk-notifier bot commented on 74fecc0 May 7, 2021

Please sign in to comment.