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

Thu Nov 5 03:30:55 UTC 2015

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?

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