# HG changeset patch # User mlarsson # Date 1457517919 -3600 # Wed Mar 09 11:05:19 2016 +0100 # Node ID 606a595af071839c3d8f7adb429ab3be94a0e0ae # Parent 47a9289d9b0b141ff6a5af43a53362f53aa27bf7 imported patch 8146879.03 diff --git a/src/os/posix/vm/os_posix.cpp b/src/os/posix/vm/os_posix.cpp --- a/src/os/posix/vm/os_posix.cpp +++ b/src/os/posix/vm/os_posix.cpp @@ -181,6 +181,32 @@ return vsnprintf(buf, len, fmt, args); } +int os::fileno(FILE* fp) { + return ::fileno(fp); +} + +int os::compare_file_modified_times(const char* file1, const char* file2) { + struct stat st[2]; + struct timespec filetime[2]; + + for (int i = 0; i < 2; i++) { + const char* file = (i == 0 ? file1 : file2); + int ret = os::stat(file, &st[i]); + assert(ret == 0, "failed to stat() file '%s': %s", file, strerror(errno)); +#ifdef __APPLE__ + filetime[i] = st[i].st_mtimespec; +#else + filetime[i] = st[i].st_mtim; +#endif + } + + int diff = filetime[0].tv_sec - filetime[1].tv_sec; + if (diff == 0) { + return filetime[0].tv_nsec - filetime[1].tv_nsec; + } + return diff; +} + void os::Posix::print_load_average(outputStream* st) { st->print("load average:"); double loadavg[3]; diff --git a/src/os/windows/vm/os_windows.cpp b/src/os/windows/vm/os_windows.cpp --- a/src/os/windows/vm/os_windows.cpp +++ b/src/os/windows/vm/os_windows.cpp @@ -1594,6 +1594,21 @@ return ret; } +int os::compare_file_modified_times(const char* file1, const char* file2) { + FILETIME ft[2]; + + for (int i = 0; i < 2; i++) { + const char* file = (i == 0 ? file1 : file2); + HANDLE fhandle = CreateFile(file, GENERIC_READ, 0, NULL, + OPEN_EXISTING, 0, NULL); + BOOL ret = GetFileTime(fhandle, NULL, NULL, &ft[i]); + assert(ret, "GetFileTime for file %s failed: %d", file, GetLastError()); + CloseHandle(fhandle); + } + + return CompareFileTime(&ft[0], &ft[2]); +} + void os::print_os_info_brief(outputStream* st) { os::print_os_info(st); } @@ -4613,6 +4628,9 @@ return 0; } +int os::fileno(FILE* fp) { + return _fileno(fp); +} // This code is a copy of JDK's sysSync // from src/windows/hpi/src/sys_api_md.c diff --git a/src/share/vm/logging/log.cpp b/src/share/vm/logging/log.cpp --- a/src/share/vm/logging/log.cpp +++ b/src/share/vm/logging/log.cpp @@ -133,7 +133,110 @@ assert_str_eq("all=off", stdoutput->config_string()); // Restore saved configuration + if (saved_config[strlen(saved_config) - 1] == ',') { + saved_config[strlen(saved_config) - 1] = '\0'; // strip trailing comma + } LogConfiguration::parse_log_arguments("stdout", saved_config, NULL, NULL, log.error_stream()); os::free(saved_config); } + +static size_t number_of_lines_with_substring_in_file(const char* filename, + const char* substr) { + size_t ret = 0; + FILE* fp = fopen(filename, "r"); + assert(fp, "error opening file %s: %s", filename, strerror(errno)); + char buf[512]; + while (fgets(buf, sizeof(buf), fp) != NULL) { + 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 const char* ExpectedLine = "a (hopefully) unique log line for testing"; + +static void init_file(const char* filename, const char* options = "") { + LogConfiguration::parse_log_arguments(filename, "logging=trace", "", options, + LogHandle(logging)::error_stream()); + log_debug(logging)("%s", ExpectedLine); + LogConfiguration::parse_log_arguments(filename, "all=off", "", "", + LogHandle(logging)::error_stream()); +} + +void Test_log_file_startup_rotation() { + ResourceMark rm; + const size_t rotations = 5; + const char* filename = "start-rotate-test"; + char* rotated_file[rotations]; + for (size_t i = 0; i < rotations; i++) { + size_t len = strlen(filename) + 3; + rotated_file[i] = NEW_RESOURCE_ARRAY(char, len); + jio_snprintf(rotated_file[i], len, "%s." SIZE_FORMAT, filename, i); + delete_file(rotated_file[i]); + }; + + delete_file(filename); + init_file(filename); + assert(file_exists(filename), + "configured logging to file '%s' but file was not found", filename); + + // Initialize the same file a bunch more times to trigger rotations + for (size_t i = 0; i < rotations; i++) { + init_file(filename); + assert(file_exists(rotated_file[i]), "existing file was not rotated"); + } + + // Remove a file and expect its slot to be re-used + delete_file(rotated_file[1]); + init_file(filename); + assert(file_exists(rotated_file[1]), "log file not properly rotated"); + + // Clean up after test + delete_file(filename); + for (size_t i = 0; i < rotations; i++) { + delete_file(rotated_file[i]); + } +} + +void Test_log_file_startup_truncation() { + ResourceMark rm; + const char* filename = "start-truncate-test"; + const char* archived_filename = "start-truncate-test.0"; + + delete_file(filename); + delete_file(archived_filename); + + // Use the same log file twice and expect it to be overwritten/truncated + init_file(filename, "filecount=0"); + assert(file_exists(filename), "couldn't find log file: %s", filename); + + init_file(filename, "filecount=0"); + assert(file_exists(filename), "couldn't find log file: %s", filename); + assert(!file_exists(archived_filename), + "existing log file %s was not properly truncated when filecount was 0", + filename); + + // Verify that the file was really truncated and not just appended + assert(number_of_lines_with_substring_in_file(filename, ExpectedLine) == 1, + "log file %s appended rather than truncated", filename); + + delete_file(filename); + delete_file(archived_filename); +} + #endif // PRODUCT diff --git a/src/share/vm/logging/logFileOutput.cpp b/src/share/vm/logging/logFileOutput.cpp --- a/src/share/vm/logging/logFileOutput.cpp +++ b/src/share/vm/logging/logFileOutput.cpp @@ -41,8 +41,9 @@ LogFileOutput::LogFileOutput(const char* name) : LogFileStreamOutput(NULL), _name(os::strdup_check_oom(name, mtLogging)), - _file_name(NULL), _archive_name(NULL), _archive_name_len(0), _current_size(0), - _rotate_size(0), _current_file(1), _file_count(0), _rotation_semaphore(1) { + _file_name(NULL), _archive_name(NULL), _archive_name_len(0), + _rotate_size(DefaultRotationFileSize), _file_count(DefaultRotationFileCount), + _current_size(0), _current_file(0), _rotation_semaphore(1) { _file_name = make_file_name(name, _pid_str, _vm_start_time_str); } @@ -59,9 +60,6 @@ LogFileOutput::~LogFileOutput() { if (_stream != NULL) { - if (_archive_name != NULL) { - archive(); - } if (fclose(_stream) != 0) { jio_fprintf(defaultStream::error_stream(), "Could not close log file '%s' (%s).\n", _file_name, strerror(errno)); @@ -72,7 +70,7 @@ os::free(const_cast(_name)); } -size_t LogFileOutput::parse_value(const char* value_str) { +static size_t parse_value(const char* value_str) { char* end; unsigned long long value = strtoull(value_str, &end, 10); if (!isdigit(*value_str) || end != value_str + strlen(value_str) || value >= SIZE_MAX) { @@ -81,7 +79,57 @@ return value; } -bool LogFileOutput::configure_rotation(const char* options) { +static bool file_exists(const char* filename) { + struct stat dummy_stat; + return os::stat(filename, &dummy_stat) == 0; +} + +static uint number_of_digits(uint number) { + double d = static_cast(number); + uint res = 1 + log10(d); + return res; +} + +static uint next_file_number(const char* filename, + uint number_of_digits, + uint filecount) { + bool found = false; + uint next_num = 0; + + // len is filename + dot + digits + null char + size_t len = strlen(filename) + number_of_digits + 2; + char* archive_name = NEW_C_HEAP_ARRAY(char, len, mtLogging); + char* oldest_name = NEW_C_HEAP_ARRAY(char, len, mtLogging); + + for (uint i = 0; i < filecount; i++) { + int ret = jio_snprintf(archive_name, len, "%s.%0*u", + filename, number_of_digits, i); + assert(ret > 0 && static_cast(ret) == len - 1, + "incorrect buffer length calculation"); + + // Stop looking if we find an unused file name + if (!file_exists(archive_name)) { + next_num = i; + found = true; + break; + } + + // Keep track of oldest existing log file + if (!found + || os::compare_file_modified_times(oldest_name, archive_name) > 0) { + strcpy(oldest_name, archive_name); + next_num = i; + found = true; + } + } + + FREE_C_HEAP_ARRAY(char, oldest_name); + FREE_C_HEAP_ARRAY(char, archive_name); + assert(found, "should always find a next number"); + return next_num; +} + +bool LogFileOutput::configure(const char* options) { if (options == NULL || strlen(options) == 0) { return true; } @@ -112,9 +160,6 @@ break; } _file_count = static_cast(value); - _file_count_max_digits = static_cast(log10(static_cast(_file_count)) + 1); - _archive_name_len = 2 + strlen(_file_name) + _file_count_max_digits; - _archive_name = NEW_C_HEAP_ARRAY(char, _archive_name_len, mtLogging); } else if (strcmp(FileSizeOptionKey, key) == 0) { size_t value = parse_value(value_str); if (value == SIZE_MAX || value > SIZE_MAX / K) { @@ -134,14 +179,40 @@ } bool LogFileOutput::initialize(const char* options) { - if (!configure_rotation(options)) { + if (!configure(options)) { return false; } + + if (_file_count > 0) { + _file_count_max_digits = number_of_digits(_file_count - 1); // -1 for 0-index + _archive_name_len = 2 + strlen(_file_name) + _file_count_max_digits; + _archive_name = NEW_C_HEAP_ARRAY(char, _archive_name_len, mtLogging); + } + + log_trace(logging)("Initializing logging to file '%s' (filecount: %u" + ", filesize: " SIZE_FORMAT " KiB).", + _file_name, _file_count, _rotate_size / K); + + if (_file_count > 0 && file_exists(_file_name)) { + _current_file = next_file_number(_file_name, + _file_count_max_digits, + _file_count); + log_trace(logging)("Existing log file found, saving it as '%s.%0*u'.", + _file_name, _file_count_max_digits, _current_file); + archive(); + } + _stream = fopen(_file_name, FileOpenMode); if (_stream == NULL) { - log_error(logging)("Could not open log file '%s' (%s).\n", _file_name, strerror(errno)); + log_error(logging)("Could not open log file '%s' (%s).", _file_name, strerror(errno)); return false; } + + if (_file_count == 0) { + log_trace(logging)("Truncating log file"); + os::ftruncate(os::fileno(_stream), 0); + } + return true; } @@ -210,7 +281,10 @@ // Reset accumulated size, increase current file counter, and check for file count wrap-around. _current_size = 0; - _current_file = (_current_file >= _file_count ? 1 : _current_file + 1); + _current_file++; + if (_current_file == _file_count) { + _current_file = 0; + } } char* LogFileOutput::make_file_name(const char* file_name, diff --git a/src/share/vm/logging/logFileOutput.hpp b/src/share/vm/logging/logFileOutput.hpp --- a/src/share/vm/logging/logFileOutput.hpp +++ b/src/share/vm/logging/logFileOutput.hpp @@ -39,6 +39,8 @@ static const char* PidFilenamePlaceholder; static const char* TimestampFilenamePlaceholder; static const char* TimestampFormat; + static const size_t DefaultRotationFileCount = 5; + static const size_t DefaultRotationFileSize = 2097152; // 20MiB static const size_t StartTimeBufferSize = 20; static const size_t PidBufferSize = 21; static char _pid_str[PidBufferSize]; @@ -61,9 +63,8 @@ void archive(); void rotate(); - bool configure_rotation(const char* options); + bool configure(const char* options); char *make_file_name(const char* file_name, const char* pid_string, const char* timestamp_string); - static size_t parse_value(const char* value_str); bool should_rotate() { return _file_count > 0 && _rotate_size > 0 && _current_size >= _rotate_size; diff --git a/src/share/vm/runtime/os.hpp b/src/share/vm/runtime/os.hpp --- a/src/share/vm/runtime/os.hpp +++ b/src/share/vm/runtime/os.hpp @@ -515,6 +515,9 @@ static int ftruncate(int fd, jlong length); static int fsync(int fd); static int available(int fd, jlong *bytes); + static int fileno(FILE* fp); + + static int compare_file_modified_times(const char* file1, const char* file2); //File i/o operations diff --git a/src/share/vm/utilities/internalVMTests.cpp b/src/share/vm/utilities/internalVMTests.cpp --- a/src/share/vm/utilities/internalVMTests.cpp +++ b/src/share/vm/utilities/internalVMTests.cpp @@ -69,6 +69,8 @@ run_unit_test(JSON_test); run_unit_test(Test_log_length); run_unit_test(Test_configure_stdout); + run_unit_test(Test_log_file_startup_rotation); + run_unit_test(Test_log_file_startup_truncation); run_unit_test(DirectivesParser_test); run_unit_test(Test_TempNewSymbol); #if INCLUDE_VM_STRUCTS