8145934: Make ttyLocker equivalent for Unified Logging framework

Reviewed-by: rprotacio, stuefe, jrose

hotspot/src/os/posix/vm/os_posix.cpp

@@ -327,6 +327,14 @@ FILE* os::open(int fd, const char* mode) {
   return ::fdopen(fd, mode);
 }
 
+void os::flockfile(FILE* fp) {
+  ::flockfile(fp);
+}
+
+void os::funlockfile(FILE* fp) {
+  ::funlockfile(fp);
+}
+
 // Builds a platform dependent Agent_OnLoad_<lib_name> function name
 // which is used to find statically linked in agents.
 // Parameters:

hotspot/src/os/windows/vm/os_windows.cpp

@@ -4661,6 +4661,14 @@ int os::available(int fd, jlong *bytes) {
   }
 }
 
+void os::flockfile(FILE* fp) {
+  _lock_file(fp);
+}
+
+void os::funlockfile(FILE* fp) {
+  _unlock_file(fp);
+}
+
 // This code is a copy of JDK's nonSeekAvailable
 // from src/windows/hpi/src/sys_api_md.c
 

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

@@ -32,6 +32,8 @@
 #include "logging/log.hpp"
 #include "logging/logConfiguration.hpp"
 #include "logging/logFileOutput.hpp"
+#include "logging/logMessage.hpp"
+#include "logging/logMessageBuffer.hpp"
 #include "logging/logOutput.hpp"
 #include "logging/logTagLevelExpression.hpp"
 #include "logging/logTagSet.hpp"
@@ -54,6 +56,102 @@ void Test_log_tag_combinations_limit() {
       LogTagLevelExpression::MaxCombinations, LogTagSet::ntagsets());
 }
 
+// Read a complete line from fp and return it as a resource allocated string.
+// Returns NULL on EOF.
+static char* read_line(FILE* fp) {
+  assert(fp != NULL, "bad fp");
+  int buflen = 512;
+  char* buf = NEW_RESOURCE_ARRAY(char, buflen);
+  long pos = ftell(fp);
+
+  char* ret = fgets(buf, buflen, fp);
+  while (ret != NULL && buf[strlen(buf) - 1] != '\n' && !feof(fp)) {
+    // retry with a larger buffer
+    buf = REALLOC_RESOURCE_ARRAY(char, buf, buflen, buflen * 2);
+    buflen *= 2;
+    // rewind to beginning of line
+    fseek(fp, pos, SEEK_SET);
+    // retry read with new buffer
+    ret = fgets(buf, buflen, fp);
+  }
+  return ret;
+}
+
+static bool file_contains_substrings_in_order(const char* filename, const char* substrs[]) {
+  FILE* fp = fopen(filename, "r");
+  assert(fp != NULL, "error opening file %s: %s", filename, strerror(errno));
+
+  size_t idx = 0;
+  while (substrs[idx] != NULL) {
+    ResourceMark rm;
+    char* line = read_line(fp);
+    if (line == NULL) {
+      break;
+    }
+    for (char* match = strstr(line, substrs[idx]); match != NULL;) {
+      size_t match_len = strlen(substrs[idx]);
+      idx++;
+      if (substrs[idx] == NULL) {
+        break;
+      }
+      match = strstr(match + match_len, substrs[idx]);
+    }
+  }
+
+  fclose(fp);
+  return substrs[idx] == NULL;
+}
+
+static bool file_contains_substring(const char* filename, const char* substr) {
+  const char* strs[] = {substr, NULL};
+  return file_contains_substrings_in_order(filename, strs);
+}
+
+static size_t number_of_lines_with_substring_in_file(const char* filename,
+                                                     const char* substr) {
+  FILE* fp = fopen(filename, "r");
+  assert(fp != NULL, "error opening file %s: %s", filename, strerror(errno));
+
+  size_t ret = 0;
+  for (;;) {
+    ResourceMark rm;
+    char* line = read_line(fp);
+    if (line == NULL) {
+      break;
+    }
+    if (strstr(line, substr) != NULL) {
+      ret++;
+    }
+  }
+
+  fclose(fp);
+  return ret;
+}
+
+static bool file_exists(const char* filename) {
+  struct stat st;
+  return os::stat(filename, &st) == 0;
+}
+
+static void delete_file(const char* filename) {
+  if (!file_exists(filename)) {
+    return;
+  }
+  int ret = remove(filename);
+  assert(ret == 0, "failed to remove file '%s': %s", filename, strerror(errno));
+}
+
+static void create_directory(const char* name) {
+  assert(!file_exists(name), "can't create directory: %s already exists", name);
+  bool failed;
+#ifdef _WINDOWS
+  failed = !CreateDirectory(name, NULL);
+#else
+  failed = mkdir(name, 0777);
+#endif
+  assert(!failed, "failed to create directory %s", name);
+}
+
 class TestLogFile {
  private:
   char file_name[256];
@@ -139,60 +237,6 @@ void Test_configure_stdout() {
   assert_str_eq("all=off", stdoutput->config_string());
 }
 
-static size_t number_of_lines_with_substring_in_file(const char* filename,
-                                                     const char* substr) {
-  ResourceMark rm;
-  size_t ret = 0;
-  FILE* fp = fopen(filename, "r");
-  assert(fp != NULL, "error opening file %s: %s", filename, strerror(errno));
-
-  int buflen = 512;
-  char* buf = NEW_RESOURCE_ARRAY(char, buflen);
-  long pos = 0;
-
-  while (fgets(buf, buflen, fp) != NULL) {
-    if (buf[strlen(buf) - 1] != '\n' && !feof(fp)) {
-      // retry with a larger buffer
-      buf = REALLOC_RESOURCE_ARRAY(char, buf, buflen, buflen * 2);
-      buflen *= 2;
-      // rewind to beginning of line
-      fseek(fp, pos, SEEK_SET);
-      continue;
-    }
-    pos = ftell(fp);
-    if (strstr(buf, substr) != NULL) {
-      ret++;
-    }
-  }
-
-  fclose(fp);
-  return ret;
-}
-
-static bool file_exists(const char* filename) {
-  struct stat st;
-  return os::stat(filename, &st) == 0;
-}
-
-static void delete_file(const char* filename) {
-  if (!file_exists(filename)) {
-    return;
-  }
-  int ret = remove(filename);
-  assert(ret == 0, "failed to remove file '%s': %s", filename, strerror(errno));
-}
-
-static void create_directory(const char* name) {
-  assert(!file_exists(name), "can't create directory: %s already exists", name);
-  bool failed;
-#ifdef _WINDOWS
-  failed = !CreateDirectory(name, NULL);
-#else
-  failed = mkdir(name, 0777);
-#endif
-  assert(!failed, "failed to create directory %s", name);
-}
-
 static const char* ExpectedLine = "a (hopefully) unique log line for testing";
 
 static void init_file(const char* filename, const char* options = "") {
@@ -264,6 +308,253 @@ void Test_log_file_startup_truncation() {
   delete_file(archived_filename);
 }
 
+class LogMessageTest {
+ private:
+  static Log(logging) _log;
+  static const char* _level_filename[];
+
+  static void test_level_inclusion();
+  static void test_long_message();
+  static void test_message_with_many_lines();
+  static void test_line_order();
+  static void test_prefixing();
+  static void test_scoped_messages();
+  static void test_scoped_flushing();
+  static void test_scoped_reset();
+
+ public:
+  static void test();
+};
+
+const char* LogMessageTest::_level_filename[] = {
+  NULL, // LogLevel::Off
+#define LOG_LEVEL(name, printname) "multiline-" #printname ".log",
+  LOG_LEVEL_LIST
+#undef LOG_LEVEL
+};
+
+void Test_multiline_logging() {
+  LogMessageTest::test();
+}
+
+void LogMessageTest::test() {
+  ResourceMark rm;
+
+  for (int i = 0; i < LogLevel::Count; i++) {
+    char buf[32];
+    // Attempt to remove possibly pre-existing log files
+    remove(_level_filename[i]);
+
+    jio_snprintf(buf, sizeof(buf), "logging=%s", LogLevel::name(static_cast<LogLevelType>(i)));
+    bool success = LogConfiguration::parse_log_arguments(_level_filename[i], buf,
+                                                         NULL, NULL, _log.error_stream());
+    assert(success, "unable to configure logging to file '%s'", _level_filename[i]);
+  }
+
+  test_level_inclusion();
+  test_line_order();
+  test_long_message();
+  test_message_with_many_lines();
+  test_prefixing();
+  test_scoped_messages();
+  test_scoped_flushing();
+  test_scoped_reset();
+
+  // Stop logging to the files and remove them.
+  for (int i = 0; i < LogLevel::Count; i++) {
+    LogConfiguration::parse_log_arguments(_level_filename[i], "all=off", NULL, NULL, _log.error_stream());
+    remove(_level_filename[i]);
+  }
+}
+
+// Verify that messages with multiple levels are written
+// to outputs configured for all the corresponding levels
+void LogMessageTest::test_level_inclusion() {
+  const size_t message_count = 10;
+  LogMessageBuffer msg[message_count];
+
+  struct {
+    int message_number;
+    LogLevelType level;
+  } lines[] = {
+    { 0, LogLevel::Error },
+    { 1, LogLevel::Info },
+    { 2, LogLevel::Info }, { 2, LogLevel::Debug },
+    { 3, LogLevel::Info }, { 3, LogLevel::Warning },
+    { 4, LogLevel::Debug }, { 4, LogLevel::Warning },
+    { 5, LogLevel::Trace }, { 5, LogLevel::Debug },
+    { 6, LogLevel::Warning }, { 6, LogLevel::Error },
+    { 7, LogLevel::Trace }, { 7, LogLevel::Info }, { 7, LogLevel::Debug },
+    { 8, LogLevel::Trace }, { 8, LogLevel::Debug }, { 8, LogLevel::Info },
+    { 8, LogLevel::Warning }, { 8, LogLevel::Error},
+    { 9, LogLevel::Trace }
+  };
+
+  // Fill in messages with the above lines
+  for (size_t i = 0; i < ARRAY_SIZE(lines); i++) {
+    switch (lines[i].level) {
+#define LOG_LEVEL(name, printname) \
+    case LogLevel::name: \
+      msg[lines[i].message_number].printname("msg[%d]: " #printname, lines[i].message_number); \
+      break;
+LOG_LEVEL_LIST
+#undef LOG_LEVEL
+    }
+  }
+
+  for (size_t i = 0; i < message_count; i++) {
+    _log.write(msg[i]);
+  }
+
+  // Verify that lines are written to the expected log files
+  for (size_t i = 0; i < ARRAY_SIZE(lines); i++) {
+    char expected[256];
+    jio_snprintf(expected, sizeof(expected), "msg[%d]: %s",
+                 lines[i].message_number, LogLevel::name(lines[i].level));
+    for (int level = lines[i].level; level > 0; level--) {
+      assert(file_contains_substring(_level_filename[level], expected),
+      "line #" SIZE_FORMAT " missing from log file '%s'", i, _level_filename[level]);
+    }
+    for (int level = lines[i].level + 1; level < LogLevel::Count; level++) {
+      assert(!file_contains_substring(_level_filename[level], expected),
+      "line #" SIZE_FORMAT " erroneously included in log file '%s'", i, _level_filename[level]);
+    }
+  }
+}
+
+// Verify that messages are logged in the order they are added to the log message
+void LogMessageTest::test_line_order() {
+  LogMessageBuffer msg;
+  msg.info("info line").error("error line").trace("trace line")
+      .error("another error").warning("warning line").debug("debug line");
+  _log.write(msg);
+
+  const char* expected[] = { "info line", "error line", "trace line",
+                             "another error", "warning line", "debug line", NULL };
+  assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected),
+         "output missing or in incorrect order");
+}
+
+void LogMessageTest::test_long_message() {
+  // Write 10K bytes worth of log data
+  LogMessageBuffer msg;
+  const size_t size = 10 * K;
+  const char* start_marker = "#start#";
+  const char* end_marker = "#the end#";
+  char* data = NEW_C_HEAP_ARRAY(char, size, mtLogging);
+
+  // fill buffer with start_marker...some data...end_marker
+  sprintf(data, "%s", start_marker);
+  for (size_t i = strlen(start_marker); i < size; i++) {
+    data[i] = '0' + (i % 10);
+  }
+  sprintf(data + size - strlen(end_marker) - 1, "%s", end_marker);
+
+  msg.trace("%s", data); // Adds a newline, making the message exactly 10K in length.
+  _log.write(msg);
+
+  const char* expected[] = { start_marker, "0123456789", end_marker, NULL };
+  assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected),
+         "unable to print long line");
+  FREE_C_HEAP_ARRAY(char, data);
+}
+
+void LogMessageTest::test_message_with_many_lines() {
+  const size_t lines = 100;
+  const size_t line_length = 16;
+
+  LogMessageBuffer msg;
+  for (size_t i = 0; i < lines; i++) {
+    msg.info("Line #" SIZE_FORMAT, i);
+  }
+  _log.write(msg);
+
+  char expected_lines_data[lines][line_length];
+  const char* expected_lines[lines + 1];
+  for (size_t i = 0; i < lines; i++) {
+    jio_snprintf(&expected_lines_data[i][0], line_length, "Line #" SIZE_FORMAT, i);
+    expected_lines[i] = expected_lines_data[i];
+  }
+  expected_lines[lines] = NULL;
+
+  assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected_lines),
+         "couldn't find all lines in multiline message");
+}
+
+static size_t dummy_prefixer(char* buf, size_t len) {
+  static int i = 0;
+  const char* prefix = "some prefix: ";
+  const size_t prefix_len = strlen(prefix);
+  if (len < prefix_len) {
+    return prefix_len;
+  }
+  jio_snprintf(buf, len, "%s", prefix);
+  return prefix_len;
+}
+
+void LogMessageTest::test_prefixing() {
+  LogMessageBuffer msg;
+  msg.set_prefix(dummy_prefixer);
+  for (int i = 0; i < 3; i++) {
+    msg.info("test %d", i);
+  }
+  msg.set_prefix(NULL);
+  msg.info("test 3");
+  _log.write(msg);
+
+  const char* expected[] = {
+    "] some prefix: test 0",
+    "] some prefix: test 1",
+    "] some prefix: test 2",
+    "] test 3",
+    NULL
+  };
+  assert(file_contains_substrings_in_order(_level_filename[LogLevel::Trace], expected), "error in prefixed output");
+}
+
+void LogMessageTest::test_scoped_messages() {
+  {
+    LogMessage(logging) msg;
+    msg.info("scoped info");
+    msg.warning("scoped warn");
+    assert(!file_contains_substring(_level_filename[LogLevel::Info], "scoped info"),
+           "scoped log message written prematurely");
+  }
+  assert(file_contains_substring(_level_filename[LogLevel::Info], "scoped info"),
+         "missing output from scoped log message");
+  assert(file_contains_substring(_level_filename[LogLevel::Warning], "scoped warn"),
+         "missing output from scoped log message");
+}
+
+void LogMessageTest::test_scoped_flushing() {
+  {
+    LogMessage(logging) msg;
+    msg.info("manual flush info");
+    msg.flush();
+    assert(file_contains_substring(_level_filename[LogLevel::Info], "manual flush info"),
+           "missing output from manually flushed scoped log message");
+  }
+  const char* tmp[] = {"manual flush info", "manual flush info", NULL};
+  assert(!file_contains_substrings_in_order(_level_filename[LogLevel::Info], tmp),
+         "log file contains duplicate lines from single scoped log message");
+}
+
+void LogMessageTest::test_scoped_reset() {
+  {
+    LogMessage(logging) msg, partial;
+    msg.info("%s", "info reset msg");
+    msg.reset();
+    partial.info("%s", "info reset msg");
+    partial.reset();
+    partial.trace("%s", "trace reset msg");
+  }
+  assert(!file_contains_substring(_level_filename[LogLevel::Info], "info reset msg"),
+         "reset message written anyway");
+  assert(file_contains_substring(_level_filename[LogLevel::Trace], "trace reset msg"),
+         "missing message from partially reset scoped log message");
+}
+
+
 static int Test_logconfiguration_subscribe_triggered = 0;
 
 static void Test_logconfiguration_subscribe_helper() {

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

@@ -32,6 +32,8 @@
 #include "runtime/os.hpp"
 #include "utilities/debug.hpp"
 
+class LogMessageBuffer;
+
 //
 // Logging macros
 //
@@ -138,6 +140,10 @@ class LogImpl VALUE_OBJ_CLASS_SPEC {
     va_end(args);
   }
 
+  static void write(const LogMessageBuffer& msg) {
+    LogTagSetMapping<T0, T1, T2, T3, T4>::tagset().log(msg);
+  };
+
   template <LogLevelType Level>
   ATTRIBUTE_PRINTF(1, 2)
   static void write(const char* fmt, ...) {

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

@@ -32,7 +32,7 @@ jlong LogDecorations::_vm_start_time_millis = 0;
 const char* LogDecorations::_host_name = "";
 
 LogDecorations::LogDecorations(LogLevelType level, const LogTagSet &tagset, const LogDecorators &decorators)
-  : _level(level), _tagset(tagset), _millis(-1) {
+    : _level(level), _tagset(tagset), _millis(-1) {
   create_decorations(decorators);
 }
 
@@ -110,8 +110,9 @@ char * LogDecorations::create_tid_decoration(char* pos) {
 }
 
 char* LogDecorations::create_level_decoration(char* pos) {
-  int written = jio_snprintf(pos, DecorationsBufferSize - (pos - _decorations_buffer), "%s", LogLevel::name(_level));
-  ASSERT_AND_RETURN(written, pos)
+  // Avoid generating the level decoration because it may change.
+  // The decoration() method has a special case for level decorations.
+  return pos;
 }
 
 char* LogDecorations::create_tags_decoration(char* pos) {

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

@@ -53,7 +53,18 @@ class LogDecorations VALUE_OBJ_CLASS_SPEC {
 
   LogDecorations(LogLevelType level, const LogTagSet& tagset, const LogDecorators& decorators);
 
+  LogLevelType level() const {
+    return _level;
+  }
+
+  void set_level(LogLevelType level) {
+    _level = level;
+  }
+
   const char* decoration(LogDecorators::Decorator decorator) const {
+    if (decorator == LogDecorators::level_decorator) {
+      return LogLevel::name(_level);
+    }
     return _decoration_offset[decorator];
   }
 };

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

@@ -102,6 +102,10 @@ class LogDecorators VALUE_OBJ_CLASS_SPEC {
     _decorators |= source._decorators;
   }
 
+  bool is_empty() const {
+    return _decorators == 0;
+  }
+
   bool is_decorator(LogDecorators::Decorator decorator) const {
     return (_decorators & mask(decorator)) != 0;
   }

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

@@ -278,6 +278,24 @@ int LogFileOutput::write(const LogDecorations& decorations, const char* msg) {
   return written;
 }
 
+int LogFileOutput::write(LogMessageBuffer::Iterator msg_iterator) {
+  if (_stream == NULL) {
+    // An error has occurred with this output, avoid writing to it.
+    return 0;
+  }
+
+  _rotation_semaphore.wait();
+  int written = LogFileStreamOutput::write(msg_iterator);
+  _current_size += written;
+
+  if (should_rotate()) {
+    rotate();
+  }
+  _rotation_semaphore.signal();
+
+  return written;
+}
+
 void LogFileOutput::archive() {
   assert(_archive_name != NULL && _archive_name_len > 0, "Rotation must be configured before using this function.");
   int ret = jio_snprintf(_archive_name, _archive_name_len, "%s.%0*u",

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

@@ -83,6 +83,7 @@ class LogFileOutput : public LogFileStreamOutput {
   virtual ~LogFileOutput();
   virtual bool initialize(const char* options, outputStream* errstream);
   virtual int write(const LogDecorations& decorations, const char* msg);
+  virtual int write(LogMessageBuffer::Iterator msg_iterator);
   virtual void force_rotate();
 
   virtual const char* name() const {

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

@@ -25,14 +25,13 @@
 #include "logging/logDecorators.hpp"
 #include "logging/logDecorations.hpp"
 #include "logging/logFileStreamOutput.hpp"
+#include "logging/logMessageBuffer.hpp"
 #include "memory/allocation.inline.hpp"
 
 LogStdoutOutput LogStdoutOutput::_instance;
 LogStderrOutput LogStderrOutput::_instance;
 
-int LogFileStreamOutput::write(const LogDecorations& decorations, const char* msg) {
-  char decoration_buf[LogDecorations::DecorationsBufferSize];
-  char* position = decoration_buf;
+int LogFileStreamOutput::write_decorations(const LogDecorations& decorations) {
   int total_written = 0;
 
   for (uint i = 0; i < LogDecorators::Count; i++) {
@@ -40,23 +39,50 @@ int LogFileStreamOutput::write(const LogDecorations& decorations, const char* ms
     if (!_decorators.is_decorator(decorator)) {
       continue;
     }
-    int written = jio_snprintf(position, sizeof(decoration_buf) - total_written, "[%-*s]",
-                               _decorator_padding[decorator],
-                               decorations.decoration(decorator));
+
+    int written = jio_fprintf(_stream, "[%-*s]",
+                              _decorator_padding[decorator],
+                              decorations.decoration(decorator));
     if (written <= 0) {
       return -1;
     } else if (static_cast<size_t>(written - 2) > _decorator_padding[decorator]) {
       _decorator_padding[decorator] = written - 2;
     }
-    position += written;
     total_written += written;
   }
-
-  if (total_written == 0) {
-    total_written = jio_fprintf(_stream, "%s\n", msg);
-  } else {
-    total_written = jio_fprintf(_stream, "%s %s\n", decoration_buf, msg);
-  }
-  fflush(_stream);
   return total_written;
 }
+
+int LogFileStreamOutput::write(const LogDecorations& decorations, const char* msg) {
+  const bool use_decorations = !_decorators.is_empty();
+
+  int written = 0;
+  os::flockfile(_stream);
+  if (use_decorations) {
+    written += write_decorations(decorations);
+    written += jio_fprintf(_stream, " ");
+  }
+  written += jio_fprintf(_stream, "%s\n", msg);
+  fflush(_stream);
+  os::funlockfile(_stream);
+
+  return written;
+}
+
+int LogFileStreamOutput::write(LogMessageBuffer::Iterator msg_iterator) {
+  const bool use_decorations = !_decorators.is_empty();
+
+  int written = 0;
+  os::flockfile(_stream);
+  for (; !msg_iterator.is_at_end(); msg_iterator++) {
+    if (use_decorations) {
+      written += write_decorations(msg_iterator.decorations());
+      written += jio_fprintf(_stream, " ");
+    }
+    written += jio_fprintf(_stream, "%s\n", msg_iterator.message());
+  }
+  fflush(_stream);
+  os::funlockfile(_stream);
+
+  return written;
+}

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

@@ -42,8 +42,11 @@ class LogFileStreamOutput : public LogOutput {
     }
   }
 
+  int write_decorations(const LogDecorations& decorations);
+
  public:
-  virtual int write(const LogDecorations &decorations, const char* msg);
+  virtual int write(const LogDecorations& decorations, const char* msg);
+  virtual int write(LogMessageBuffer::Iterator msg_iterator);
 };
 
 class LogStdoutOutput : public LogFileStreamOutput {

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

@@ -0,0 +1,105 @@
+/*
+ * Copyright (c) 2016, 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.
+ *
+ */
+#ifndef SHARE_VM_LOGGING_LOGMESSAGE_HPP
+#define SHARE_VM_LOGGING_LOGMESSAGE_HPP
+
+#include "logging/log.hpp"
+#include "logging/logMessageBuffer.hpp"
+#include "logging/logPrefix.hpp"
+#include "logging/logTag.hpp"
+
+// The LogMessage class represents a multi-part/multi-line message
+// that is guaranteed to be sent and written to the log outputs
+// in a way that prevents interleaving by other log messages.
+//
+// The interface of LogMessage is very similar to the Log class,
+// with printf functions for each level (trace(), debug(), etc).
+// The difference is that these functions will append/write to the
+// LogMessage, which only buffers the message-parts until the whole
+// message is sent to a log (using Log::write). Internal buffers
+// are C heap allocated lazily on first write. LogMessages are
+// automatically written when they go out of scope.
+//
+// Example usage:
+//
+// {
+//   LogMessage(logging) msg;
+//   if (msg.is_debug()) {
+//     msg.debug("debug message");
+//     msg.trace("additional trace information");
+//   }
+// }
+//
+// Log outputs on trace level will see both of the messages above,
+// and the trace line will immediately follow the debug line.
+// They will have identical decorations (apart from level).
+// Log outputs on debug level will see the debug message,
+// but not the trace message.
+//
+#define LogMessage(...) LogMessageImpl<LOG_TAGS(__VA_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 LogMessageImpl : public LogMessageBuffer {
+ private:
+  LogImpl<T0, T1, T2, T3, T4, GuardTag> _log;
+  bool _has_content;
+
+ public:
+  LogMessageImpl() : _has_content(false) {
+  }
+
+  ~LogMessageImpl() {
+    if (_has_content) {
+      flush();
+    }
+  }
+
+  void flush() {
+    _log.write(*this);
+    reset();
+  }
+
+  void reset() {
+    _has_content = false;
+    LogMessageBuffer::reset();
+  }
+
+  ATTRIBUTE_PRINTF(3, 0)
+  void vwrite(LogLevelType level, const char* fmt, va_list args) {
+    if (!_has_content) {
+      _has_content = true;
+      set_prefix(LogPrefix<T0, T1, T2, T3, T4>::prefix);
+    }
+    LogMessageBuffer::vwrite(level, fmt, args);
+  }
+
+#define LOG_LEVEL(level, name) \
+  bool is_##name() const { \
+    return _log.is_level(LogLevel::level); \
+  }
+  LOG_LEVEL_LIST
+#undef LOG_LEVEL
+};
+
+#endif // SHARE_VM_LOGGING_LOGMESSAGE_HPP

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

@@ -0,0 +1,146 @@
+/*
+ * Copyright (c) 2016, 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.
+ *
+ */
+#include "precompiled.hpp"
+#include "logging/logMessageBuffer.hpp"
+#include "memory/allocation.inline.hpp"
+#include "runtime/thread.inline.hpp"
+
+template <typename T>
+static void grow(T*& buffer, size_t& capacity, size_t minimum_length = 0) {
+  size_t new_size = capacity * 2;
+  if (new_size < minimum_length) {
+    new_size = minimum_length;
+  }
+  buffer = REALLOC_C_HEAP_ARRAY(T, buffer, new_size, mtLogging);
+  capacity = new_size;
+}
+
+LogMessageBuffer::LogMessageBuffer() : _message_buffer_size(0),
+                                       _message_buffer_capacity(0),
+                                       _message_buffer(NULL),
+                                       _line_count(0),
+                                       _line_capacity(0),
+                                       _lines(NULL),
+                                       _allocated(false),
+                                       _least_detailed_level(LogLevel::Off),
+                                       _prefix_fn(NULL) {
+}
+
+LogMessageBuffer::~LogMessageBuffer() {
+  if (_allocated) {
+    FREE_C_HEAP_ARRAY(char, _message_buffer);
+    FREE_C_HEAP_ARRAY(LogLine, _lines);
+  }
+}
+
+void LogMessageBuffer::reset() {
+  _message_buffer_size = 0;
+  _line_count = 0;
+}
+
+void LogMessageBuffer::initialize_buffers() {
+  assert(!_allocated, "buffer already initialized/allocated");
+  _allocated = true;
+  _message_buffer = NEW_C_HEAP_ARRAY(char, InitialMessageBufferCapacity, mtLogging);
+  _lines = NEW_C_HEAP_ARRAY(LogLine, InitialLineCapacity, mtLogging);
+  _message_buffer_capacity = InitialMessageBufferCapacity;
+  _line_capacity = InitialLineCapacity;
+}
+
+void LogMessageBuffer::Iterator::skip_messages_with_finer_level() {
+  for (; _current_line_index < _message._line_count; _current_line_index++) {
+    if (_message._lines[_current_line_index].level >= _level) {
+      break;
+    }
+  }
+}
+
+void LogMessageBuffer::write(LogLevelType level, const char* fmt, ...) {
+  va_list args;
+  va_start(args, fmt);
+  vwrite(level, fmt, args);
+  va_end(args);
+};
+
+void LogMessageBuffer::vwrite(LogLevelType level, const char* fmt, va_list args) {
+  if (!_allocated) {
+    initialize_buffers();
+  }
+
+  if (level > _least_detailed_level) {
+    _least_detailed_level = level;
+  }
+
+  size_t written;
+  for (int attempts = 0; attempts < 2; attempts++) {
+    written = 0;
+    size_t remaining_buffer_length = _message_buffer_capacity - _message_buffer_size;
+    char* current_buffer_position = _message_buffer + _message_buffer_size;
+
+    if (_prefix_fn != NULL) {
+      written += _prefix_fn(current_buffer_position, remaining_buffer_length);
+      current_buffer_position += written;
+      if (remaining_buffer_length < written) {
+        remaining_buffer_length = 0;
+      } else {
+        remaining_buffer_length -= written;
+      }
+    }
+
+    va_list copy;
+    va_copy(copy, args);
+    written += (size_t)os::log_vsnprintf(current_buffer_position, remaining_buffer_length, fmt, copy) + 1;
+    va_end(copy);
+    if (written > _message_buffer_capacity - _message_buffer_size) {
+      assert(attempts == 0, "Second attempt should always have a sufficiently large buffer (resized to fit).");
+      grow(_message_buffer, _message_buffer_capacity, _message_buffer_size + written);
+      continue;
+    }
+    break;
+  }
+
+  if (_line_count == _line_capacity) {
+    grow(_lines, _line_capacity);
+  }
+
+  _lines[_line_count].level = level;
+  _lines[_line_count].message_offset = _message_buffer_size;
+  _message_buffer_size += written;
+  _line_count++;
+}
+
+#define LOG_LEVEL(level, name) \
+LogMessageBuffer& LogMessageBuffer::v##name(const char* fmt, va_list args) { \
+  vwrite(LogLevel::level, fmt, args); \
+  return *this; \
+} \
+LogMessageBuffer& LogMessageBuffer::name(const char* fmt, ...) { \
+  va_list args; \
+  va_start(args, fmt); \
+  vwrite(LogLevel::level, fmt, args); \
+  va_end(args); \
+  return *this; \
+}
+LOG_LEVEL_LIST
+#undef LOG_LEVEL

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

@@ -0,0 +1,131 @@
+/*
+ * Copyright (c) 2016, 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.
+ *
+ */
+#ifndef SHARE_VM_LOGGING_LOGMESSAGEBUFFER_HPP
+#define SHARE_VM_LOGGING_LOGMESSAGEBUFFER_HPP
+
+#include "logging/logDecorations.hpp"
+#include "logging/logLevel.hpp"
+#include "memory/allocation.hpp"
+
+class LogMessageBuffer : public StackObj {
+  friend class LogMessageTest;
+ protected:
+  struct LogLine VALUE_OBJ_CLASS_SPEC {
+    LogLevelType level;
+    size_t message_offset;
+  };
+  static const size_t InitialLineCapacity = 10;
+  static const size_t InitialMessageBufferCapacity = 1024;
+
+  size_t _message_buffer_size;
+  size_t _message_buffer_capacity;
+  char* _message_buffer;
+
+  size_t _line_count;
+  size_t _line_capacity;
+  LogLine* _lines;
+
+  bool _allocated;
+  LogLevelType _least_detailed_level;
+  size_t (*_prefix_fn)(char*, size_t);
+
+  void initialize_buffers();
+
+ private:
+  // Forbid copy assignment and copy constructor.
+  void operator=(const LogMessageBuffer& ref) {}
+  LogMessageBuffer(const LogMessageBuffer& ref) {}
+
+ public:
+  LogMessageBuffer();
+  ~LogMessageBuffer();
+
+  class Iterator {
+   private:
+    const LogMessageBuffer& _message;
+    size_t _current_line_index;
+    LogLevelType _level;
+    LogDecorations &_decorations;
+
+    void skip_messages_with_finer_level();
+
+   public:
+    Iterator(const LogMessageBuffer& message, LogLevelType level, LogDecorations& decorations)
+        : _message(message), _level(level), _decorations(decorations), _current_line_index(0) {
+      skip_messages_with_finer_level();
+    }
+
+    void operator++(int) {
+      _current_line_index++;
+      skip_messages_with_finer_level();
+    }
+
+    bool is_at_end() {
+      return _current_line_index == _message._line_count;
+    }
+
+    const char* message() const {
+      return _message._message_buffer + _message._lines[_current_line_index].message_offset;
+    }
+
+    const LogDecorations& decorations() {
+      _decorations.set_level(_message._lines[_current_line_index].level);
+      return _decorations;
+    }
+  };
+
+  void reset();
+
+  LogLevelType least_detailed_level() const {
+    return _least_detailed_level;
+  }
+
+  Iterator iterator(LogLevelType level, LogDecorations& decorations) const {
+    return Iterator(*this, level, decorations);
+  }
+
+  // Lines in LogMessageBuffers are not automatically prefixed based on tags
+  // like regular simple messages (see LogPrefix.hpp for more about prefixes).
+  // It is, however, possible to specify a prefix per LogMessageBuffer,
+  // using set_prefix(). Lines added to the LogMessageBuffer after a prefix
+  // function has been set will be prefixed automatically.
+  // Setting this to NULL will disable prefixing.
+  void set_prefix(size_t (*prefix_fn)(char*, size_t)) {
+    _prefix_fn = prefix_fn;
+  }
+
+  ATTRIBUTE_PRINTF(3, 4)
+  void write(LogLevelType level, const char* fmt, ...);
+
+  ATTRIBUTE_PRINTF(3, 0)
+  virtual void vwrite(LogLevelType level, const char* fmt, va_list args);
+
+#define LOG_LEVEL(level, name) \
+  LogMessageBuffer& v##name(const char* fmt, va_list args) ATTRIBUTE_PRINTF(2, 0); \
+  LogMessageBuffer& name(const char* fmt, ...) ATTRIBUTE_PRINTF(2, 3);
+  LOG_LEVEL_LIST
+#undef LOG_LEVEL
+};
+
+#endif // SHARE_VM_LOGGING_LOGMESSAGEBUFFER_HPP

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

@@ -26,10 +26,12 @@
 
 #include "logging/logDecorators.hpp"
 #include "logging/logLevel.hpp"
+#include "logging/logMessageBuffer.hpp"
 #include "memory/allocation.hpp"
 #include "utilities/globalDefinitions.hpp"
 
 class LogDecorations;
+class LogMessageBuffer;
 class LogTagSet;
 
 // The base class/interface for log outputs.
@@ -83,7 +85,8 @@ class LogOutput : public CHeapObj<mtLogging> {
 
   virtual const char* name() const = 0;
   virtual bool initialize(const char* options, outputStream* errstream) = 0;
-  virtual int write(const LogDecorations &decorations, const char* msg) = 0;
+  virtual int write(const LogDecorations& decorations, const char* msg) = 0;
+  virtual int write(LogMessageBuffer::Iterator msg_iterator) = 0;
 };
 
 #endif // SHARE_VM_LOGGING_LOGOUTPUT_HPP

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

@@ -113,6 +113,10 @@ class LogOutputList VALUE_OBJ_CLASS_SPEC {
     bool operator!=(const LogOutputNode *ref) const {
       return _current != ref;
     }
+
+    LogLevelType level() const {
+      return _current->_level;
+    }
   };
 
   Iterator iterator(LogLevelType level = LogLevel::Last) {

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

@@ -96,9 +96,14 @@ struct LogPrefix : public AllStatic {
 #define LOG_PREFIX(fn, ...) \
 template <> struct LogPrefix<__VA_ARGS__> { \
   static size_t prefix(char* buf, size_t len) { \
-    DEBUG_ONLY(buf[0] = '\0';) \
     size_t ret = fn(buf, len); \
-    assert(ret == strlen(buf), "Length mismatch ret (" SIZE_FORMAT ") != buf length (" SIZE_FORMAT ")", ret, strlen(buf)); \
+    /* Either prefix did fit (strlen(buf) == ret && ret < len) */ \
+    /* or the prefix didn't fit in buffer (ret > len && strlen(buf) < len) */ \
+    assert(ret == 0 || strlen(buf) < len, \
+           "Buffer overrun by prefix function."); \
+    assert(ret == 0 || strlen(buf) == ret || ret >= len, \
+           "Prefix function should return length of prefix written," \
+           " or the intended length of prefix if the buffer was too small."); \
     return ret; \
   } \
 };

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

@@ -24,6 +24,7 @@
 #include "precompiled.hpp"
 #include "logging/logDecorations.hpp"
 #include "logging/logLevel.hpp"
+#include "logging/logMessageBuffer.hpp"
 #include "logging/logOutput.hpp"
 #include "logging/logTag.hpp"
 #include "logging/logTagSet.hpp"
@@ -74,6 +75,13 @@ void LogTagSet::log(LogLevelType level, const char* msg) {
   }
 }
 
+void LogTagSet::log(const LogMessageBuffer& msg) {
+  LogDecorations decorations(LogLevel::Invalid, *this, _decorators);
+  for (LogOutputList::Iterator it = _output_list.iterator(msg.least_detailed_level()); it != _output_list.end(); it++) {
+    (*it)->write(msg.iterator(it.level(), decorations));
+  }
+}
+
 int LogTagSet::label(char* buf, size_t len, const char* separator) const {
   int tot_written = 0;
   for (size_t i = 0; i < _ntags; i++) {

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

@@ -31,6 +31,8 @@
 #include "logging/logTag.hpp"
 #include "utilities/globalDefinitions.hpp"
 
+class LogMessageBuffer;
+
 // The tagset represents a combination of tags that occur in a log call somewhere.
 // Tagsets are created automatically by the LogTagSetMappings and should never be
 // instantiated directly somewhere else.
@@ -110,6 +112,7 @@ class LogTagSet VALUE_OBJ_CLASS_SPEC {
     return _output_list.is_level(level);
   }
   void log(LogLevelType level, const char* msg);
+  void log(const LogMessageBuffer& msg);
 
   ATTRIBUTE_PRINTF(3, 4)
   void write(LogLevelType level, const char* fmt, ...);

hotspot/src/share/vm/runtime/os.hpp

@@ -521,6 +521,8 @@ class os: AllStatic {
   static int fsync(int fd);
   static int available(int fd, jlong *bytes);
   static int get_fileno(FILE* fp);
+  static void flockfile(FILE* fp);
+  static void funlockfile(FILE* fp);
 
   static int compare_file_modified_times(const char* file1, const char* file2);
 

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

@@ -81,6 +81,7 @@ void InternalVMTests::run() {
   run_unit_test(Test_log_file_startup_rotation);
   run_unit_test(Test_log_file_startup_truncation);
   run_unit_test(Test_invalid_log_file);
+  run_unit_test(Test_multiline_logging);
   run_unit_test(DirectivesParser_test);
   run_unit_test(Test_TempNewSymbol);
 #if INCLUDE_VM_STRUCTS