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

[David Holmes]

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