changeset 9578:150c50761d56

8142952: Unified Logging framework does not allow multiple -Xlog: arguments. Reviewed-by: brutisso, sla
author mlarsson
date Fri, 27 Nov 2015 12:37:38 +0100
parents 64b5cb84040b
children 3d7f9ca8b1f0 a10aa5486ef6
files src/share/vm/logging/logConfiguration.cpp src/share/vm/logging/logConfiguration.hpp src/share/vm/logging/logDecorators.cpp src/share/vm/logging/logDecorators.hpp src/share/vm/logging/logLevel.hpp src/share/vm/logging/logOutput.cpp src/share/vm/logging/logOutput.hpp src/share/vm/logging/logOutputList.cpp src/share/vm/logging/logOutputList.hpp src/share/vm/logging/logTagLevelExpression.cpp src/share/vm/logging/logTagLevelExpression.hpp src/share/vm/logging/logTagSet.cpp src/share/vm/logging/logTagSet.hpp test/serviceability/logging/TestMultipleXlogArgs.java
diffstat 14 files changed, 243 insertions(+), 39 deletions(-) [+]
line wrap: on
line diff
--- a/src/share/vm/logging/logConfiguration.cpp	Fri Nov 27 12:07:01 2015 +0100
+++ b/src/share/vm/logging/logConfiguration.cpp	Fri Nov 27 12:37:38 2015 +0100
@@ -33,6 +33,7 @@
 #include "logging/logTagSet.hpp"
 #include "memory/allocation.inline.hpp"
 #include "memory/resourceArea.hpp"
+#include "runtime/mutexLocker.hpp"
 #include "runtime/os.inline.hpp"
 #include "utilities/globalDefinitions.hpp"
 
@@ -127,33 +128,72 @@
 void LogConfiguration::configure_output(size_t idx, const LogTagLevelExpression& tag_level_expression, const LogDecorators& decorators) {
   assert(idx < _n_outputs, "Invalid index, idx = " SIZE_FORMAT " and _n_outputs = " SIZE_FORMAT, idx, _n_outputs);
   LogOutput* output = _outputs[idx];
-  output->set_decorators(decorators);
-  output->set_config_string(tag_level_expression.to_string());
+
+  // Clear the previous config description
+  output->clear_config_string();
+
   bool enabled = false;
   for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
     LogLevelType level = tag_level_expression.level_for(*ts);
+
+    // Ignore tagsets that do not, and will not log on the output
+    if (!ts->has_output(output) && (level == LogLevel::NotMentioned || level == LogLevel::Off)) {
+      continue;
+    }
+
+    // Update decorators before adding/updating output level,
+    // so that the tagset will have the necessary decorators when requiring them.
     if (level != LogLevel::Off) {
+      ts->update_decorators(decorators);
+    }
+
+    // Set the new level, if it changed
+    if (level != LogLevel::NotMentioned) {
+      ts->set_output_level(output, level);
+    }
+
+    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);
     }
-    ts->update_decorators(decorators);
-    ts->set_output_level(output, level);
   }
 
-  // If the output is not used by any tagset it should be removed, unless it is stdout/stderr.
-  if (!enabled && idx > 1) {
+  // It is now safe to set the new decorators for the actual output
+  output->set_decorators(decorators);
+
+  // Update the decorators on all tagsets to get rid of unused decorators
+  for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
+    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.
     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");
   }
 }
 
 void LogConfiguration::disable_output(size_t idx) {
   LogOutput* out = _outputs[idx];
-  LogDecorators empty_decorators;
-  empty_decorators.clear();
 
   // Remove the output from all tagsets.
   for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
     ts->set_output_level(out, LogLevel::Off);
-    ts->update_decorators(empty_decorators);
+    ts->update_decorators();
   }
 
   // Delete the output unless stdout/stderr
@@ -172,6 +212,36 @@
   }
 }
 
+void LogConfiguration::configure_stdout(LogLevelType level, bool exact_match, ...) {
+  assert(LogConfiguration_lock == NULL || LogConfiguration_lock->owned_by_self(),
+         "LogConfiguration lock must be held when calling this function");
+
+  size_t i;
+  va_list ap;
+  LogTagLevelExpression expr;
+  va_start(ap, exact_match);
+  for (i = 0; i < LogTag::MaxTags; i++) {
+    LogTagType tag = static_cast<LogTagType>(va_arg(ap, int));
+    expr.add_tag(tag);
+    if (tag == LogTag::__NO_TAG) {
+      assert(i > 0, "Must specify at least one tag!");
+      break;
+    }
+  }
+  assert(i < LogTag::MaxTags || static_cast<LogTagType>(va_arg(ap, int)) == LogTag::__NO_TAG,
+         "Too many tags specified! Can only have up to " SIZE_FORMAT " tags in a tag set.", LogTag::MaxTags);
+  va_end(ap);
+
+  if (!exact_match) {
+    expr.set_allow_other_tags();
+  }
+  expr.set_level(level);
+  expr.new_combination();
+
+  // Apply configuration to stdout (output #0), with the same decorators as before.
+  configure_output(0, expr, LogOutput::Stdout->decorators());
+}
+
 bool LogConfiguration::parse_command_line_arguments(const char* opts) {
   char* copy = os::strdup_check_oom(opts, mtLogging);
 
--- a/src/share/vm/logging/logConfiguration.hpp	Fri Nov 27 12:07:01 2015 +0100
+++ b/src/share/vm/logging/logConfiguration.hpp	Fri Nov 27 12:37:38 2015 +0100
@@ -24,6 +24,7 @@
 #ifndef SHARE_VM_LOGGING_LOGCONFIGURATION_HPP
 #define SHARE_VM_LOGGING_LOGCONFIGURATION_HPP
 
+#include "logging/logLevel.hpp"
 #include "memory/allocation.hpp"
 #include "utilities/globalDefinitions.hpp"
 
@@ -70,6 +71,14 @@
   // Disable all logging, equivalent to -Xlog:disable.
   static void disable_logging();
 
+  // Configures logging on stdout for the given tags and level combination.
+  // Intended for mappings between -XX: flags and Unified Logging configuration.
+  // If exact_match is true, only tagsets with precisely the specified tags will be configured
+  // (exact_match=false is the same as "-Xlog:<tags>*=<level>", and exact_match=true is "-Xlog:<tags>=<level>").
+  // Tags should be specified using the LOG_TAGS macro, e.g.
+  // LogConfiguration::configure_stdout(LogLevel::<level>, <true/false>, LOG_TAGS(<tags>));
+  static void configure_stdout(LogLevelType level, bool exact_match, ...);
+
   // Parse command line configuration. Parameter 'opts' is the string immediately following the -Xlog: argument ("gc" for -Xlog:gc).
   static bool parse_command_line_arguments(const char* opts = "all");
 
--- a/src/share/vm/logging/logDecorators.cpp	Fri Nov 27 12:07:01 2015 +0100
+++ b/src/share/vm/logging/logDecorators.cpp	Fri Nov 27 12:37:38 2015 +0100
@@ -25,6 +25,8 @@
 #include "logging/logDecorators.hpp"
 #include "runtime/os.inline.hpp"
 
+const LogDecorators LogDecorators::None = LogDecorators(0);
+
 const char* LogDecorators::_name[][2] = {
 #define DECORATOR(n, a) {#n, #a},
   DECORATOR_LIST
--- a/src/share/vm/logging/logDecorators.hpp	Fri Nov 27 12:07:01 2015 +0100
+++ b/src/share/vm/logging/logDecorators.hpp	Fri Nov 27 12:37:38 2015 +0100
@@ -73,7 +73,12 @@
     return 1 << decorator;
   }
 
+  LogDecorators(uint mask) : _decorators(mask) {
+  }
+
  public:
+  static const LogDecorators None;
+
   LogDecorators() : _decorators(DefaultDecoratorsMask) {
   };
 
--- a/src/share/vm/logging/logLevel.hpp	Fri Nov 27 12:07:01 2015 +0100
+++ b/src/share/vm/logging/logLevel.hpp	Fri Nov 27 12:37:38 2015 +0100
@@ -58,6 +58,7 @@
 #undef LOG_LEVEL
     Count,
     Invalid,
+    NotMentioned,
     First = Off + 1,
     Last = Error,
     Default = Warning,
@@ -65,6 +66,7 @@
   };
 
   static const char *name(LogLevel::type level) {
+    assert(level >= 0 && level < LogLevel::Count, "Invalid level (enum value %d).", level);
     return _name[level];
   }
 
--- a/src/share/vm/logging/logOutput.cpp	Fri Nov 27 12:07:01 2015 +0100
+++ b/src/share/vm/logging/logOutput.cpp	Fri Nov 27 12:37:38 2015 +0100
@@ -24,7 +24,9 @@
 #include "precompiled.hpp"
 #include "logging/logFileStreamOutput.hpp"
 #include "logging/logOutput.hpp"
+#include "logging/logTagSet.hpp"
 #include "memory/allocation.inline.hpp"
+#include "runtime/mutexLocker.hpp"
 #include "runtime/os.inline.hpp"
 
 LogOutput* const LogOutput::Stdout = &LogStdoutOutput::_instance;
@@ -34,7 +36,54 @@
   os::free(_config_string);
 }
 
+void LogOutput::clear_config_string() {
+  assert(LogConfiguration_lock == NULL || LogConfiguration_lock->owned_by_self(),
+         "Must hold configuration lock to modify 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) {
+  assert(LogConfiguration_lock == NULL || LogConfiguration_lock->owned_by_self(),
+         "Must hold configuration lock to modify config string");
+
   os::free(_config_string);
-  _config_string = os::strdup_check_oom(string, mtLogging);
+  _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) {
+  assert(LogConfiguration_lock == NULL || LogConfiguration_lock->owned_by_self(),
+         "Must hold configuration lock to modify config string");
+
+  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);
+  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;
+  }
+}
--- a/src/share/vm/logging/logOutput.hpp	Fri Nov 27 12:07:01 2015 +0100
+++ b/src/share/vm/logging/logOutput.hpp	Fri Nov 27 12:37:38 2015 +0100
@@ -25,18 +25,24 @@
 #define SHARE_VM_LOGGING_LOGOUTPUT_HPP
 
 #include "logging/logDecorators.hpp"
+#include "logging/logLevel.hpp"
 #include "memory/allocation.hpp"
 #include "utilities/globalDefinitions.hpp"
 
 class LogDecorations;
+class LogTagSet;
 
 // The base class/interface for log outputs.
 // Keeps track of the latest configuration string,
 // and its selected decorators.
 class LogOutput : public CHeapObj<mtLogging> {
+ private:
+  static const size_t InitialConfigBufferSize = 256;
+  char* _config_string;
+  size_t _config_string_buffer_size;
+
  protected:
   LogDecorators _decorators;
-  char* _config_string;
 
  public:
   static LogOutput* const Stdout;
@@ -54,10 +60,16 @@
     return _config_string;
   }
 
-  LogOutput() : _config_string(NULL) {
+  LogOutput() : _config_string(NULL), _config_string_buffer_size(0) {
   }
 
   virtual ~LogOutput();
+
+  // 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);
 
   virtual const char* name() const = 0;
--- a/src/share/vm/logging/logOutputList.cpp	Fri Nov 27 12:07:01 2015 +0100
+++ b/src/share/vm/logging/logOutputList.cpp	Fri Nov 27 12:37:38 2015 +0100
@@ -59,7 +59,7 @@
   }
 }
 
-LogOutputList::LogOutputNode* LogOutputList::find(LogOutput* output) {
+LogOutputList::LogOutputNode* LogOutputList::find(const LogOutput* output) const {
   for (LogOutputNode* node = _level_start[LogLevel::Last]; node != NULL; node = node->_next) {
     if (output == node->_value) {
       return node;
--- a/src/share/vm/logging/logOutputList.hpp	Fri Nov 27 12:07:01 2015 +0100
+++ b/src/share/vm/logging/logOutputList.hpp	Fri Nov 27 12:37:38 2015 +0100
@@ -56,7 +56,7 @@
   LogOutputNode*  _level_start[LogLevel::Count];
   volatile jint   _active_readers;
 
-  LogOutputNode* find(LogOutput* output);
+  LogOutputNode* find(const LogOutput* output) const;
   void remove_output(LogOutputNode* node);
   void add_output(LogOutput* output, LogLevelType level);
   void update_output_level(LogOutputNode* node, LogLevelType level);
@@ -69,10 +69,18 @@
   }
 
   // Test if the outputlist has an output for the given level.
-  bool is_level(LogLevelType level) {
+  bool is_level(LogLevelType level) const {
     return _level_start[level] != NULL;
   }
 
+  LogLevelType level_for(const LogOutput* output) const {
+    LogOutputNode* node = this->find(output);
+    if (node == NULL) {
+      return LogLevel::Off;
+    }
+    return node->_level;
+  }
+
   // Set (add/update/remove) the output to the specified level.
   void set_output_level(LogOutput* output, LogLevelType level);
 
--- a/src/share/vm/logging/logTagLevelExpression.cpp	Fri Nov 27 12:07:01 2015 +0100
+++ b/src/share/vm/logging/logTagLevelExpression.cpp	Fri Nov 27 12:37:38 2015 +0100
@@ -29,10 +29,6 @@
 
 const char* LogTagLevelExpression::DefaultExpressionString = "all";
 
-LogTagLevelExpression::~LogTagLevelExpression() {
-  os::free(_string);
-}
-
 void LogTagLevelExpression::clear() {
   _ntags = 0;
   _ncombinations = 0;
@@ -43,8 +39,6 @@
       _tags[combination][tag] = LogTag::__NO_TAG;
     }
   }
-  os::free(_string);
-  _string = NULL;
 }
 
 bool LogTagLevelExpression::parse(const char* str, outputStream* errstream) {
@@ -131,15 +125,13 @@
     new_combination();
   }
 
-  // Save the (unmodified) string for printing purposes.
-  _string = copy;
-  strcpy(_string, str);
-
+  os::free(copy);
   return success;
 }
 
 LogLevelType LogTagLevelExpression::level_for(const LogTagSet& ts) const {
-  LogLevelType level = LogLevel::Off;
+  // Return NotMentioned if the given tagset isn't covered by this expression.
+  LogLevelType level = LogLevel::NotMentioned;
   for (size_t combination = 0; combination < _ncombinations; combination++) {
     bool contains_all = true;
     size_t tag_idx;
--- a/src/share/vm/logging/logTagLevelExpression.hpp	Fri Nov 27 12:07:01 2015 +0100
+++ b/src/share/vm/logging/logTagLevelExpression.hpp	Fri Nov 27 12:37:38 2015 +0100
@@ -24,6 +24,7 @@
 #ifndef SHARE_VM_LOGGING_LOGTAGLEVELEXPRESSION_HPP
 #define SHARE_VM_LOGGING_LOGTAGLEVELEXPRESSION_HPP
 
+#include "logging/logConfiguration.hpp"
 #include "logging/logLevel.hpp"
 #include "logging/logTag.hpp"
 #include "memory/allocation.hpp"
@@ -35,6 +36,7 @@
 // Class used to temporary encode a 'what'-expression during log configuration.
 // Consists of a combination of tags and levels, e.g. "tag1+tag2=level1,tag3*=level2".
 class LogTagLevelExpression : public StackObj {
+  friend void LogConfiguration::configure_stdout(LogLevelType, bool, ...);
  private:
   static const size_t MaxCombinations = 32;
   static const char* DefaultExpressionString;
@@ -43,7 +45,6 @@
   LogTagType    _tags[MaxCombinations][LogTag::MaxTags];
   LogLevelType  _level[MaxCombinations];
   bool          _allow_other_tags[MaxCombinations];
-  char*         _string;
 
   void new_combination() {
     _ncombinations++;
@@ -66,14 +67,9 @@
   void clear();
 
  public:
-  LogTagLevelExpression() : _ntags(0), _ncombinations(0), _string(NULL) {
+  LogTagLevelExpression() : _ntags(0), _ncombinations(0) {
   }
 
-  const char* to_string() const {
-    return _string;
-  }
-
-  ~LogTagLevelExpression();
   bool parse(const char* str, outputStream* errstream = NULL);
   LogLevelType level_for(const LogTagSet& ts) const;
 };
--- a/src/share/vm/logging/logTagSet.cpp	Fri Nov 27 12:07:01 2015 +0100
+++ b/src/share/vm/logging/logTagSet.cpp	Fri Nov 27 12:37:38 2015 +0100
@@ -49,7 +49,7 @@
   _output_list.set_output_level(LogOutput::Stderr, LogLevel::Default);
 }
 
-bool LogTagSet::is_level(LogLevelType level) {
+bool LogTagSet::is_level(LogLevelType level) const {
   return _output_list.is_level(level);
 }
 
@@ -77,11 +77,11 @@
   }
 }
 
-int LogTagSet::label(char* buf, size_t len)  {
+int LogTagSet::label(char* buf, size_t len, const char* separator) const {
   int tot_written = 0;
   for (size_t i = 0; i < _ntags; i++) {
     int written = jio_snprintf(buf + tot_written, len - tot_written, "%s%s",
-                               (i == 0 ? "" : ","),
+                               (i == 0 ? "" : separator),
                                LogTag::name(_tag[i]));
     if (written < 0) {
       return -1;
--- a/src/share/vm/logging/logTagSet.hpp	Fri Nov 27 12:07:01 2015 +0100
+++ b/src/share/vm/logging/logTagSet.hpp	Fri Nov 27 12:37:38 2015 +0100
@@ -77,17 +77,21 @@
     return false;
   }
 
+  LogLevelType level_for(const LogOutput* output) const {
+    return _output_list.level_for(output);
+  }
+
   void set_output_level(LogOutput* output, LogLevelType level) {
     _output_list.set_output_level(output, level);
   }
 
   // Refresh the decorators for this tagset to contain the decorators for all
   // of its current outputs combined with the given decorators.
-  void update_decorators(const LogDecorators& decorator);
+  void update_decorators(const LogDecorators& decorator = LogDecorators::None);
 
-  int label(char *buf, size_t len);
+  int label(char *buf, size_t len, const char* separator = ",") const;
   bool has_output(const LogOutput* output);
-  bool is_level(LogLevelType level);
+  bool is_level(LogLevelType level) const;
   void log(LogLevelType level, const char* msg);
 };
 
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/test/serviceability/logging/TestMultipleXlogArgs.java	Fri Nov 27 12:37:38 2015 +0100
@@ -0,0 +1,55 @@
+/*
+ * Copyright (c) 2015, 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
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ */
+
+/*
+ * @test TestMultipleXlogArgs
+ * @summary Ensure multiple -Xlog arguments aggregate the logging options.
+ * @library /testlibrary
+ */
+
+import jdk.test.lib.ProcessTools;
+import jdk.test.lib.OutputAnalyzer;
+
+public class TestMultipleXlogArgs {
+
+    public static void main(String[] args) throws Exception {
+        ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-Xlog:logging=debug",
+                                                                  "-Xlog:logging=trace",
+                                                                  "-Xlog:defaultmethods=trace",
+                                                                  "-Xlog:defaultmethods=off",
+                                                                  "-Xlog:safepoint=info",
+                                                                  "-Xlog:safepoint=info",
+                                                                  "-version");
+        OutputAnalyzer output = new OutputAnalyzer(pb.start());
+        // -Xlog:logging=trace means that the log configuration will be printed.
+        String stdoutConfigLine = "\\[logging *\\] #0: stdout .*";
+        // Ensure logging=trace has overwritten logging=debug
+        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
+        output.shouldNotMatch(stdoutConfigLine + "defaultmethods");
+        output.shouldHaveExitValue(0);
+    }
+}
+