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

Mon Nov 2 13:32:44 UTC 2015

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
>>>>>>>>>>>
>>>>>>>>>
>>>>>>>
>>>>>
>>>