6950794: Make the GC log file name parameterized
Yasumasa Suenaga
suenaga.yasumasa at lab.ntt.co.jp
Thu Jul 26 00:47:51 UTC 2012
Hi,
I've made a patch for this RFE.
This patch allows for 4 parameters as following:
%p - Java process' PID
%t - date stamp when log file is created (format: YYYY-MM-DD)
%n - if log rotation logic is enabled, then log segment id, otherwise "0"
%% - escaped '%' character in file name
(These parameters are defined in 6950794)
Other features of this patch:
* The oldest log is removed. If you set -XX:NumberOfGCLogFiles=5 and
gc.log.0 - 4 is exists, gc.log.0 is removed and gc.log.5 is created.
* Log segment id (%n) is unsigned int . If id is UINT_MAX (0xFFFFFFFF),
next id is zero.
* I expanded Arguments::copy_expand_pid() . This modification affects
-XX:OnError, -XX:ErrorFile, -XX:PerfDataSaveFile . These option also
can use parameters that this patch provides.
If this is not good, I can separate this feature from Arguments::copy_expand_pid() .
This patch works fine in my environment.
I would like to contribute this patch.
Please cooperate.
Thanks,
Yasumasa
On 2012/07/20 9:58, Yasumasa Suenaga wrote:
> Hi Rainer,
>
> Do you point the following as "negative consequences" ? :
>
> http://mail.openjdk.java.net/pipermail/hotspot-gc-use/2010-May/000613.html
> ----------------
> * "f00.00000001 might have been detected as old and copied to the remote
> host and during the same time GC decides to now reuse it... That's why
> I personally find externally organized pruning better. Another thing I
> often miss is the ability to combine size and time based rotation." (Rainer)
>
> The proposal never reuses log files. We'll never overwrite anything.
> Instead, we'll delete the oldest files as we create new ones. If we tell
> the users to prune the older log files themselves, I know what the first
> bug filed against the new policy will be. :-) Regarding rotating based
> on both size and time: most people care about size so I think that's
> what we'll do. If you want more advanced management of the logs you'll
> have to set N to infinity (at least we'll need a way to say "never
> delete older files") so that HotSpot doesn't delete any files and you'll
> be able to copy them and delete them yourself.
>
> But, seriously, this is excellent feedback. You guys are doing more wild
> stuff with our logs than I had imagined. :-)
> ----------------
>
> Tony says "The proposal never reuses log files. We'll never overwrite anything."
> However, seems to reuse the oldest log :-)
>
> hotspot/src/share/vm/utilities/ostream.cpp:
> void rotatingFileStream::rotate_log()
>
>
> We can find the oldest log with "stat" command and can check mtime of
> all logs on Linux.
> I think that "mtime" is updated every write(2) syscall .
>
> At least, status of this RFE is "3-Accepted" .
> So I believe that this RFE will be merge mainline someday :-)
>
>
> Thanks,
>
> Yasumasa
>
> On 2012/07/19 23:52, Rainer Jung wrote:
>> On 19.07.2012 09:56, Yasumasa Suenaga wrote:
>>> Hi,
>>>
>>> I use GC log rotation with -XX:+UseGCLogFileRotation .
>>> However, suffix of logfile is fixed ( .N : cyclic 0-(NumberOfGCLogFiles-1) ) .
>>> So I'm not easy to find the oldest log.
>>> (I have to check timestamp of file or GC event time.)
>>
>> See the discussion thread starting at
>>
>> http://mail.openjdk.java.net/pipermail/hotspot-gc-use/2010-May/000597.html
>>
>> including a reply of mine on the negative consequences of the numeric naming scheme and responses of Tony to the comments on his proposal.
>>
>> Regards,
>>
>> Rainer
>>
>>> I hope that this RFE is merged to JDK6/7/8.
>>>
>>> Someone is working on this RFE ?
>>> If none, I would like to contribute a patch.
>>> (Then, please someone become a sponsor of me :-) )
-------------- next part --------------
diff -r e3619706a725 src/share/vm/runtime/arguments.cpp
--- a/src/share/vm/runtime/arguments.cpp Mon Jul 23 12:38:08 2012 -0700
+++ b/src/share/vm/runtime/arguments.cpp Wed Jul 25 15:26:43 2012 +0900
@@ -1705,8 +1705,10 @@
// no gc log rotation when log file not supplied or
// NumberOfGCLogFiles is 0, or GCLogFileSize is 0
void check_gclog_consistency() {
+ const char *gclog_name = Arguments::gc_log_filename();
+
if (UseGCLogFileRotation) {
- if ((Arguments::gc_log_filename() == NULL) ||
+ if ((gclog_name == NULL) ||
(NumberOfGCLogFiles == 0) ||
(GCLogFileSize == 0)) {
jio_fprintf(defaultStream::output_stream(),
@@ -1717,11 +1719,28 @@
}
}
- if (UseGCLogFileRotation && GCLogFileSize < 8*K) {
+ if(UseGCLogFileRotation){
+
+ if (GCLogFileSize < 8*K) {
FLAG_SET_CMDLINE(uintx, GCLogFileSize, 8*K);
jio_fprintf(defaultStream::output_stream(),
"GCLogFileSize changed to minimum 8K\n");
+ }
+
+ if(strstr(gclog_name, "%n") == NULL){
+ // I DO NOT use os::malloc() / os::free() .
+ // Because Arguments::_gc_log_filename is initialized through strdup()
+ // in Arguments::parse_each_vm_init_arg() (-Xloggc option)
+ char *buf = (char *)malloc(strlen(gclog_name) + 4);
+ strcpy(buf, gclog_name);
+ strcat(buf, ".%n");
+
+ free((char *)gclog_name);
+ Arguments::set_gc_log_filename(buf);
+ }
+
}
+
}
// Check consistency of GC selection
@@ -3380,7 +3399,12 @@
}
#endif // KERNEL
-// Copies src into buf, replacing "%%" with "%" and "%p" with pid
+// Copies src into buf with replacing format string.
+// Supported format stiring:
+// %% - escaped '%' character in string
+// %p - Java process' PID
+// %t - now date stamp (format: YYYY-MM-DD)
+// %n - log segment id (for UseGCLogFileRotation)
// Returns true if all of the source pointed by src has been copied over to
// the destination buffer pointed by buf. Otherwise, returns false.
// Notes:
@@ -3389,14 +3413,14 @@
// pid characters, it also returns false instead of returning the partially
// expanded one.
// 2. The passed in "buflen" should be large enough to hold the null terminator.
-bool Arguments::copy_expand_pid(const char* src, size_t srclen,
- char* buf, size_t buflen) {
+bool Arguments::copy_expand_parameter(const char* src, size_t srclen,
+ char* buf, size_t buflen, unsigned int segid) {
const char* p = src;
char* b = buf;
const char* src_end = &src[srclen];
char* buf_end = &buf[buflen - 1];
- while (p < src_end && b < buf_end) {
+ while (p != '\0' && p < src_end && b < buf_end) {
if (*p == '%') {
switch (*(++p)) {
case '%': // "%%" ==> "%"
@@ -3414,7 +3438,59 @@
return false;
} else {
b += ret;
- assert(*b == '\0', "fail in copy_expand_pid");
+ assert(*b == '\0', "fail in copy_expand_parameter");
+ if (p == src_end && b == buf_end + 1) {
+ // reach the end of the buffer.
+ return true;
+ }
+ }
+ p++;
+ break;
+ }
+ case 't': { // "%t" ==> now date (YYYY-MM-DD)
+ struct tm now_tm;
+ time_t now_time = time(NULL);
+
+ if(now_time == (time_t)-1){
+ return false;
+ }
+
+ if(os::localtime_pd(&now_time, &now_tm) == NULL){
+ return false;
+ }
+
+ // buf_end points to the character before the last character so
+ // that we could write '\0' to the end of the buffer.
+ size_t buf_sz = buf_end - b + 1;
+ size_t ret = strftime(b, buf_sz, "%F", &now_tm);
+
+ // if strftime() failed, returns false.
+ if (ret == 0) {
+ return false;
+ } else {
+ b += ret;
+ assert(*b == '\0', "fail in copy_expand_parameter");
+ if (p == src_end && b == buf_end + 1) {
+ // reach the end of the buffer.
+ return true;
+ }
+ }
+ p++;
+ break;
+ }
+ case 'n': { // "%n" ==> segment id
+ // buf_end points to the character before the last character so
+ // that we could write '\0' to the end of the buffer.
+ size_t buf_sz = buf_end - b + 1;
+ int ret = jio_snprintf(b, buf_sz, "%u", segid);
+
+ // if jio_snprintf fails or the buffer is not long enough to hold
+ // the segment id, returns false.
+ if (ret < 0 || ret >= (int)buf_sz) {
+ return false;
+ } else {
+ b += ret;
+ assert(*b == '\0', "fail in copy_expand_parameter");
if (p == src_end && b == buf_end + 1) {
// reach the end of the buffer.
return true;
diff -r e3619706a725 src/share/vm/runtime/arguments.hpp
--- a/src/share/vm/runtime/arguments.hpp Mon Jul 23 12:38:08 2012 -0700
+++ b/src/share/vm/runtime/arguments.hpp Wed Jul 25 15:26:43 2012 +0900
@@ -453,6 +453,7 @@
// -Xloggc:<file>, if not specified will be NULL
static const char* gc_log_filename() { return _gc_log_filename; }
+ static void set_gc_log_filename(const char *logname) { _gc_log_filename = logname; }
// -Xprof/-Xaprof
static bool has_profile() { return _has_profile; }
@@ -535,8 +536,8 @@
// Operation modi
static Mode mode() { return _mode; }
- // Utility: copies src into buf, replacing "%%" with "%" and "%p" with pid.
- static bool copy_expand_pid(const char* src, size_t srclen, char* buf, size_t buflen);
+ // Utility: copies src into buf, replacing format string.
+ static bool copy_expand_parameter(const char* src, size_t srclen, char* buf, size_t buflen, unsigned int segid = 0);
#ifdef KERNEL
// For java kernel vm, return property string for kernel properties.
diff -r e3619706a725 src/share/vm/runtime/perfMemory.cpp
--- a/src/share/vm/runtime/perfMemory.cpp Mon Jul 23 12:38:08 2012 -0700
+++ b/src/share/vm/runtime/perfMemory.cpp Wed Jul 25 15:26:43 2012 +0900
@@ -245,7 +245,7 @@
// dest_file_name stores the validated file name if file_name
// contains %p which will be replaced by pid.
dest_file = NEW_C_HEAP_ARRAY(char, JVM_MAXPATHLEN, mtInternal);
- if(!Arguments::copy_expand_pid(PerfDataSaveFile, strlen(PerfDataSaveFile),
+ if(!Arguments::copy_expand_parameter(PerfDataSaveFile, strlen(PerfDataSaveFile),
dest_file, JVM_MAXPATHLEN)) {
FREE_C_HEAP_ARRAY(char, dest_file, mtInternal);
if (PrintMiscellaneous && Verbose) {
diff -r e3619706a725 src/share/vm/utilities/ostream.cpp
--- a/src/share/vm/utilities/ostream.cpp Mon Jul 23 12:38:08 2012 -0700
+++ b/src/share/vm/utilities/ostream.cpp Wed Jul 25 15:26:43 2012 +0900
@@ -313,13 +313,25 @@
extern Mutex* tty_lock;
fileStream::fileStream(const char* file_name) {
- _file = fopen(file_name, "w");
- _need_close = true;
+ strncpy(_file_name, file_name, O_BUFLEN);
+
+ if(Arguments::copy_expand_parameter(
+ file_name, strlen(file_name), _opened_file, O_BUFLEN)){
+ _file = fopen(_opened_file, "w");
+ _need_close = true;
+ }
+
}
fileStream::fileStream(const char* file_name, const char* opentype) {
- _file = fopen(file_name, opentype);
- _need_close = true;
+ strncpy(_file_name, file_name, O_BUFLEN);
+
+ if(Arguments::copy_expand_parameter(
+ file_name, strlen(file_name), _opened_file, O_BUFLEN)){
+ _file = fopen(_opened_file, opentype);
+ _need_close = true;
+ }
+
}
void fileStream::write(const char* s, size_t len) {
@@ -353,6 +365,8 @@
if (_file != NULL) {
if (_need_close) fclose(_file);
_file = NULL;
+ _file_name[0] = '\0';
+ _opened_file[0] = '\0';
}
}
@@ -381,30 +395,33 @@
}
rotatingFileStream::~rotatingFileStream() {
- if (_file != NULL) {
- if (_need_close) fclose(_file);
- _file = NULL;
- FREE_C_HEAP_ARRAY(char, _file_name, mtInternal);
- _file_name = NULL;
+ if (_log_gen_ring_buffer != NULL) {
+ FREE_C_HEAP_ARRAY(char, _log_gen_ring_buffer, mtInternal);
}
}
-rotatingFileStream::rotatingFileStream(const char* file_name) {
+rotatingFileStream::rotatingFileStream(const char* file_name)
+ : fileStream(file_name)
+{
_cur_file_num = 0;
_bytes_writen = 0L;
- _file_name = NEW_C_HEAP_ARRAY(char, strlen(file_name)+10, mtInternal);
- jio_snprintf(_file_name, strlen(file_name)+10, "%s.%d", file_name, _cur_file_num);
- _file = fopen(_file_name, "w");
- _need_close = true;
+ _suffix_num = 0;
+ _log_gen_ring_buffer = NEW_C_HEAP_ARRAY(char,
+ NumberOfGCLogFiles * O_BUFLEN, mtInternal);
+ memset(_log_gen_ring_buffer, 0, NumberOfGCLogFiles * O_BUFLEN);
+ strncpy(_log_gen_ring_buffer, _opened_file, O_BUFLEN);
}
-rotatingFileStream::rotatingFileStream(const char* file_name, const char* opentype) {
+rotatingFileStream::rotatingFileStream(const char* file_name, const char* opentype)
+ : fileStream(file_name, opentype)
+{
_cur_file_num = 0;
_bytes_writen = 0L;
- _file_name = NEW_C_HEAP_ARRAY(char, strlen(file_name)+10, mtInternal);
- jio_snprintf(_file_name, strlen(file_name)+10, "%s.%d", file_name, _cur_file_num);
- _file = fopen(_file_name, opentype);
- _need_close = true;
+ _suffix_num = 0;
+ _log_gen_ring_buffer = NEW_C_HEAP_ARRAY(char,
+ NumberOfGCLogFiles * O_BUFLEN, mtInternal);
+ memset(_log_gen_ring_buffer, 0, NumberOfGCLogFiles * O_BUFLEN);
+ strncpy(_log_gen_ring_buffer, _opened_file, O_BUFLEN);
}
void rotatingFileStream::write(const char* s, size_t len) {
@@ -425,6 +442,11 @@
// concurrent GC threads to run parallel with VMThread at safepoint, write and rotate_log
// must be synchronized.
void rotatingFileStream::rotate_log() {
+
+ if(!_need_close){
+ return;
+ }
+
if (_bytes_writen < (jlong)GCLogFileSize) return;
#ifdef ASSERT
Thread *thread = Thread::current();
@@ -432,32 +454,63 @@
(thread->is_VM_thread() && SafepointSynchronize::is_at_safepoint()),
"Must be VMThread at safepoint");
#endif
+
+ _bytes_writen = 0L;
+
if (NumberOfGCLogFiles == 1) {
// rotate in same file
rewind();
- _bytes_writen = 0L;
return;
}
// rotate file in names file.0, file.1, file.2, ..., file.<MaxGCLogFileNumbers-1>
- // close current file, rotate to next file
- if (_file != NULL) {
- _cur_file_num ++;
- if (_cur_file_num >= NumberOfGCLogFiles) _cur_file_num = 0;
- jio_snprintf(_file_name, strlen(Arguments::gc_log_filename()) + 10, "%s.%d",
- Arguments::gc_log_filename(), _cur_file_num);
- fclose(_file);
- _file = NULL;
+
+ // delete oldest file and update _cur_file_num
+ char *oldest_filename = (++_cur_file_num < NumberOfGCLogFiles)
+ ? &_log_gen_ring_buffer[_cur_file_num * O_BUFLEN]
+ : &_log_gen_ring_buffer[0];
+
+
+ if(oldest_filename[0] != '\0'){
+ remove(oldest_filename);
}
- _file = fopen(_file_name, "w");
- if (_file != NULL) {
- _bytes_writen = 0L;
- _need_close = true;
- } else {
- tty->print_cr("failed to open rotation log file %s due to %s\n",
- _file_name, strerror(errno));
+
+ if(_cur_file_num == NumberOfGCLogFiles){
+ _cur_file_num = 0;
+ }
+
+ // Open new log file
+ char buf[O_BUFLEN];
+ FILE *tmp = NULL;
+
+ if(Arguments::copy_expand_parameter(
+ _file_name, strlen(_file_name), buf, O_BUFLEN, _suffix_num + 1)){
+ tmp = fopen(buf, "w");
+
+ if(tmp == NULL){
+ tty->print_cr("failed to open rotation log file %s due to %s\n",
+ buf, strerror(errno));
+ _need_close = false;
+ gclog_or_tty = tty;
+ }
+ else{
+ strncpy(oldest_filename, buf, O_BUFLEN);
+ _suffix_num++;
+ }
+
+ }
+ else{
+ tty->print_cr("failed to create new log file name %s\n", _file_name);
_need_close = false;
}
+
+
+ // close now file and swap new file
+ if(_file != NULL){
+ fclose(_file);
+ }
+
+ _file = tmp;
}
defaultStream* defaultStream::instance = NULL;
diff -r e3619706a725 src/share/vm/utilities/ostream.hpp
--- a/src/share/vm/utilities/ostream.hpp Mon Jul 23 12:38:08 2012 -0700
+++ b/src/share/vm/utilities/ostream.hpp Wed Jul 25 15:26:43 2012 +0900
@@ -28,6 +28,8 @@
#include "memory/allocation.hpp"
#include "runtime/timer.hpp"
+#define O_BUFLEN 2000 // max size of output of individual print() methods
+
// Output streams for printing
//
// Printing guidelines:
@@ -174,13 +176,15 @@
class fileStream : public outputStream {
protected:
+ char _file_name[O_BUFLEN];
+ char _opened_file[O_BUFLEN];
FILE* _file;
bool _need_close;
public:
fileStream() { _file = NULL; _need_close = false; }
fileStream(const char* file_name);
fileStream(const char* file_name, const char* opentype);
- fileStream(FILE* file) { _file = file; _need_close = false; }
+ fileStream(FILE* file) { _file_name[0] = '\0'; _opened_file[0] = '\0'; _file = file; _need_close = false; }
~fileStream();
bool is_open() const { return _file != NULL; }
void set_need_close(bool b) { _need_close = b;}
@@ -214,9 +218,10 @@
class rotatingFileStream : public fileStream {
protected:
- char* _file_name;
jlong _bytes_writen;
uintx _cur_file_num; // current logfile rotation number, from 0 to MaxGCLogFileNumbers-1
+ uintx _suffix_num; // logfile suffix number
+ char * _log_gen_ring_buffer;
public:
rotatingFileStream(const char* file_name);
rotatingFileStream(const char* file_name, const char* opentype);
@@ -271,8 +276,6 @@
char* as_string();
};
-#define O_BUFLEN 2000 // max size of output of individual print() methods
-
#ifndef PRODUCT
class networkStream : public bufferedStream {
diff -r e3619706a725 src/share/vm/utilities/vmError.cpp
--- a/src/share/vm/utilities/vmError.cpp Mon Jul 23 12:38:08 2012 -0700
+++ b/src/share/vm/utilities/vmError.cpp Wed Jul 25 15:26:43 2012 +0900
@@ -185,7 +185,7 @@
const char * cmdend = cmd;
while (*cmdend != '\0' && *cmdend != ';') cmdend++;
- Arguments::copy_expand_pid(cmd, cmdend - cmd, buf, buflen);
+ Arguments::copy_expand_parameter(cmd, cmdend - cmd, buf, buflen);
*ptr = (*cmdend == '\0' ? cmdend : cmdend + 1);
return buf;
@@ -913,7 +913,7 @@
if (ErrorFile != NULL) {
bool copy_ok =
- Arguments::copy_expand_pid(ErrorFile, strlen(ErrorFile), buffer, sizeof(buffer));
+ Arguments::copy_expand_parameter(ErrorFile, strlen(ErrorFile), buffer, sizeof(buffer));
if (copy_ok) {
fd = open(buffer, O_RDWR | O_CREAT | O_TRUNC, 0666);
}
More information about the hotspot-gc-dev
mailing list