8151993: Remove inclusion of inline.hpp in log.hpp

Reviewed-by: kbarrett, stefank

hotspot/src/share/vm/logging/log.cpp

@@ -23,6 +23,24 @@
  */
 
 #include "precompiled.hpp"
+#include "logging/log.hpp"
+#include "memory/allocation.inline.hpp"
+
+void LogWriteHelper::write_large(LogTagSet& lts,
+                                 LogLevelType level,
+                                 const char* prefix,
+                                 size_t prefix_len,
+                                 size_t msg_len,
+                                 const char* fmt,
+                                 va_list args) {
+  size_t newbuf_len = prefix_len + msg_len + 1;
+  char* newbuf = NEW_C_HEAP_ARRAY(char, newbuf_len, mtLogging);
+  memcpy(newbuf, prefix, prefix_len);
+  int ret = os::log_vsnprintf(newbuf + prefix_len, newbuf_len - prefix_len, fmt, args);
+  assert(ret >= 0, "Log message buffer issue");
+  lts.log(level, newbuf);
+  FREE_C_HEAP_ARRAY(char, newbuf);
+}
 
 /////////////// Unit tests ///////////////
 
@@ -33,66 +51,6 @@
 #include "logging/logOutput.hpp"
 #include "memory/resourceArea.hpp"
 
-void Test_log_length() {
-  remove("loglengthoutput.txt");
-
-  // Write long message to output file
-  ResourceMark rm;
-  LogHandle(logging) log;
-  bool success = LogConfiguration::parse_log_arguments("loglengthoutput.txt", "logging=trace",
-    NULL, NULL, log.error_stream());
-  assert(success, "test unable to configure logging");
-  log.trace("01:1234567890-"
-            "02:1234567890-"
-            "03:1234567890-"
-            "04:1234567890-"
-            "05:1234567890-"
-            "06:1234567890-"
-            "07:1234567890-"
-            "08:1234567890-"
-            "09:1234567890-"
-            "10:1234567890-"
-            "11:1234567890-"
-            "12:1234567890-"
-            "13:1234567890-"
-            "14:1234567890-"
-            "15:1234567890-"
-            "16:1234567890-"
-            "17:1234567890-"
-            "18:1234567890-"
-            "19:1234567890-"
-            "20:1234567890-"
-            "21:1234567890-"
-            "22:1234567890-"
-            "23:1234567890-"
-            "24:1234567890-"
-            "25:1234567890-"
-            "26:1234567890-"
-            "27:1234567890-"
-            "28:1234567890-"
-            "29:1234567890-"
-            "30:1234567890-"
-            "31:1234567890-"
-            "32:1234567890-"
-            "33:1234567890-"
-            "34:1234567890-"
-            "35:1234567890-"
-            "36:1234567890-"
-            "37:1234567890-");
-  LogConfiguration::parse_log_arguments("loglengthoutput.txt", "all=off",
-    NULL, NULL, log.error_stream());
-
-  // Look for end of message in output file
-  FILE* fp = fopen("loglengthoutput.txt", "r");
-  assert(fp, "File read error");
-  char output[600];
-  if (fgets(output, 600, fp) != NULL) {
-    assert(strstr(output, "37:1234567890-"), "logging print size error");
-  }
-  fclose(fp);
-  remove("loglengthoutput.txt");
-}
-
 #define assert_str_eq(s1, s2) \
   assert(strcmp(s1, s2) == 0, "Expected '%s' to equal '%s'", s1, s2)
 
@@ -102,14 +60,67 @@ void Test_log_length() {
 #define assert_char_not_in(c, s) \
   assert(strchr(s, c) == NULL, "Expected '%s' to *not* contain character '%c'", s, c)
 
+class TestLogFile {
+ private:
+  char file_name[256];
+
+  void set_name(const char* test_name) {
+    const char* tmpdir = os::get_temp_directory();
+    int pos = jio_snprintf(file_name, sizeof(file_name), "%s%svmtest.%s.%d.log", tmpdir, os::file_separator(), test_name, os::current_process_id());
+    assert(pos > 0, "too small log file name buffer");
+    assert((size_t)pos < sizeof(file_name), "too small log file name buffer");
+  }
+
+ public:
+  TestLogFile(const char* test_name) {
+    set_name(test_name);
+    remove(name());
+  }
+
+  ~TestLogFile() {
+    remove(name());
+  }
+
+  const char* name() {
+    return file_name;
+  }
+};
+
+class TestLogSavedConfig {
+ private:
+  char* _saved_config;
+  char* _new_output;
+  LogHandle(logging) _log;
+ public:
+  TestLogSavedConfig(const char* apply_output = NULL, const char* apply_setting = NULL) : _new_output(0) {
+    _saved_config = os::strdup_check_oom(LogOutput::Stdout->config_string());
+    bool success = LogConfiguration::parse_log_arguments("stdout", "all=off", NULL, NULL, _log.error_stream());
+    assert(success, "test unable to turn all off");
+
+    if (apply_output) {
+      _new_output = os::strdup_check_oom(apply_output);
+      bool success = LogConfiguration::parse_log_arguments(_new_output, apply_setting,  NULL, NULL, _log.error_stream());
+      assert(success, "test unable to apply test log configuration");
+    }
+  }
+
+  ~TestLogSavedConfig() {
+    if (_new_output) {
+      bool success = LogConfiguration::parse_log_arguments(_new_output, "all=off", NULL, NULL, _log.error_stream());
+      assert(success, "test unable to turn all off");
+      os::free(_new_output);
+    }
+
+    bool success = LogConfiguration::parse_log_arguments("stdout", _saved_config, NULL, NULL, _log.error_stream());
+    assert(success, "test unable to restore log configuration");
+    os::free(_saved_config);
+  }
+};
+
 void Test_configure_stdout() {
   ResourceMark rm;
-  LogHandle(logging) log;
   LogOutput* stdoutput = LogOutput::Stdout;
-
+  TestLogSavedConfig tlsc;
-  // Save current stdout config and clear it
-  char* saved_config = os::strdup_check_oom(stdoutput->config_string());
-  LogConfiguration::parse_log_arguments("stdout", "all=off", NULL, NULL, log.error_stream());
 
   // Enable 'logging=info', verifying it has been set
   LogConfiguration::configure_stdout(LogLevel::Info, true, LOG_TAGS(logging));
@@ -131,10 +142,6 @@ void Test_configure_stdout() {
   LogConfiguration::configure_stdout(LogLevel::Off, false, LOG_TAGS(gc));
   LogConfiguration::configure_stdout(LogLevel::Off, true, LOG_TAGS(logging));
   assert_str_eq("all=off", stdoutput->config_string());
-
-  // Restore saved configuration
-  LogConfiguration::parse_log_arguments("stdout", saved_config, NULL, NULL, log.error_stream());
-  os::free(saved_config);
 }
 
 static int Test_logconfiguration_subscribe_triggered = 0;
@@ -147,6 +154,8 @@ void Test_logconfiguration_subscribe() {
   ResourceMark rm;
   LogHandle(logging) log;
 
+  TestLogSavedConfig log_cfg("stdout", "logging+test=trace");
+
   LogConfiguration::register_update_listener(&Test_logconfiguration_subscribe_helper);
 
   LogConfiguration::parse_log_arguments("stdout", "logging=trace", NULL, NULL, log.error_stream());
@@ -157,6 +166,60 @@ void Test_logconfiguration_subscribe() {
 
   LogConfiguration::disable_logging();
   assert(Test_logconfiguration_subscribe_triggered == 3, "subscription not triggered (3)");
+
+  // We need to renable stderr error logging since "disable_logging" disable it all.
+  // TestLogSavedConfig log_cfg will only renable stdout for us.
+  LogConfiguration::parse_log_arguments("stderr", "all=warning", NULL, NULL, log.error_stream());
+  assert(Test_logconfiguration_subscribe_triggered == 4, "subscription not triggered (3)");
+}
+
+#define LOG_PREFIX_STR "THE_PREFIX "
+#define LOG_LINE_STR "a log line"
+
+size_t Test_log_prefix_prefixer(char* buf, size_t len) {
+  int ret = jio_snprintf(buf, len, LOG_PREFIX_STR);
+  assert(ret > 0, "Failed to print prefix. Log buffer too small?");
+  return (size_t) ret;
+}
+
+void Test_log_prefix() {
+  ResourceMark rm;
+  TestLogFile log_file("log_prefix");
+  TestLogSavedConfig log_cfg(log_file.name(), "logging+test=trace");
+
+  log_trace(logging, test)(LOG_LINE_STR);
+
+  FILE* fp = fopen(log_file.name(), "r");
+  assert(fp, "File read error");
+  char output[1024];
+  if (fgets(output, 1024, fp) != NULL) {
+    assert(strstr(output, LOG_PREFIX_STR LOG_LINE_STR), "logging prefix error");
+  }
+  fclose(fp);
+}
+
+void Test_log_big() {
+  char big_msg[4096] = {0};
+  char Xchar = '~';
+
+  ResourceMark rm;
+  TestLogFile log_file("log_big");
+  TestLogSavedConfig log_cfg(log_file.name(), "logging+test=trace");
+
+  memset(big_msg, Xchar, sizeof(big_msg) - 1);
+
+  log_trace(logging, test)("%s", big_msg);
+
+  FILE* fp = fopen(log_file.name(), "r");
+  assert(fp, "File read error");
+  char output[sizeof(big_msg)+128 /*decorators*/ ];
+  if (fgets(output, sizeof(output), fp) != NULL) {
+    assert(strstr(output, LOG_PREFIX_STR), "logging prefix error");
+    size_t count = 0;
+    for (size_t ps = 0 ; output[ps + count] != '\0'; output[ps + count] == Xchar ? count++ : ps++);
+    assert(count == (sizeof(big_msg) - 1) , "logging msg error");
+  }
+  fclose(fp);
 }
 
 void Test_logtagset_duplicates() {

hotspot/src/share/vm/logging/log.hpp

@@ -29,7 +29,6 @@
 #include "logging/logTagSet.hpp"
 #include "logging/logTag.hpp"
 #include "memory/allocation.hpp"
-#include "memory/allocation.inline.hpp"
 #include "runtime/os.hpp"
 #include "utilities/debug.hpp"
 #include "utilities/ostream.hpp"
@@ -87,6 +86,26 @@
 //
 #define LogHandle(...)  Log<LOG_TAGS(__VA_ARGS__)>
 
+template <LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
+class Log;
+
+// Non-template helper class for implementing write-slowpath in cpp
+class LogWriteHelper : AllStatic {
+ private:
+
+  template <LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
+  friend class Log;
+
+  ATTRIBUTE_PRINTF(6, 0)
+  static void write_large(LogTagSet& lts,
+                          LogLevelType level,
+                          const char* prefix,
+                          size_t prefix_len,
+                          size_t msg_len,
+                          const char* fmt,
+                          va_list args);
+};
+
 template <LogTagType T0, LogTagType T1 = LogTag::__NO_TAG, LogTagType T2 = LogTag::__NO_TAG, LogTagType T3 = LogTag::__NO_TAG,
           LogTagType T4 = LogTag::__NO_TAG, LogTagType GuardTag = LogTag::__NO_TAG>
 class Log VALUE_OBJ_CLASS_SPEC {
@@ -133,21 +152,14 @@ class Log VALUE_OBJ_CLASS_SPEC {
     // Check that string fits in buffer; resize buffer if necessary
     int ret = os::log_vsnprintf(buf + prefix_len, sizeof(buf) - prefix_len, fmt, args);
     assert(ret >= 0, "Log message buffer issue");
-    if ((size_t)ret >= sizeof(buf)) {
+    size_t msg_len = ret;
-      size_t newbuf_len = prefix_len + ret + 1;
+    LogTagSet& lts = LogTagSetMapping<T0, T1, T2, T3, T4>::tagset();
-      char* newbuf = NEW_C_HEAP_ARRAY(char, newbuf_len, mtLogging);
+    if (msg_len >= sizeof(buf)) {
-      prefix_len = LogPrefix<T0, T1, T2, T3, T4>::prefix(newbuf, newbuf_len);
+      LogWriteHelper::write_large(lts, level, buf, prefix_len, msg_len, fmt, saved_args);
-      ret = os::log_vsnprintf(newbuf + prefix_len, newbuf_len - prefix_len, fmt, saved_args);
-      assert(ret >= 0, "Log message buffer issue");
-      puts(level, newbuf);
-      FREE_C_HEAP_ARRAY(char, newbuf);
     } else {
-      puts(level, buf);
+      lts.log(level, buf);
     }
-  }
+    va_end(saved_args);
-
-  static void puts(LogLevelType level, const char* string) {
-    LogTagSetMapping<T0, T1, T2, T3, T4>::tagset().log(level, string);
   }
 
 #define LOG_LEVEL(level, name) ATTRIBUTE_PRINTF(2, 0) \

hotspot/src/share/vm/logging/logPrefix.hpp

@@ -38,6 +38,10 @@
 // List of prefixes for specific tags and/or tagsets.
 // Syntax: LOG_PREFIX(<name of prefixer function>, LOG_TAGS(<chosen log tags>))
 // Where the prefixer function matches the following signature: size_t (*)(char*, size_t)
+
+// Prefix function for internal vm test
+DEBUG_ONLY(size_t Test_log_prefix_prefixer(char* buf, size_t len);)
+
 #define LOG_PREFIX_LIST \
   LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc)) \
   LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, age)) \
@@ -72,6 +76,7 @@
   LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, task, start)) \
   LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, task, stats)) \
   LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, task, time)) \
+  DEBUG_ONLY(LOG_PREFIX(Test_log_prefix_prefixer, LOG_TAGS(logging, test))) \
   LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, tlab))
 
 

hotspot/src/share/vm/logging/logTag.hpp

@@ -89,6 +89,7 @@
   LOG_TAG(survivor) \
   LOG_TAG(sweep) \
   LOG_TAG(task) \
+  DEBUG_ONLY(LOG_TAG(test)) \
   LOG_TAG(thread) \
   LOG_TAG(tlab) \
   LOG_TAG(time) \

hotspot/src/share/vm/utilities/internalVMTests.cpp

@@ -67,9 +67,10 @@ void InternalVMTests::run() {
   run_unit_test(Test_linked_list);
   run_unit_test(TestChunkedList_test);
   run_unit_test(JSON_test);
-  run_unit_test(Test_log_length);
   run_unit_test(Test_configure_stdout);
   run_unit_test(Test_logconfiguration_subscribe);
+  run_unit_test(Test_log_prefix);
+  run_unit_test(Test_log_big);
   run_unit_test(Test_logtagset_duplicates);
   run_unit_test(DirectivesParser_test);
   run_unit_test(Test_TempNewSymbol);