RFR: 7164841: Improvements to the GC log file rotation

STIRLING, SCOTT ss4766 at att.com
Wed Aug 28 06:53:18 PDT 2013


As to why (i.e., append to a gc log across process restarts) and can GC tools tolerate logs with multiple JVM histories?

Mainly, appending new history to log file is simple for preserving history, and for text processing and correlating log data later. It's relatively easy to detect where one GC history starts or ends in the same file by the default elapsed time stamp in the GC entries, or by the new date stamp and time stamp options.

The IBM JVM logs are XML of course, and can contain multiple JVM process histories, appending across restarts.

Scott S

On Aug 28, 2013, at 7:16 AM, "STIRLING, SCOTT" <ss4766 at att.com> wrote:

> Always clobbers the last gc log *on JVM restart*, I should say. It's the JVM restart issue where there's no simple way via the JVM to just append to the last GC log if the file exists vs clobber it.
> 
> Scott
> 
> On Aug 28, 2013, at 7:13 AM, "STIRLING, SCOTT" <ss4766 at att.com> wrote:
> 
>> Append vs clobber: with or without rotation, -Xloggc always clobbers the last log. That's why people want a time stamp or pid in the gc file name, IMHO.
>> 
>> Alternatively, give an option to append when -Xloggc is enabled, vs default overwrite.
>> 
>> Kind regards,
>> 
>> Scott Stirling
>> AT&T, Boston
>> 
>> On Aug 27, 2013, at 1:14 PM, "Tao Mao" <tao.mao at oracle.com> wrote:
>> 
>>> 
>>> 
>>> On 8/27/13 1:01 AM, Bengt Rutisson wrote:
>>>> 
>>>> Yumin,
>>>> 
>>>> On 8/26/13 7:01 PM, Yumin Qi wrote:
>>>>> Bengt,
>>>>> 
>>>>> Thanks for your comments.
>>>>> Yes, as you said, the purpose of rotating logs is primarily targeted for saving disk space. This bug is supplying  customers another option to prevent the previous gc logs from removed by restart app without making copy. Now with this pid and time stamp included in file name,  we have more options for users. It is up to user to make decision to or not to keep the logs. We cannot handle all the requests in JVM, but we can offer the choices for users I think. Any way, with either the previous rotating version, or the one I am working, the logs will not grow constantly without limit to blow storage out as long as users give enough attention.
>>>>> 
>>>>> My concern is for no log rotation, should we still use time stamp in file name? I have one version for this, I hope get more comments for that.
>>>> 
>>>> Sorry if I wasn't clear before. I am not worried about the case when log rotation is turned on. What I was worried about was the case where a user is not using log rotation but is still piping the GC output to a file. That file will be overwritten every time the VM is restarted. If we add time stamps to the file name for this case then the file will not be overwritten. I think that is a bit of a scary change. That's all.
>>> 
>>> If you are worried about the case where a user is not using log rotation but creating a new file for each restart, you should be almost equivalently worried about the case where a user is using log rotation and having many rotated logs created which are different for each VM restart. Basically, we are creating even more files over time, which falls into your concern.
>>> 
>>> At this point, I'm fine with either choice for they have pros and cons. If we always append date and time to log file names, customers may say "the logs are 'eating' my disk"; if you don't do that, the customers would still complain the log is overwritten after a restart (I saw these kinds of CR's twice).
>>> 
>>> Thanks.
>>> Tao
>>> 
>>>> 
>>>> Bengt
>>>> 
>>>>> 
>>>>> More comments are appreciated by sending to more wide audience, especially sustaining, they have more experience with customer request.
>>>>> 
>>>>> Thanks
>>>>> Yumin
>>>>> 
>>>>> 
>>>>> 
>>>>> On 8/26/2013 4:47 AM, Bengt Rutisson wrote:
>>>>>> 
>>>>>> Hi Yumin and Tao,
>>>>>> 
>>>>>> I have not reviewed the code change but I have a comment inlined below.
>>>>>> 
>>>>>> On 8/24/13 1:05 AM, Yumin Qi wrote:
>>>>>>> Tao,
>>>>>>> 
>>>>>>> Thanks for your review.
>>>>>>> 
>>>>>>> On 8/23/2013 3:33 PM, Tao Mao wrote:
>>>>>>>> Hi,
>>>>>>>> 
>>>>>>>> I reviewed most of the code and test-ran a build from it. It's a very cool and important improvement.
>>>>>>>> 
>>>>>>>> Thank you for putting together these on our wishlist for long.
>>>>>>>> 
>>>>>>>> Below are some comments.
>>>>>>>> 
>>>>>>>> 1. src/share/vm/runtime/arguments.cpp
>>>>>>>> 
>>>>>>>> - 1853 "To enable GC log rotation, use -Xloggc:<filename> -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=<num_of_files> -XX:GCLogFileSize=<num_of_size>[k|K|m|M]\n"
>>>>>>>> + 1853 "To enable GC log rotation, use -Xloggc:<filename> -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=<num_of_files> -XX:GCLogFileSize=<num_of_size>[k|K|m|M|g|G]\n"
>>>>>>>> 
>>>>>>>> Please consider adding [g|G] to GCLogFileSize suggestion.
>>>>>>>> 
>>>>>>>> I worked on a problem of enabling gc log limit over 2G (JDK-7122222). So it seems that customers sometimes want gc logs to be very large.
>>>>>>> Sure, will add.
>>>>>>>> 2. src/share/vm/runtime/arguments.hpp
>>>>>>>> 
>>>>>>>> (1) with the current changeset, we only append date&time to file_name w/ +UseGCLogFileRotation; if not, we won't have date&time info.
>>>>>>>> 
>>>>>>>> I think it would be useful to let both cases (w/ and w/o UseGCLogFileRotation) have date&time in order to solve the overwritten problem (e.g. JDK-8020667). In fact, having that, we actually solve JDK-8020667.
>>>>>>>> 
>>>>>>>> If you want to have that, basically you need to work on the FileStream constructor methods fileStream().
>>>>>>> I can change that, if no objection from others. This also will simplify the setting of file name here.
>>>>>> 
>>>>>> I think appending a timestamp to the log file name is a nice idea, but I think it is also a bit scary. There are users who restart their applications regularly. With the suggested idea such users will now risk filling up their disk space with log files. I imagine that that will not be appreciated by everyone. Such a change should probably be discussed more thoroughly than just in a review request.
>>>>>> 
>>>>>> Thanks,
>>>>>> Bengt
>>>>>> 
>>>>>> 
>>>>>>> 
>>>>>>>> (2) Would it be better to rename method name reformat_filename() to extend_filename()?
>>>>>>>> 
>>>>>>>> (3) Typos and suggestion
>>>>>>>> 537 // rotate file in names filename.0, filename.1, ..., filename.<NumberOfGCLogFiles - 1>
>>>>>>>> *=> extended_filename.0*
>>>>>>>> 
>>>>>>>> 538 // filename contains pid and time when the fist file created. The current filename is
>>>>>>>> *=> *the*first *file created.
>>>>>>>> 
>>>>>>>> 539 // gc_log_file_name + pid<pid> + YYYY-MM-DD_HH-MM-SS.<i>.current, where i is current
>>>>>>>> 540 // rotation file number. After it reaches max file size, the file will be saved and
>>>>>>>> 541 // renamed with .current removed from its tail.
>>>>>>> Will change that.
>>>>>>>> 3. For your point 5), I don't quite get it. In my test-run, I tried to change file permission to unreadable and unwritable, but VM would later change the permission back anyway.
>>>>>>>> 
>>>>>>>> So could you bring up some use cases of that functionality to give more details?
>>>>>>> Changing file permission will not stop the file create, in this rotation, the file opened/saved/removed/renamed -> then repeat. What I have done is change the while directory to read only, then the create failed so rotation stopped.
>>>>>>> 
>>>>>>>> 4. Will you write jtreg tests for this functionality? It looks possible to write some tests, at least checking the format of log names.
>>>>>>> Good suggestion, I will add one.
>>>>>>> 
>>>>>>>> Thanks.
>>>>>>>> Tao
>>>>>>>> 
>>>>>>>> On 8/23/13 7:53 AM, Yumin Qi wrote:
>>>>>>>>> Could I get  a GC staff review the change? Need more reviewers to push this in.
>>>>>>>>> 
>>>>>>>>> Thanks
>>>>>>>>> Yumin
>>>>>>>>> 
>>>>>>>>> On 8/21/2013 3:43 PM, Yumin Qi wrote:
>>>>>>>>>> Hi, all
>>>>>>>>>> 
>>>>>>>>>> This is second version after feedback from first round.
>>>>>>>>>> The changes are:
>>>>>>>>>> 
>>>>>>>>>> 1) file name will be based on gc log file name (-Xloggc:filename), pid (process id) and time when the first rotation file created:
>>>>>>>>>> <filename>-pid<pid>-YYYY-MM-DD_HH-MM-SS
>>>>>>>>>> 2) If rotate in same file, file name is as in 1), if rotate in multiple files, .<i> will append to above file name.
>>>>>>>>>> 3) every time file rotated, file name and time when file created will be logged to head/tail, this is same as first version.
>>>>>>>>>> 4) current file has name <filename>-pid<pid>-YYYY-MM-DD_HH-MM-SS.<i>.current
>>>>>>>>>>     This is similar to first version.
>>>>>>>>>>     By adapting such name format we will never loss logs in case apps stops and restart, the log files will not be overwritten since time stamp in file names.
>>>>>>>>>> 5) If open file failed, turn off gc log rotation.
>>>>>>>>>>      If due to some reason, file operation failed (such as permission changed etc), with log file opened, logging still works, but at
>>>>>>>>>>      saving and renaming, the file operation will fail, this will lead not all files saved.
>>>>>>>>>> 
>>>>>>>>>> http://cr.openjdk.java.net/~minqi/7164841/webrev01
>>>>>>>>>> 
>>>>>>>>>>   Tested with jtreg, JPRT.
>>>>>>>>>> 
>>>>>>>>>> Thanks
>>>>>>>>>> Yumin
>>>>>>>>>> 
>>>>>>>>>> On 8/15/2013 8:35 AM, Yumin Qi wrote:
>>>>>>>>>>> Hi,
>>>>>>>>>>> 
>>>>>>>>>>> Can I have your review for this small changes?
>>>>>>>>>>> http://cr.openjdk.java.net/~minqi/7164841/webrev00/ <http://cr.openjdk.java.net/%7Eminqi/7164841/webrev00/>
>>>>>>>>>>> 
>>>>>>>>>>> This is for a enhancement to add head/tail message to the logging files to assist reading GC output.
>>>>>>>>>>> 1. modified prompt message if invalid arguments used for log rotating;
>>>>>>>>>>> 2. add time and file name message to log file head/tail.
>>>>>>>>>>> 3. for easily identify which log file is current, use file name like <filename>.n.current, after it reaches maximum size, rename it to <filename>.n
>>>>>>>>>>>      On Windows, there is no F_OK (existing test) definition, F_OK is defined as "0" and for _access of VC++, it just describes:
>>>>>>>>>>> 
>>>>>>>>>>> modevalue
>>>>>>>>>>> 
>>>>>>>>>>> 
>>>>>>>>>>> 
>>>>>>>>>>> Checks file for
>>>>>>>>>>> 
>>>>>>>>>>> 00
>>>>>>>>>>> 
>>>>>>>>>>> 
>>>>>>>>>>> 
>>>>>>>>>>> Existence only
>>>>>>>>>>> 
>>>>>>>>>>> 02
>>>>>>>>>>> 
>>>>>>>>>>> 
>>>>>>>>>>> 
>>>>>>>>>>> Write-only
>>>>>>>>>>> 
>>>>>>>>>>> 04
>>>>>>>>>>> 
>>>>>>>>>>> 
>>>>>>>>>>> 
>>>>>>>>>>> Read-only
>>>>>>>>>>> 
>>>>>>>>>>> 06
>>>>>>>>>>> 
>>>>>>>>>>> 
>>>>>>>>>>> 
>>>>>>>>>>> Read and write
>>>>>>>>>>> 
>>>>>>>>>>> 
>>>>>>>>>>> http://msdn.microsoft.com/en-us/library/1w06ktdy.aspx
>>>>>>>>>>> The definition are consistent with unistd.h.
>>>>>>>>>>> 
>>>>>>>>>>>  Test: JPRT and jtreg.
>>>>>>>>>>> 
>>>>>>>>>>> Thanks
>>>>>>>>>>> Yumin
>>>> 


More information about the hotspot-runtime-dev mailing list