JDK-7090324: gclog rotation via external tool

Thu Jan 30 03:12:51 PST 2014

Hi Staffan,

I've uploaded new webrev:
http://cr.openjdk.java.net/~ysuenaga/JDK-7090324/webrev.03/

On 2014/01/30 17:23, Staffan Larsen wrote:
> Would it be possible for the Diagnostic Command to output the location of the rotated log? When invoking the command it would be good to get some kind of feedback.

I changed rotate_log() to redirect messages to jcmd.
If GC.rotate_log is executed, we can get messages on jcmd console as below:
------------
$ jcmd 18976 GC.rotate_log
18976:
2014-01-30 19:59:39 GC log rotation request has been received. Saved as test.log.0
2014-01-30 19:59:39 GC log file created test.log.1
------------

> test/gc/7090324/Test7090324.java:
> - I think this needs to have the Oracle copyright notice as well.
> - Tests should now use descriptive names, not bug numbers: https://wiki.openjdk.java.net/display/HotSpot/Naming+HotSpot+JTReg+Tests
> - nits: lots of missing spaces before ‘{‘, and after ‘for’, ‘if’
> - line 47: you don’t need to clean up old files, jtreg will give you a fresh scratch directory to run in

I've fixed.
Could you review again?

Thanks,

Yasumasa

> /Staffan
>
>
>
> On 30 jan 2014, at 08:08, Yasumasa Suenaga<suenaga.yasumasa at lab.ntt.co.jp>  wrote:
>
>> Hi Erik, Staffan,
>>
>> I've uploaded new webrev. Could you review this ?
>> http://cr.openjdk.java.net/~ysuenaga/JDK-7090324/webrev.02/
>>
>> This patch includes fixes from comments of Staffan and Erik.
>>
>> And I created new test of this patch as Test7090324 .
>> This test works fine with jtreg.
>>
>>
>> Thanks,
>>
>> Yasumasa
>>
>> On 2014/01/30 0:55, Yasumasa Suenaga wrote:
>>> Hi Erik,
>>>
>>> On 2014/01/30 0:13, Erik Helin wrote:
>>>> Hi Yasumasa,
>>>>
>>>> (have to use HTML email to get a width of more than 78 chars, sorry)
>>>>
>>>> why did you change the code in arguments.cpp in the method check_gc_log_consistency?
>>>
>>> In current implementation, check_gclog_consistency() checks three parameters:
>>>
>>> - GC log filename
>>> - NumberOfGCLogFiles
>>> - GCLogFileSize
>>>
>>> My customer uses external trigger "ONLY" for rotating logs.
>>> If they want to do that, GCLogFileSize does not need.
>>>
>>>
>>>> Next, the gcLogFileStream::rotate_log method now does a lot of things.
>>>> Could you separate out the first block into a new method,
>>>> gcLogFileStream::should_rotate(bool force)?
>>>>
>>>> This was, the code would read:
>>>>
>>>>> bool gcLogFileStream::should_rotate(bool force) {
>>>>> return force || _bytes_writen>= GCLogFileSize;
>>>>> }
>>>>>
>>>>> void gcLogFileStream::rotate_log(bool force) {
>>>>> char time_msg[FILENAMEBUFLEN];
>>>>> char time_str[EXTRACHARLEN];
>>>>> char current_file_name[FILENAMEBUFLEN];
>>>>> char renamed_file_name[FILENAMEBUFLEN];
>>>>>
>>>>> if (!should_rotate(force)) {
>>>>> return;
>>>>> }
>>>>>
>>>>> ...
>>>>> }
>>>>
>>>> Could you please update your patch?
>>>
>>> I will do that.
>>>
>>>
>>>> There is a new empty line in the rotate_log method:
>>>>
>>>>> }
>>>>> +
>>>>> #ifdef ASSERT
>>>>
>>>> could you please remove it?
>>>
>>> I will do that.
>>>
>>>
>>>> The logging change in rotate_log uses a different kind of if/else syntax
>>>> than the rest of the file:
>>>>
>>>>> if (force) {
>>>>> ...
>>>>> }
>>>>> else {
>>>>> ...
>>>>> }
>>>>
>>>> The other if/else statements in the file uses:
>>>>
>>>>> if (cond) {
>>>>> ...
>>>>> } else {
>>>>> ...
>>>>> }
>>>>
>>>> Could you please update your change to use the same if/else syntax?
>>>
>>> I will do that.
>>>
>>>
>>>> This part of the change duplicates the code:
>>>>
>>>> + jio_snprintf(time_msg, sizeof(time_msg), "%s GC log rotation request has been received. Saved as %s\n",
>>>> + os::local_time_string((char *)time_str, sizeof(time_str)),
>>>> + renamed_file_name);
>>>> + }
>>>> + else {
>>>> + jio_snprintf(time_msg, sizeof(time_msg), "%s GC log file has reached the"
>>>> " maximum size. Saved as %s\n",
>>>> - os::local_time_string((char *)time_str, sizeof(time_str)),
>>>> + os::local_time_string((char *)time_str, sizeof(time_str)),
>>>> renamed_file_name);
>>>>
>>>> Could you instead just change the message, as in:
>>>>
>>>>> const char* msg = forced ? "%s GC log rotation request has been received. Saved as %s\n" :
>>>>> "%s GC log file has reached the maximum size. Saved as %s\n";
>>>>> jio_snprintf(msg, os::local_time_string((char *)time_str, sizeof(time_str)), renamed_file_name);
>>>
>>> I will do that.
>>>
>>>
>>>> The declaration of rotate_log in ostream.hpp still uses the old
>>>> variable name is_force, it should use force,
>>>> just as the definition.
>>>
>>> Sorry, I will fix it.
>>>
>>>
>>>> Finally, could you add a test that tests your change? Have a look at the other tests
>>>> in hotspot/test/gc to see how you can do it
>>>> (you might want to use some functionality from hotspot/test/testlibrary).
>>>
>>> I found three tests as following:
>>>
>>> [ysuenaga at xelvis test]$ find . -iname "*jcmd*"
>>> ./runtime/NMT/JcmdWithNMTDisabled.java
>>> ./runtime/NMT/JcmdScale.java
>>> ./gc/TestG1ZeroPGCTJcmdThreadPrint.java
>>>
>>> I understand that these tests checks output (stdout/stderr) with OutputAnalyzer.
>>> However, my patch affects target VM. So I guess current test cannot check
>>> that GC log rotation is succeeded.
>>>
>>> Should I make test which checks exit value of jcmd ?
>>>
>>>
>>> Thanks,
>>>
>>> Yasumasa
>>>
>>>> Thanks,
>>>> Erik
>>>>
>>>> On 2014-01-29 15:28, Yasumasa Suenaga wrote:
>>>>> Hi Staffan,
>>>>>
>>>>> Thank you for reviewing!
>>>>> I've uploaded new webrev.
>>>>> http://cr.openjdk.java.net/~ysuenaga/JDK-7090324/webrev.01/
>>>>>
>>>>> On 2014/01/29 20:56, Staffan Larsen wrote:
>>>>>> Yasumasa,
>>>>>>
>>>>>> src/share/vm/runtime/arguments.cpp
>>>>>> no comments
>>>>>>
>>>>>> src/share/vm/runtime/safepoint.cpp
>>>>>> I was surprised that gc log size was checked after each safe point. That seems an uneccssary burden to place on a safe point. Instead we should switch to a periodic task that checks the gc log size. However, this is unrelated to you patch, so please ignore for now.
>>>>>
>>>>> Agree.
>>>>> However, I think that PeriodicTask also is not appropriate for this.
>>>>>
>>>>> Size of GC log file is increased when GC is occurred.
>>>>> So I think rotate function should be called at entry of each GC events
>>>>> e.g. VM_GC_Operation::doit_prologue() etc...
>>>>>
>>>>>
>>>>>> src/share/vm/runtime/vm_operations.hpp
>>>>>> line 402: nit: missing space before {
>>>>>
>>>>> Fixed.
>>>>>
>>>>>
>>>>>> line 405: I think ‘force’ is a better name than ‘is_force’
>>>>>
>>>>> I removed "force" option from DCmd.
>>>>> So I removed this from VMOperation.
>>>>>
>>>>>
>>>>>> src/share/vm/services/diagnosticCommand.cpp
>>>>>> line 666: What does this do without the -force option? It looks to me that the non-force case will happen after each safe point (see above) and that there is no need to ever do this from a diagnostic command. Can we remove the option?
>>>>>
>>>>> Indeed.
>>>>> I removed "force" option.
>>>>>
>>>>>
>>>>>> line 677: “Target VM does not support GC log file rotation."
>>>>>
>>>>> Fixed.
>>>>>
>>>>>
>>>>>> nits: some missing spaces before ‘{' and after ‘if'
>>>>>
>>>>> Fixed.
>>>>>
>>>>>
>>>>>> src/share/vm/services/diagnosticCommand.hpp
>>>>>> I think RotateGCLogDCmd should require the “control” permission when executed via JMX, so please add:
>>>>>> static const JavaPermission permission() {
>>>>>> JavaPermission p = {"java.lang.management.ManagementPermission",
>>>>>> "control", NULL};
>>>>>> return p;
>>>>>> }
>>>>>
>>>>> Added.
>>>>>
>>>>>
>>>>>> line 394: Maybe “Force the GC log file to be rotated.” is a better description?
>>>>>
>>>>> Fixed.
>>>>>
>>>>>
>>>>>> src/share/vm/utilities/ostream.cpp
>>>>>> line 662: I think ‘force’ is a better name than ‘is_force’
>>>>>> line 668: The comment says exactly the same thing as the code so I think it can be skipped
>>>>>> line 671: “GC log file rotation occurs by external trigger ONLY."
>>>>>> line 675: "not need” ->  “no need”
>>>>>> line 718: "GC log rotation request has been received”
>>>>>
>>>>> Fixed them.
>>>>>
>>>>>
>>>>> Thanks,
>>>>>
>>>>> Yasumasa
>>>>>
>>>>>
>>>>>> src/share/vm/utilities/ostream.hpp
>>>>>> no comments
>>>>>>
>>>>>>
>>>>>> Thanks,
>>>>>> /Staffan
>>>>>>
>>>>>> On 24 jan 2014, at 14:50, Yasumasa Suenaga<yasu at ysfactory.dip.jp>  wrote:
>>>>>>
>>>>>>> Hi all,
>>>>>>>
>>>>>>> I've created webrev:
>>>>>>> http://cr.openjdk.java.net/~ysuenaga/JDK-7090324/webrev.00/
>>>>>>>
>>>>>>> This patch works fine on current jdk9/hs-rt .
>>>>>>> Could you review this?
>>>>>>>
>>>>>>>
>>>>>>> I am just an Author. So I need a sponsor.
>>>>>>> Could you help me?
>>>>>>>
>>>>>>>
>>>>>>> Please cooperate.
>>>>>>>
>>>>>>>
>>>>>>> Thanks,
>>>>>>>
>>>>>>> Yasumasa
>>>>>>>
>>>>>>>
>>>>>>> On 2013/12/06 0:05, Yasumasa Suenaga wrote:
>>>>>>>> Hi all,
>>>>>>>>
>>>>>>>> Did someone read my email?
>>>>>>>> I really hope to merge "JDK-7090324: gclog rotation via external tool" .
>>>>>>>>
>>>>>>>> I hear that someone need this RFE. So I want to discuss about this.
>>>>>>>>
>>>>>>>>
>>>>>>>> Thanks,
>>>>>>>>
>>>>>>>> Yasumasa
>>>>>>>>
>>>>>>>> On 2013/11/08 21:47, Yasumasa Suenaga wrote:
>>>>>>>>> Hi all,
>>>>>>>>>
>>>>>>>>> Did someone read my mail?
>>>>>>>>>
>>>>>>>>> I think that this RFE helps us to watch Java heap on production system.
>>>>>>>>> Also I think this RFE is able to be part of the JEP 158 (Unified JVM Logging) .
>>>>>>>>>
>>>>>>>>> I want to update this RFE in JDK Bug System, but I don't have account.
>>>>>>>>> So I've posted email at first.
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> Thanks,
>>>>>>>>>
>>>>>>>>> Yasumasa
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> On 2013/09/30 21:10, Yasumasa Suenaga wrote:
>>>>>>>>>> In previous email, I've attached new patch for this RFE.
>>>>>>>>>> It works fine with current hsx.
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> Yasumasa
>>>>>>>>>>
>>>>>>>>>> On 2013/09/29 23:40, Yasu wrote:
>>>>>>>>>>> Hi all,
>>>>>>>>>>>
>>>>>>>>>>> We are using "logrotate" tool on RHEL for various log rotation.
>>>>>>>>>>> Current HotSpot has gclog rotation function for log size base,
>>>>>>>>>>> however I need to rotate gc log synchronizing with logrotate tool.
>>>>>>>>>>>
>>>>>>>>>>> So I've created RFE as "JDK-7090324: gclog rotation via external tool" .
>>>>>>>>>>> And Sr. Engineering Manager in Oracle said he use the essence of my patch in one
>>>>>>>>>>> of the jcmd subcommands.
>>>>>>>>>>> http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/2011-September/003274.html
>>>>>>>>>>>
>>>>>>>>>>> 2 years ago, I posted a patch for this RFE.
>>>>>>>>>>> But this patch is too old to apply for current HotSpot.
>>>>>>>>>>>
>>>>>>>>>>> In last month, a similar discussion was appeared in ML.
>>>>>>>>>>> So I think it's time to discuss this RFE.
>>>>>>>>>>> http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/2013-August/008029.html
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> Please cooperate.
>>>>>>>>>>>
>>>>>>>>>>> Best regards,
>>>>>>>>>>> Yasumasa
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>
>>>>>
>>>>
>