8168722: Unified Logging configuration output needs simplifying
authormlarsson
Wed, 28 Feb 2018 22:38:53 +0100
changeset 49188 e9ba8b40ca6f
parent 49187 f7b73f9ae38f
child 49189 41e570d862b4
8168722: Unified Logging configuration output needs simplifying Reviewed-by: rehn, lfoltan, hseigel
src/hotspot/share/logging/logConfiguration.cpp
src/hotspot/share/logging/logOutput.cpp
src/hotspot/share/logging/logOutput.hpp
src/hotspot/share/logging/logSelection.cpp
src/hotspot/share/logging/logSelection.hpp
test/hotspot/gtest/logging/test_logConfiguration.cpp
test/hotspot/gtest/logging/test_logSelection.cpp
test/hotspot/jtreg/serviceability/logging/TestMultipleXlogArgs.java
--- 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) {
--- 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<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);
+}
+
--- 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;
--- 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;
 }
--- 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;
--- 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
--- 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) };
--- 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);
     }