8168722: Unified Logging configuration output needs simplifying

Reviewed-by: rehn, lfoltan, hseigel
This commit is contained in:
Marcus Larsson 2018-02-28 22:38:53 +01:00
parent 1392d4b80f
commit 98c77d44de
8 changed files with 346 additions and 77 deletions

@ -220,8 +220,7 @@ void LogConfiguration::configure_output(size_t idx, const LogSelectionList& sele
output->_reconfigured = true;
// Clear the previous config description
output->clear_config_string();
size_t on_level[LogLevel::Count] = {0};
bool enabled = false;
for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
@ -229,6 +228,7 @@ void LogConfiguration::configure_output(size_t idx, const LogSelectionList& sele
// Ignore tagsets that do not, and will not log on the output
if (!ts->has_output(output) && (level == LogLevel::NotMentioned || level == LogLevel::Off)) {
on_level[LogLevel::Off]++;
continue;
}
@ -241,20 +241,18 @@ void LogConfiguration::configure_output(size_t idx, const LogSelectionList& sele
// Set the new level, if it changed
if (level != LogLevel::NotMentioned) {
ts->set_output_level(output, level);
} else {
// Look up the previously set level for this output on this tagset
level = ts->level_for(output);
}
if (level != LogLevel::Off) {
// Keep track of whether or not the output is ever used by some tagset
enabled = true;
if (level == LogLevel::NotMentioned) {
// Look up the previously set level for this output on this tagset
level = ts->level_for(output);
}
// Update the config description with this tagset and level
output->add_to_config_string(ts, level);
}
// Track of the number of tag sets on each level
on_level[level]++;
}
// It is now safe to set the new decorators for the actual output
@ -265,17 +263,14 @@ void LogConfiguration::configure_output(size_t idx, const LogSelectionList& sele
ts->update_decorators();
}
if (enabled) {
assert(strlen(output->config_string()) > 0,
"Should always have a config description if the output is enabled.");
} else if (idx > 1) {
// Output is unused and should be removed.
if (!enabled && idx > 1) {
// Output is unused and should be removed, unless it is stdout/stderr (idx < 2)
delete_output(idx);
} else {
// Output is either stdout or stderr, which means we can't remove it.
// Update the config description to reflect that the output is disabled.
output->set_config_string("all=off");
return;
}
output->update_config_string(on_level);
assert(strlen(output->config_string()) > 0, "should always have a config description");
}
void LogConfiguration::disable_output(size_t idx) {

@ -23,8 +23,10 @@
*/
#include "precompiled.hpp"
#include "jvm.h"
#include "logging/log.hpp"
#include "logging/logFileStreamOutput.hpp"
#include "logging/logOutput.hpp"
#include "logging/logSelection.hpp"
#include "logging/logTagSet.hpp"
#include "memory/allocation.inline.hpp"
#include "runtime/mutexLocker.hpp"
@ -34,54 +36,6 @@ LogOutput::~LogOutput() {
os::free(_config_string);
}
void LogOutput::clear_config_string() {
os::free(_config_string);
_config_string_buffer_size = InitialConfigBufferSize;
_config_string = NEW_C_HEAP_ARRAY(char, _config_string_buffer_size, mtLogging);
_config_string[0] = '\0';
}
void LogOutput::set_config_string(const char* string) {
os::free(_config_string);
_config_string = os::strdup(string, mtLogging);
_config_string_buffer_size = strlen(_config_string) + 1;
}
void LogOutput::add_to_config_string(const LogTagSet* ts, LogLevelType level) {
if (_config_string_buffer_size < InitialConfigBufferSize) {
_config_string_buffer_size = InitialConfigBufferSize;
_config_string = REALLOC_C_HEAP_ARRAY(char, _config_string, _config_string_buffer_size, mtLogging);
}
size_t offset = strlen(_config_string);
if (offset > 0) {
// Add commas in-between tag and level combinations in the config string
_config_string[offset++] = ',';
}
for (;;) {
int ret = ts->label(_config_string + offset, _config_string_buffer_size - offset, "+");
if (ret == -1) {
// Double the buffer size and retry
_config_string_buffer_size *= 2;
_config_string = REALLOC_C_HEAP_ARRAY(char, _config_string, _config_string_buffer_size, mtLogging);
continue;
}
break;
};
offset = strlen(_config_string);
for (;;) {
int ret = jio_snprintf(_config_string + offset, _config_string_buffer_size - offset, "=%s", LogLevel::name(level));
if (ret == -1) {
_config_string_buffer_size *= 2;
_config_string = REALLOC_C_HEAP_ARRAY(char, _config_string, _config_string_buffer_size, mtLogging);
continue;
}
break;
}
}
void LogOutput::describe(outputStream *out) {
out->print("%s ", name());
out->print_raw(config_string()); // raw printed because length might exceed O_BUFLEN
@ -101,3 +55,286 @@ void LogOutput::describe(outputStream *out) {
}
}
void LogOutput::set_config_string(const char* string) {
os::free(_config_string);
_config_string = os::strdup(string, mtLogging);
_config_string_buffer_size = strlen(_config_string) + 1;
}
void LogOutput::add_to_config_string(const LogSelection& selection) {
if (_config_string_buffer_size < InitialConfigBufferSize) {
_config_string_buffer_size = InitialConfigBufferSize;
_config_string = REALLOC_C_HEAP_ARRAY(char, _config_string, _config_string_buffer_size, mtLogging);
}
size_t offset = strlen(_config_string);
if (offset > 0) {
// Add commas in-between tag and level combinations in the config string
_config_string[offset++] = ',';
}
for (;;) {
int ret = selection.describe(_config_string + offset,
_config_string_buffer_size - offset);
if (ret == -1) {
// Double the buffer size and retry
_config_string_buffer_size *= 2;
_config_string = REALLOC_C_HEAP_ARRAY(char, _config_string, _config_string_buffer_size, mtLogging);
continue;
}
break;
};
}
static int tag_cmp(const void *a, const void *b) {
return static_cast<const LogTagType*>(a) - static_cast<const LogTagType*>(b);
}
static void sort_tags(LogTagType tags[LogTag::MaxTags]) {
size_t ntags = 0;
while (tags[ntags] != LogTag::__NO_TAG) {
ntags++;
}
qsort(tags, ntags, sizeof(*tags), tag_cmp);
}
static const size_t MaxSubsets = 1 << LogTag::MaxTags;
// Fill result with all possible subsets of the given tag set. Empty set not included.
// For example, if tags is {gc, heap} then the result is {{gc}, {heap}, {gc, heap}}.
// (Arguments with default values are intended exclusively for recursive calls.)
static void generate_all_subsets_of(LogTagType result[MaxSubsets][LogTag::MaxTags],
size_t* result_size,
const LogTagType tags[LogTag::MaxTags],
LogTagType subset[LogTag::MaxTags] = NULL,
const size_t subset_size = 0,
const size_t depth = 0) {
assert(subset_size <= LogTag::MaxTags, "subset must never have more than MaxTags tags");
assert(depth <= LogTag::MaxTags, "recursion depth overflow");
if (subset == NULL) {
assert(*result_size == 0, "outer (non-recursive) call expects result_size to be 0");
// Make subset the first element in the result array initially
subset = result[0];
}
assert((void*) subset >= result && (void*) subset < result + sizeof(result),
"subset should always point to element in result");
if (depth == LogTag::MaxTags || tags[depth] == LogTag::__NO_TAG) {
if (subset_size == 0) {
// Ignore empty subset
return;
}
if (subset_size != LogTag::MaxTags) {
subset[subset_size] = LogTag::__NO_TAG;
}
assert(*result_size < MaxSubsets, "subsets overflow");
*result_size += 1;
// Bump subset and copy over current state
memcpy(result[*result_size], subset, sizeof(*subset) * LogTag::MaxTags);
subset = result[*result_size];
return;
}
// Recurse, excluding the tag of the current depth
generate_all_subsets_of(result, result_size, tags, subset, subset_size, depth + 1);
// ... and with it included
subset[subset_size] = tags[depth];
generate_all_subsets_of(result, result_size, tags, subset, subset_size + 1, depth + 1);
}
// Generate all possible selections (for the given level) based on the given tag set,
// and add them to the selections array (growing it as necessary).
static void add_selections(LogSelection** selections,
size_t* n_selections,
size_t* selections_cap,
const LogTagSet& tagset,
LogLevelType level) {
LogTagType tags[LogTag::MaxTags] = { LogTag::__NO_TAG };
for (size_t i = 0; i < tagset.ntags(); i++) {
tags[i] = tagset.tag(i);
}
size_t n_subsets = 0;
LogTagType subsets[MaxSubsets][LogTag::MaxTags];
generate_all_subsets_of(subsets, &n_subsets, tags);
for (size_t i = 0; i < n_subsets; i++) {
// Always keep tags sorted
sort_tags(subsets[i]);
// Ignore subsets already represented in selections
bool unique = true;
for (size_t sel = 0; sel < *n_selections; sel++) {
if (level == (*selections)[sel].level() && (*selections)[sel].consists_of(subsets[i])) {
unique = false;
break;
}
}
if (!unique) {
continue;
}
LogSelection exact_selection(subsets[i], false, level);
LogSelection wildcard_selection(subsets[i], true, level);
// Check if the two selections match any tag sets
bool wildcard_match = false;
bool exact_match = false;
for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
if (!wildcard_selection.selects(*ts)) {
continue;
}
wildcard_match = true;
if (exact_selection.selects(*ts)) {
exact_match = true;
}
if (exact_match) {
break;
}
}
if (!wildcard_match && !exact_match) {
continue;
}
// Ensure there's enough room for both wildcard_match and exact_match
if (*n_selections + 2 > *selections_cap) {
*selections_cap *= 2;
*selections = REALLOC_C_HEAP_ARRAY(LogSelection, *selections, *selections_cap, mtLogging);
}
// Add found matching selections to the result array
if (exact_match) {
(*selections)[(*n_selections)++] = exact_selection;
}
if (wildcard_match) {
(*selections)[(*n_selections)++] = wildcard_selection;
}
}
}
void LogOutput::update_config_string(const size_t on_level[LogLevel::Count]) {
// Find the most common level (MCL)
LogLevelType mcl = LogLevel::Off;
size_t max = on_level[LogLevel::Off];
for (LogLevelType l = LogLevel::First; l <= LogLevel::Last; l = static_cast<LogLevelType>(l + 1)) {
if (on_level[l] > max) {
mcl = l;
max = on_level[l];
}
}
// Always let the first part of each output's config string be "all=<MCL>"
{
char buf[64];
jio_snprintf(buf, sizeof(buf), "all=%s", LogLevel::name(mcl));
set_config_string(buf);
}
// If there are no deviating tag sets, we're done
size_t deviating_tagsets = LogTagSet::ntagsets() - max;
if (deviating_tagsets == 0) {
return;
}
size_t n_selections = 0;
size_t selections_cap = 4 * MaxSubsets; // Start with some reasonably large initial capacity
LogSelection* selections = NEW_C_HEAP_ARRAY(LogSelection, selections_cap, mtLogging);
size_t n_deviates = 0;
const LogTagSet** deviates = NEW_C_HEAP_ARRAY(const LogTagSet*, deviating_tagsets, mtLogging);
// Generate all possible selections involving the deviating tag sets
for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
LogLevelType level = ts->level_for(this);
if (level == mcl) {
continue;
}
deviates[n_deviates++] = ts;
add_selections(&selections, &n_selections, &selections_cap, *ts, level);
}
// Reduce deviates greedily, using the "best" selection at each step to reduce the number of deviating tag sets
while (n_deviates > 0) {
size_t prev_deviates = n_deviates;
int max_score = 0;
const LogSelection* best_selection = NULL;
for (size_t i = 0; i < n_selections; i++) {
// Give the selection a score based on how many deviating tag sets it selects (with correct level)
int score = 0;
for (size_t d = 0; d < n_deviates; d++) {
if (selections[i].selects(*deviates[d]) && deviates[d]->level_for(this) == selections[i].level()) {
score++;
}
}
// Ignore selections with lower score than the current best even before subtracting mismatched selections
if (score < max_score) {
continue;
}
// Subtract from the score the number of tag sets it selects with an incorrect level
for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
if (selections[i].selects(*ts) && ts->level_for(this) != selections[i].level()) {
score--;
}
}
// Pick the selection with the best score, or in the case of a tie, the one with fewest tags
if (score > max_score ||
(score == max_score && best_selection != NULL && selections[i].ntags() < best_selection->ntags())) {
max_score = score;
best_selection = &selections[i];
}
}
assert(best_selection != NULL, "must always find a maximal selection");
add_to_config_string(*best_selection);
// Remove all deviates that this selection covered
for (size_t d = 0; d < n_deviates;) {
if (deviates[d]->level_for(this) == best_selection->level() && best_selection->selects(*deviates[d])) {
deviates[d] = deviates[--n_deviates];
continue;
}
d++;
}
// Add back any new deviates that this selection added (no array growth since removed > added)
for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
if (ts->level_for(this) == best_selection->level() || !best_selection->selects(*ts)) {
continue;
}
bool already_added = false;
for (size_t dev = 0; dev < n_deviates; dev++) {
if (deviates[dev] == ts) {
already_added = true;
break;
}
}
if (already_added) {
continue;
}
deviates[n_deviates++] = ts;
}
// Reset the selections and generate a new ones based on the updated deviating tag sets
n_selections = 0;
for (size_t d = 0; d < n_deviates; d++) {
add_selections(&selections, &n_selections, &selections_cap, *deviates[d], deviates[d]->level_for(this));
}
assert(n_deviates < deviating_tagsets, "deviating tag set array overflow");
assert(prev_deviates > n_deviates, "number of deviating tag sets must never grow");
}
FREE_C_HEAP_ARRAY(LogTagSet*, deviates);
FREE_C_HEAP_ARRAY(Selection, selections);
}

@ -32,6 +32,7 @@
class LogDecorations;
class LogMessageBuffer;
class LogSelection;
class LogTagSet;
// The base class/interface for log outputs.
@ -52,16 +53,18 @@ class LogOutput : public CHeapObj<mtLogging> {
char* _config_string;
size_t _config_string_buffer_size;
// Adds the log selection to the config description (e.g. "tag1+tag2*=level").
void add_to_config_string(const LogSelection& selection);
protected:
LogDecorators _decorators;
// Clears any previous config description in preparation of reconfiguration.
void clear_config_string();
// Adds the tagset on the given level to the config description (e.g. "tag1+tag2=level").
void add_to_config_string(const LogTagSet* ts, LogLevelType level);
// Replaces the current config description with the given string.
void set_config_string(const char* string);
// Update the config string for this output to reflect its current configuration
void update_config_string(const size_t on_level[LogLevel::Count]);
public:
void set_decorators(const LogDecorators &decorators) {
_decorators = decorators;

@ -170,6 +170,25 @@ bool LogSelection::selects(const LogTagSet& ts) const {
return true;
}
static bool contains(LogTagType tag, const LogTagType tags[LogTag::MaxTags], size_t ntags) {
for (size_t i = 0; i < ntags; i++) {
if (tags[i] == tag) {
return true;
}
}
return false;
}
bool LogSelection::consists_of(const LogTagType tags[LogTag::MaxTags]) const {
size_t i;
for (i = 0; tags[i] != LogTag::__NO_TAG; i++) {
if (!contains(tags[i], _tags, _ntags)) {
return false;
}
}
return i == _ntags;
}
size_t LogSelection::ntags() const {
return _ntags;
}

@ -59,6 +59,7 @@ class LogSelection : public StackObj {
size_t tag_sets_selected() const;
bool selects(const LogTagSet& ts) const;
bool consists_of(const LogTagType tags[LogTag::MaxTags]) const;
int describe_tags(char* buf, size_t bufsize) const;
int describe(char* buf, size_t bufsize) const;

@ -113,7 +113,7 @@ TEST_VM_F(LogConfigurationTest, describe) {
EXPECT_FALSE(is_described(TestLogFileName)) << "Test output already exists!";
set_log_config(TestLogFileName, what);
EXPECT_TRUE(is_described(TestLogFileName));
EXPECT_TRUE(is_described("logging=trace"));
EXPECT_TRUE(is_described("all=trace"));
}
// Test updating an existing log output
@ -125,7 +125,7 @@ TEST_VM_F(LogConfigurationTest, update_output) {
// Verify configuration using LogConfiguration::describe
EXPECT_TRUE(is_described("#0: stdout"));
EXPECT_TRUE(is_described("logging=info"));
EXPECT_TRUE(is_described("all=info"));
// Verify by iterating over tagsets
LogOutput* o = &StdoutLog;
@ -154,7 +154,7 @@ TEST_VM_F(LogConfigurationTest, add_new_output) {
// Verify new output using LogConfiguration::describe
EXPECT_TRUE(is_described(TestLogFileName));
EXPECT_TRUE(is_described("logging=trace"));
EXPECT_TRUE(is_described("all=trace"));
// Also verify by iterating over tagsets, checking levels on tagsets
for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
@ -265,7 +265,7 @@ TEST_VM_F(LogConfigurationTest, parse_command_line_arguments) {
bool success = LogConfiguration::parse_command_line_arguments(buf);
EXPECT_TRUE(success) << "Error parsing valid command line arguments '" << buf << "'";
// Ensure the new configuration applied
EXPECT_TRUE(is_described("logging=debug"));
EXPECT_TRUE(is_described("logging*=debug"));
EXPECT_TRUE(is_described(_all_decorators));
// Test the configuration of file outputs as well

@ -184,6 +184,20 @@ TEST(LogSelection, equals) {
EXPECT_NE(selection, fewer_tags);
}
TEST(LogSelection, consists_of) {
LogTagType tags[LogTag::MaxTags] = {
PREFIX_LOG_TAG(logging), PREFIX_LOG_TAG(test), PREFIX_LOG_TAG(_NO_TAG)
};
LogSelection s(tags, false, LogLevel::Off);
EXPECT_TRUE(s.consists_of(tags));
tags[2] = PREFIX_LOG_TAG(safepoint);
EXPECT_FALSE(s.consists_of(tags));
s = LogSelection(tags, true, LogLevel::Info);
EXPECT_TRUE(s.consists_of(tags));
}
TEST(LogSelection, describe_tags) {
char buf[256];
LogTagType tags[LogTag::MaxTags] = { PREFIX_LOG_TAG(logging), PREFIX_LOG_TAG(test), PREFIX_LOG_TAG(_NO_TAG) };

@ -37,7 +37,7 @@ public class TestMultipleXlogArgs {
ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-Xlog:logging=debug",
"-Xlog:logging=trace",
"-Xlog:defaultmethods=trace",
"-Xlog:defaultmethods=off",
"-Xlog:defaultmethods=warning",
"-Xlog:safepoint=info",
"-Xlog:safepoint=info",
"-version");
@ -48,7 +48,7 @@ public class TestMultipleXlogArgs {
output.shouldMatch(stdoutConfigLine + "logging=trace").shouldNotMatch(stdoutConfigLine + "logging=debug");
// Make sure safepoint=info is printed exactly once even though we're setting it twice
output.shouldMatch(stdoutConfigLine + "safepoint=info").shouldNotMatch(stdoutConfigLine + "safepoint=info.*safepoint=info");
// Shouldn't see defaultmethods at all, because disabled tags are not listed
// Shouldn't see defaultmethods at all, because it should be covered by the initial 'all=warning' config
output.shouldNotMatch(stdoutConfigLine + "defaultmethods");
output.shouldHaveExitValue(0);
}