# HG changeset patch # User mlarsson # Date 1519853933 -3600 # Node ID e9ba8b40ca6f1cac532b9485c8245bea4b946508 # Parent f7b73f9ae38f25653d3a7aa4406ebbb66c81e633 8168722: Unified Logging configuration output needs simplifying Reviewed-by: rehn, lfoltan, hseigel diff -r f7b73f9ae38f -r e9ba8b40ca6f src/hotspot/share/logging/logConfiguration.cpp --- a/src/hotspot/share/logging/logConfiguration.cpp Wed Feb 28 23:23:35 2018 -0800 +++ b/src/hotspot/share/logging/logConfiguration.cpp Wed Feb 28 22:38:53 2018 +0100 @@ -220,8 +220,7 @@ 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 @@ // 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 @@ // 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 @@ 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) { diff -r f7b73f9ae38f -r e9ba8b40ca6f src/hotspot/share/logging/logOutput.cpp --- a/src/hotspot/share/logging/logOutput.cpp Wed Feb 28 23:23:35 2018 -0800 +++ b/src/hotspot/share/logging/logOutput.cpp Wed Feb 28 22:38:53 2018 +0100 @@ -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 @@ 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::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(a) - static_cast(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(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=" + { + 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); +} + diff -r f7b73f9ae38f -r e9ba8b40ca6f src/hotspot/share/logging/logOutput.hpp --- a/src/hotspot/share/logging/logOutput.hpp Wed Feb 28 23:23:35 2018 -0800 +++ b/src/hotspot/share/logging/logOutput.hpp Wed Feb 28 22:38:53 2018 +0100 @@ -32,6 +32,7 @@ class LogDecorations; class LogMessageBuffer; +class LogSelection; class LogTagSet; // The base class/interface for log outputs. @@ -52,16 +53,18 @@ 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; diff -r f7b73f9ae38f -r e9ba8b40ca6f src/hotspot/share/logging/logSelection.cpp --- a/src/hotspot/share/logging/logSelection.cpp Wed Feb 28 23:23:35 2018 -0800 +++ b/src/hotspot/share/logging/logSelection.cpp Wed Feb 28 22:38:53 2018 +0100 @@ -170,6 +170,25 @@ 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; } diff -r f7b73f9ae38f -r e9ba8b40ca6f src/hotspot/share/logging/logSelection.hpp --- a/src/hotspot/share/logging/logSelection.hpp Wed Feb 28 23:23:35 2018 -0800 +++ b/src/hotspot/share/logging/logSelection.hpp Wed Feb 28 22:38:53 2018 +0100 @@ -59,6 +59,7 @@ 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; diff -r f7b73f9ae38f -r e9ba8b40ca6f test/hotspot/gtest/logging/test_logConfiguration.cpp --- a/test/hotspot/gtest/logging/test_logConfiguration.cpp Wed Feb 28 23:23:35 2018 -0800 +++ b/test/hotspot/gtest/logging/test_logConfiguration.cpp Wed Feb 28 22:38:53 2018 +0100 @@ -113,7 +113,7 @@ 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 @@ // 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 @@ // 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 @@ 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 diff -r f7b73f9ae38f -r e9ba8b40ca6f test/hotspot/gtest/logging/test_logSelection.cpp --- a/test/hotspot/gtest/logging/test_logSelection.cpp Wed Feb 28 23:23:35 2018 -0800 +++ b/test/hotspot/gtest/logging/test_logSelection.cpp Wed Feb 28 22:38:53 2018 +0100 @@ -184,6 +184,20 @@ 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) }; diff -r f7b73f9ae38f -r e9ba8b40ca6f test/hotspot/jtreg/serviceability/logging/TestMultipleXlogArgs.java --- a/test/hotspot/jtreg/serviceability/logging/TestMultipleXlogArgs.java Wed Feb 28 23:23:35 2018 -0800 +++ b/test/hotspot/jtreg/serviceability/logging/TestMultipleXlogArgs.java Wed Feb 28 22:38:53 2018 +0100 @@ -37,7 +37,7 @@ 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 @@ 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); }