8145934: Make ttyLocker equivalent for Unified Logging framework
Reviewed-by: rprotacio, stuefe, jrose
--- a/hotspot/src/os/posix/vm/os_posix.cpp Tue May 10 03:37:36 2016 +0000
+++ b/hotspot/src/os/posix/vm/os_posix.cpp Mon May 09 15:46:12 2016 +0200
@@ -327,6 +327,14 @@
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:
--- a/hotspot/src/os/windows/vm/os_windows.cpp Tue May 10 03:37:36 2016 +0000
+++ b/hotspot/src/os/windows/vm/os_windows.cpp Mon May 09 15:46:12 2016 +0200
@@ -4661,6 +4661,14 @@
}
}
+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
--- a/hotspot/src/share/vm/logging/log.cpp Tue May 10 03:37:36 2016 +0000
+++ b/hotspot/src/share/vm/logging/log.cpp Mon May 09 15:46:12 2016 +0200
@@ -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 @@
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 @@
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 @@
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() {
--- a/hotspot/src/share/vm/logging/log.hpp Tue May 10 03:37:36 2016 +0000
+++ b/hotspot/src/share/vm/logging/log.hpp Mon May 09 15:46:12 2016 +0200
@@ -32,6 +32,8 @@
#include "runtime/os.hpp"
#include "utilities/debug.hpp"
+class LogMessageBuffer;
+
//
// Logging macros
//
@@ -138,6 +140,10 @@
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, ...) {
--- a/hotspot/src/share/vm/logging/logDecorations.cpp Tue May 10 03:37:36 2016 +0000
+++ b/hotspot/src/share/vm/logging/logDecorations.cpp Mon May 09 15:46:12 2016 +0200
@@ -32,7 +32,7 @@
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_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) {
--- a/hotspot/src/share/vm/logging/logDecorations.hpp Tue May 10 03:37:36 2016 +0000
+++ b/hotspot/src/share/vm/logging/logDecorations.hpp Mon May 09 15:46:12 2016 +0200
@@ -53,7 +53,18 @@
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];
}
};
--- a/hotspot/src/share/vm/logging/logDecorators.hpp Tue May 10 03:37:36 2016 +0000
+++ b/hotspot/src/share/vm/logging/logDecorators.hpp Mon May 09 15:46:12 2016 +0200
@@ -102,6 +102,10 @@
_decorators |= source._decorators;
}
+ bool is_empty() const {
+ return _decorators == 0;
+ }
+
bool is_decorator(LogDecorators::Decorator decorator) const {
return (_decorators & mask(decorator)) != 0;
}
--- a/hotspot/src/share/vm/logging/logFileOutput.cpp Tue May 10 03:37:36 2016 +0000
+++ b/hotspot/src/share/vm/logging/logFileOutput.cpp Mon May 09 15:46:12 2016 +0200
@@ -278,6 +278,24 @@
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",
--- a/hotspot/src/share/vm/logging/logFileOutput.hpp Tue May 10 03:37:36 2016 +0000
+++ b/hotspot/src/share/vm/logging/logFileOutput.hpp Mon May 09 15:46:12 2016 +0200
@@ -83,6 +83,7 @@
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 {
--- a/hotspot/src/share/vm/logging/logFileStreamOutput.cpp Tue May 10 03:37:36 2016 +0000
+++ b/hotspot/src/share/vm/logging/logFileStreamOutput.cpp Mon May 09 15:46:12 2016 +0200
@@ -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 @@
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;
}
+ return total_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);
+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);
- return total_written;
+ os::funlockfile(_stream);
+
+ return written;
}
--- a/hotspot/src/share/vm/logging/logFileStreamOutput.hpp Tue May 10 03:37:36 2016 +0000
+++ b/hotspot/src/share/vm/logging/logFileStreamOutput.hpp Mon May 09 15:46:12 2016 +0200
@@ -42,8 +42,11 @@
}
}
+ 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 {
--- /dev/null Thu Jan 01 00:00:00 1970 +0000
+++ b/hotspot/src/share/vm/logging/logMessage.hpp Mon May 09 15:46:12 2016 +0200
@@ -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
--- /dev/null Thu Jan 01 00:00:00 1970 +0000
+++ b/hotspot/src/share/vm/logging/logMessageBuffer.cpp Mon May 09 15:46:12 2016 +0200
@@ -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
--- /dev/null Thu Jan 01 00:00:00 1970 +0000
+++ b/hotspot/src/share/vm/logging/logMessageBuffer.hpp Mon May 09 15:46:12 2016 +0200
@@ -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
--- a/hotspot/src/share/vm/logging/logOutput.hpp Tue May 10 03:37:36 2016 +0000
+++ b/hotspot/src/share/vm/logging/logOutput.hpp Mon May 09 15:46:12 2016 +0200
@@ -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 @@
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
--- a/hotspot/src/share/vm/logging/logOutputList.hpp Tue May 10 03:37:36 2016 +0000
+++ b/hotspot/src/share/vm/logging/logOutputList.hpp Mon May 09 15:46:12 2016 +0200
@@ -113,6 +113,10 @@
bool operator!=(const LogOutputNode *ref) const {
return _current != ref;
}
+
+ LogLevelType level() const {
+ return _current->_level;
+ }
};
Iterator iterator(LogLevelType level = LogLevel::Last) {
--- a/hotspot/src/share/vm/logging/logPrefix.hpp Tue May 10 03:37:36 2016 +0000
+++ b/hotspot/src/share/vm/logging/logPrefix.hpp Mon May 09 15:46:12 2016 +0200
@@ -96,9 +96,14 @@
#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; \
} \
};
--- a/hotspot/src/share/vm/logging/logTagSet.cpp Tue May 10 03:37:36 2016 +0000
+++ b/hotspot/src/share/vm/logging/logTagSet.cpp Mon May 09 15:46:12 2016 +0200
@@ -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(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++) {
--- a/hotspot/src/share/vm/logging/logTagSet.hpp Tue May 10 03:37:36 2016 +0000
+++ b/hotspot/src/share/vm/logging/logTagSet.hpp Mon May 09 15:46:12 2016 +0200
@@ -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 @@
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, ...);
--- a/hotspot/src/share/vm/runtime/os.hpp Tue May 10 03:37:36 2016 +0000
+++ b/hotspot/src/share/vm/runtime/os.hpp Mon May 09 15:46:12 2016 +0200
@@ -521,6 +521,8 @@
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);
--- a/hotspot/src/share/vm/utilities/internalVMTests.cpp Tue May 10 03:37:36 2016 +0000
+++ b/hotspot/src/share/vm/utilities/internalVMTests.cpp Mon May 09 15:46:12 2016 +0200
@@ -81,6 +81,7 @@
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