RFR: JDK-8140556: Add force rotation option to VM.log jcmd

Thu Nov 5 14:38:49 UTC 2015

Hey,

On 2015-11-05 04:50, David Holmes wrote:
> On 5/11/2015 1:30 PM, Yasumasa Suenaga wrote:
>> I've uploaded new webrev:
>>    http://cr.openjdk.java.net/~ysuenaga/JDK-8140556/webrev.03/
>>
>> I added _initialized to LogConfiguration.
>> LogConfiguration::post_initialize() will be called after main thread
>> initialization.
>> So _initialized set to true in this function, and we can check this flag
>> at rotation.
>>
>> Could you review it?

Looks OK to me. This is much better than checking for Thread::current() 
!= NULL in is_rotatable(), IMHO.

>
> _post_initialized would be a more accurate name.
>
> This of course works, but I don't know whether the additional delay in 
> allowing rotation will impact anything.

It shouldn't. If anyone ever generates that much logging during startup 
they will have to accept that the first rotated log won't be properly 
sized, that's all.

Thanks,
Marcus

>
> Thanks,
> David
>
>>
>> Thanks,
>>
>> Yasumasa
>>
>>
>> On 2015/11/02 22:32, Yasumasa Suenaga wrote:
>>> Marcus, David,
>>>
>>> I've uploaded new webrev:
>>> http://cr.openjdk.java.net/~ysuenaga/JDK-8140556/webrev.02/
>>>
>>> Could you review it?
>>>
>>>
>>>>>>>> Still missing the renaming of rotate_all_logfile to
>>>>>>>> rotate_all_outputs.
>>>
>>> I've fixed.
>>>
>>>
>>>>>> Small typo, please make that is_rotatable().
>>>
>>> I've added, and have used at LogConfiguration::rotate_all_outputs().
>>>
>>>
>>>> You can't safely lock a mutex until the current thread has attached
>>>> to the VM and Thread::current() returns non-null (that is what
>>>> Thread::initialize_thread_local_storage() currently does). You may
>>>> get away with it, particularly in product builds, during VM
>>>> initialization, as the fast-lock path doesn't require access to
>>>> Thread::current().
>>>
>>> I will check whether Thread::current() is NULL or not at
>>> LogFileOutput::is_rotatable()
>>> is_rotatable() is called at LogFileOutput::rotate() before locking
>>> _rotation_lock.
>>> So we can avoid crash/assert which is related to TLS.
>>>
>>>
>>> Thanks,
>>>
>>> Yasumasa
>>>
>>>
>>> On 2015/11/02 11:11, David Holmes wrote:
>>>> On 1/11/2015 1:10 AM, Yasumasa Suenaga wrote:
>>>>>> This in turn means that we are logging before the thread local 
>>>>>> storage
>>>>>> has been initialized, and the JVM will crash/hit the assert 
>>>>>> because we
>>>>>> are trying to take the rotation lock.
>>>>>
>>>>> I guess that you are saying about class member (not TLS - e.g.
>>>>> pthread_setspecific()).
>>>>
>>>> You can't safely lock a mutex until the current thread has attached
>>>> to the VM and Thread::current() returns non-null (that is what
>>>> Thread::initialize_thread_local_storage() currently does). You may
>>>> get away with it, particularly in product builds, during VM
>>>> initialization, as the fast-lock path doesn't require access to
>>>> Thread::current().
>>>>
>>>> David
>>>>
>>>>> Most of fields (include _rotation_lock) in LogFileOutput are
>>>>> initialized
>>>>> at c'tor.
>>>>> Other field (_stream) is initialized at LogFileOutput::initialize().
>>>>>
>>>>> We can avoid problem if we can move initialize() to c'tor because
>>>>> LogFileOutput
>>>>> will be instantiated at LogConfiguration::new_output().
>>>>>
>>>>> Currently, LogFileOutput will be added to LogConfiguration::_outputs
>>>>> and
>>>>> to LogTagSet after calling LogFileOutput::initialize().
>>>>> I wonder why we cannot avoid crash/assert with current
>>>>> implementation...
>>>>>
>>>>>
>>>>> I will keep current implementation about _rotation_lock if the 
>>>>> above is
>>>>> incorrect.
>>>>>
>>>>>
>>>>> Thanks,
>>>>>
>>>>> Yasumasa
>>>>>
>>>>>
>>>>> On 2015/10/31 0:31, Marcus Larsson wrote:
>>>>>> Hey,
>>>>>>
>>>>>> On 2015-10-30 15:39, Yasumasa Suenaga wrote:
>>>>>>> Hi Marcus,
>>>>>>>
>>>>>>> Thank you for your comment.
>>>>>>>
>>>>>>>
>>>>>>>> Still missing the renaming of rotate_all_logfile to
>>>>>>>> rotate_all_outputs.
>>>>>>>
>>>>>>> Sorry, I will fix.
>>>>>>>
>>>>>>
>>>>>> Thanks!
>>>>>>
>>>>>>>
>>>>>>>> This rotate function works I guess, but it will probably need some
>>>>>>>> rework once there are other types of log outputs (rotate doesn't
>>>>>>>> make sense on all types of log outputs).
>>>>>>>
>>>>>>> I will add is_rotetable() to LogOutput as virtual function.
>>>>>>> This function return false (can not rotate) by default, return true
>>>>>>> if _file_count is
>>>>>>> greater than 0 in LogFileOutput.
>>>>>>>
>>>>>>> LogConfiguration::rotate_all_outputs() will rotate if this function
>>>>>>> returns true.
>>>>>>>
>>>>>>
>>>>>> Small typo, please make that is_rotatable().
>>>>>>
>>>>>>>
>>>>>>>> If we configure a rotated file output and then log something on 
>>>>>>>> that
>>>>>>>> output before thread local storage initialization is complete, we
>>>>>>>> will crash/hit an assert. The previous implementation avoided this
>>>>>>>> as long as no rotation was needed before this initialization was
>>>>>>>> complete. (This can be triggered using the following arguments
>>>>>>>> "-Xlog:all=trace:file.txt::filesize=10,filecount=2 -Xlog:invalid",
>>>>>>>> for example.)
>>>>>>>
>>>>>>> I do not think so.
>>>>>>> Each -Xlog option creates unique instance of LogOutput (and
>>>>>>> subclass).
>>>>>>> So they are isolated.
>>>>>>
>>>>>> My example includes a second (and intentionally incorrect) -Xlog
>>>>>> option only to trigger logging on the newly configured rotating
>>>>>> LogFileOutput. This will cause some logging about the invalid -Xlog
>>>>>> argument, and this logging happens during the argument parsing. This
>>>>>> in turn means that we are logging before the thread local storage 
>>>>>> has
>>>>>> been initialized, and the JVM will crash/hit the assert because 
>>>>>> we are
>>>>>> trying to take the rotation lock. This has nothing to do with
>>>>>> concurrent fprintfs or freopens, even if that is a problem.
>>>>>>
>>>>>>>
>>>>>>> However, we might have to rotate at safepoint.
>>>>>>
>>>>>> Doing stuff at a safepoint will not give us much in this case. There
>>>>>> are threads that continue execution through a safepoint, which means
>>>>>> we will see log calls being made even during this time.
>>>>>>
>>>>>>> Currently, LogOutput might be used by multiple threads 
>>>>>>> concurrently.
>>>>>>> If we rotate log when another thread is writing string to 
>>>>>>> output, we
>>>>>>> encounter unexpected behavior.
>>>>>>>
>>>>>>> LogFileOutput::rotate() uses freopen().
>>>>>>> LogFileStreamOutput::write() uses vfprintf() through jio_fprintf().
>>>>>>> freopen() and vfprintf() are not atomic.
>>>>>>
>>>>>> You're right. There seems to be an overlooked concurrency issue with
>>>>>> vfprintfs during freopen. I don't think we should resolve this as 
>>>>>> part
>>>>>> of this particular fix, so instead I'll create a separate issue for
>>>>>> it.
>>>>>>
>>>>>>>
>>>>>>> I think that cause of crash/assertion which you say is it.
>>>>>>> (GC log will be rotated at safepoint.)
>>>>>>>
>>>>>>
>>>>>> See my comment above for what crash/assert I'm talking about.
>>>>>>
>>>>>> Thanks,
>>>>>> Marcus
>>>>>>
>>>>>>>
>>>>>>> Thanks,
>>>>>>>
>>>>>>> Yasumasa
>>>>>>>
>>>>>>>
>>>>>>> On 2015/10/29 23:58, Marcus Larsson wrote:
>>>>>>>> Hi,
>>>>>>>>
>>>>>>>> On 2015-10-29 15:01, Yasumasa Suenaga wrote:
>>>>>>>>> Hi Marcus,
>>>>>>>>>
>>>>>>>>> Thank you for your comment.
>>>>>>>>>
>>>>>>>>>> I'll sponsor it.
>>>>>>>>>
>>>>>>>>> Thank you so much!
>>>>>>>>> I've uploaded new webrev:
>>>>>>>>>
>>>>>>>>> http://cr.openjdk.java.net/~ysuenaga/JDK-8140556/webrev.01/
>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>> Still missing the renaming of rotate_all_logfile to
>>>>>>>> rotate_all_outputs.
>>>>>>>>
>>>>>>>>>> logConfiguration.cpp/hpp:
>>>>>>>>>>
>>>>>>>>>> * I don't think we should rely on the archive_name or the 
>>>>>>>>>> output's
>>>>>>>>>> name to decide whether or not an output should be rotated. It
>>>>>>>>>> would be better to introduce an is_rotated() test function in
>>>>>>>>>> LogOutput that could be used here.
>>>>>>>>>>
>>>>>>>>>> * rotate_all_logfile() should be renamed to 
>>>>>>>>>> rotate_all_outputs().
>>>>>>>>>> Currently there are only LogFileOutputs (other than
>>>>>>>>>> stdout/stderr), but in the future there might be other types of
>>>>>>>>>> outputs so I prefer having a more general name.
>>>>>>>>>> Also, please use static_cast<LogFileOutput*> instead of the
>>>>>>>>>> C-style cast. (Additional logic will be required here once more
>>>>>>>>>> types of log outputs are added, but I don't think we need to 
>>>>>>>>>> worry
>>>>>>>>>> about this right now.)
>>>>>>>>>>
>>>>>>>>>> * Don't print an error if an output is not rotatable, since it's
>>>>>>>>>> not an error to have some log outputs rotated while others are
>>>>>>>>>> not. If you really want some traceability here I suggest adding
>>>>>>>>>> log messages on trace level, tagged with 'logging'.
>>>>>>>>>
>>>>>>>>> I added  LogOutput::rotate(bool) as virtual function.
>>>>>>>>> This function works nothing by default, but will rotate all 
>>>>>>>>> logs at
>>>>>>>>> LogFileOutput.
>>>>>>>>
>>>>>>>> This rotate function works I guess, but it will probably need some
>>>>>>>> rework once there are other types of log outputs (rotate doesn't
>>>>>>>> make sense on all types of log outputs).
>>>>>>>>
>>>>>>>>>
>>>>>>>>> If true is passed to this function, all files will be rotated.
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> logDiagnosticCommand.cpp/hpp:
>>>>>>>>>>
>>>>>>>>>> * I think the description could be improved to something like
>>>>>>>>>> "Lists current log configuration, enables/disables/configures a
>>>>>>>>>> log output, or disables/rotates all logs."
>>>>>>>>>>
>>>>>>>>>> * The rotate option description should clarify that all logs 
>>>>>>>>>> will
>>>>>>>>>> be rotated ("current log" is too ambiguous).
>>>>>>>>>
>>>>>>>>> I've fixed.
>>>>>>>>
>>>>>>>> Great, thanks!
>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> logFileOutput.cpp/hpp:
>>>>>>>>>>
>>>>>>>>>> * Moving the MutexLocker like this introduces a race condition
>>>>>>>>>> where a log might be rotated multiple times by different 
>>>>>>>>>> threads,
>>>>>>>>>> instead of just once.
>>>>>>>>>> Instead of making the rotate() function public and moving the
>>>>>>>>>> mutexlocker, I suggest adding something like a public
>>>>>>>>>> force_rotation() function that grabs the lock and calls the
>>>>>>>>>> private rotate().
>>>>>>>>>>
>>>>>>>>>> * Given the addition of is_rotated() in LogOutput, then
>>>>>>>>>> get_archive_name() should be removed.
>>>>>>>>>
>>>>>>>>> I moved MutexLocker and should_rotate() to rotate().
>>>>>>>>> I think this change can avoid race condition.
>>>>>>>>>
>>>>>>>>
>>>>>>>> There is a subtle problem with taking the lock to check if we 
>>>>>>>> should
>>>>>>>> rotate. If we configure a rotated file output and then log 
>>>>>>>> something
>>>>>>>> on that output before thread local storage initialization is
>>>>>>>> complete, we will crash/hit an assert. The previous implementation
>>>>>>>> avoided this as long as no rotation was needed before this
>>>>>>>> initialization was complete. (This can be triggered using the
>>>>>>>> following arguments
>>>>>>>> "-Xlog:all=trace:file.txt::filesize=10,filecount=2 -Xlog:invalid",
>>>>>>>> for example.)
>>>>>>>>
>>>>>>>> Thanks,
>>>>>>>> Marcus
>>>>>>>>
>>>>>>>>>
>>>>>>>>> Thanks,
>>>>>>>>>
>>>>>>>>> Yasumasa
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> On 2015/10/27 21:17, Marcus Larsson wrote:
>>>>>>>>>> Hi,
>>>>>>>>>>
>>>>>>>>>> On 2015-10-27 01:03, Yasumasa Suenaga wrote:
>>>>>>>>>>> Hi Marcus,
>>>>>>>>>>>
>>>>>>>>>>> Thank you for replying.
>>>>>>>>>>>
>>>>>>>>>>> I filed this feature to JBS and change subject of this email.
>>>>>>>>>>> Could you be a sponsor and review it?
>>>>>>>>>>
>>>>>>>>>> I'll sponsor it.
>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> http://cr.openjdk.java.net/~ysuenaga/JDK-8140556/webrev.00/
>>>>>>>>>>
>>>>>>>>>> logConfiguration.cpp/hpp:
>>>>>>>>>>
>>>>>>>>>> * I don't think we should rely on the archive_name or the 
>>>>>>>>>> output's
>>>>>>>>>> name to decide whether or not an output should be rotated. It
>>>>>>>>>> would be better to introduce an is_rotated() test function in
>>>>>>>>>> LogOutput that could be used here.
>>>>>>>>>>
>>>>>>>>>> * rotate_all_logfile() should be renamed to 
>>>>>>>>>> rotate_all_outputs().
>>>>>>>>>> Currently there are only LogFileOutputs (other than
>>>>>>>>>> stdout/stderr), but in the future there might be other types of
>>>>>>>>>> outputs so I prefer having a more general name.
>>>>>>>>>> Also, please use static_cast<LogFileOutput*> instead of the
>>>>>>>>>> C-style cast. (Additional logic will be required here once more
>>>>>>>>>> types of log outputs are added, but I don't think we need to 
>>>>>>>>>> worry
>>>>>>>>>> about this right now.)
>>>>>>>>>>
>>>>>>>>>> * Don't print an error if an output is not rotatable, since it's
>>>>>>>>>> not an error to have some log outputs rotated while others are
>>>>>>>>>> not. If you really want some traceability here I suggest adding
>>>>>>>>>> log messages on trace level, tagged with 'logging'.
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> logDiagnosticCommand.cpp/hpp:
>>>>>>>>>>
>>>>>>>>>> * I think the description could be improved to something like
>>>>>>>>>> "Lists current log configuration, enables/disables/configures a
>>>>>>>>>> log output, or disables/rotates all logs."
>>>>>>>>>>
>>>>>>>>>> * The rotate option description should clarify that all logs 
>>>>>>>>>> will
>>>>>>>>>> be rotated ("current log" is too ambiguous).
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> logFileOutput.cpp/hpp:
>>>>>>>>>>
>>>>>>>>>> * Moving the MutexLocker like this introduces a race condition
>>>>>>>>>> where a log might be rotated multiple times by different 
>>>>>>>>>> threads,
>>>>>>>>>> instead of just once.
>>>>>>>>>> Instead of making the rotate() function public and moving the
>>>>>>>>>> mutexlocker, I suggest adding something like a public
>>>>>>>>>> force_rotation() function that grabs the lock and calls the
>>>>>>>>>> private rotate().
>>>>>>>>>>
>>>>>>>>>> * Given the addition of is_rotated() in LogOutput, then
>>>>>>>>>> get_archive_name() should be removed.
>>>>>>>>>>
>>>>>>>>>> Thanks,
>>>>>>>>>> Marcus
>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> Thanks,
>>>>>>>>>>>
>>>>>>>>>>> Yasumasa
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> On 2015/10/26 18:56, Marcus Larsson wrote:
>>>>>>>>>>>> Hi,
>>>>>>>>>>>>
>>>>>>>>>>>> Sorry for my late reply.
>>>>>>>>>>>>
>>>>>>>>>>>> I think being able to force rotation via jcmd seems like a 
>>>>>>>>>>>> good
>>>>>>>>>>>> feature. Files are currently opened in append mode so it 
>>>>>>>>>>>> should
>>>>>>>>>>>> already be possible to use external log rotation tools by
>>>>>>>>>>>> copying and truncating the files. Still I think it would be 
>>>>>>>>>>>> nice
>>>>>>>>>>>> to provide the jcmd for rotation as well.
>>>>>>>>>>>>
>>>>>>>>>>>> I can see some small issues with the implementation, but we 
>>>>>>>>>>>> can
>>>>>>>>>>>> deal with that during the review.
>>>>>>>>>>>>
>>>>>>>>>>>> Thanks,
>>>>>>>>>>>> Marcus
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> On 2015-10-26 00:26, Yasumasa Suenaga wrote:
>>>>>>>>>>>>> Hi all,
>>>>>>>>>>>>>
>>>>>>>>>>>>> Have you ever seen my change?
>>>>>>>>>>>>> I (and my customers) need log rotation function via external
>>>>>>>>>>>>> tool.
>>>>>>>>>>>>>
>>>>>>>>>>>>> I want to merge it by Feature Complete.
>>>>>>>>>>>>>
>>>>>>>>>>>>> Thanks,
>>>>>>>>>>>>>
>>>>>>>>>>>>> Yasumasa
>>>>>>>>>>>>> 2015/10/16 22:55 "Yasumasa Suenaga" <yasuenag at gmail.com>:
>>>>>>>>>>>>>
>>>>>>>>>>>>>> Hi all,
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> I contributed JDK-7090324: gclog rotation via external tool
>>>>>>>>>>>>>> to be
>>>>>>>>>>>>>> synchronized with
>>>>>>>>>>>>>> logrotated tool on Linux.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> I think JEP 158 is in progress.
>>>>>>>>>>>>>> However, this JEP does not contain log rotation via external
>>>>>>>>>>>>>> tool in the
>>>>>>>>>>>>>> spec.
>>>>>>>>>>>>>> I want to rotate logs via jcmd in this JEP.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> I've updated a patch for it:
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> http://cr.openjdk.java.net/~ysuenaga/jvmlogging-logrotate/
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> This patch provides new option "rotate" in VM.log command.
>>>>>>>>>>>>>> If this change can be accepted, I will file it to JBS and 
>>>>>>>>>>>>>> send
>>>>>>>>>>>>>> RFR.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> Thanks,
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> Yasumasa
>>>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>
>>>>>>