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

Yasumasa Suenaga yasuenag at gmail.com
Sun Nov 15 12:51:03 UTC 2015 

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