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

Thu Nov 5 14:50:08 UTC 2015

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