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

Yasumasa Suenaga yasuenag at gmail.com
Wed Nov 25 14:14:55 UTC 2015 

PING: Could you review it?
    http://cr.openjdk.java.net/~ysuenaga/JDK-8140556/webrev.04/

Yasumasa


On 2015/11/15 21:51, Yasumasa Suenaga wrote:
> PING: Could you review it?
>    http://cr.openjdk.java.net/~ysuenaga/JDK-8140556/webrev.04/
>
> Yasumasa
>
>
> On 2015/11/05 23:50, Yasumasa Suenaga wrote:
>>>> _post_initialized would be a more accurate name.
>>
>> I've fixed it in new webrev:
>>    http://cr.openjdk.java.net/~ysuenaga/JDK-8140556/webrev.04/
>>
>> I will send changeset to Marcus if this changeset is reviewed.
>>
>>
>> Thanks.
>>
>> Yasumasa
>>
>>
>> On 2015/11/05 23:38, Marcus Larsson wrote:
>>> 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
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>
>>>

More information about the hotspot-runtime-dev mailing list