RFR: JDK-8140556: Add force rotation option to VM.log jcmd
David Holmes
david.holmes at oracle.com
Wed Nov 4 07:34:21 UTC 2015
On 4/11/2015 12:45 AM, Yasumasa Suenaga wrote:
> David, Marcus,
>
>> I'm unclear of the context in which this could be called by an
>> unattached thread (ie during early VM initialization). Could you
>> clarify the code-path for me please? It seems an odd check to make on
>> all rotate() requests rather then doing something only in the
>> problematic case.
>
> I changed a little current implementation and built fastdebug.
Thanks, now I see the problem and don't have a better solution.
David
-----
> Changes:
> ------------------------
> diff -r 4338b5465f50 src/share/vm/logging/logFileOutput.cpp
> --- a/src/share/vm/logging/logFileOutput.cpp Fri Oct 30 12:36:54 2015
> +0100
> +++ b/src/share/vm/logging/logFileOutput.cpp Tue Nov 03 23:34:33 2015
> +0900
> @@ -123,7 +123,8 @@
> success = false;
> break;
> }
> - _rotate_size = value * K;
> + //_rotate_size = value * K;
> + _rotate_size = value;
> } else {
> success = false;
> break;
> @@ -155,12 +156,12 @@
> int written = LogFileStreamOutput::write(decorations, msg);
> _current_size += written;
>
> - if (should_rotate()) {
> +// if (should_rotate()) {
> MutexLockerEx ml(&_rotation_lock, true /* no safepoint check */);
> if (should_rotate()) {
> rotate();
> }
> - }
> +// }
>
> return written;
> }
> ------------------------
>
> Results: - from hs_err log
> ------------------------
> # A fatal error has been detected by the Java Runtime Environment:
> #
> # Internal Error
> (/home/ysuenaga/OpenJDK/hs-rt/hotspot/src/share/vm/runtime/thread.hpp:669),
> pid=61982, tid=61983
> # assert(thread != __null) failed: just checking
> :
> Command Line: -Xlog:all=trace:file.txt::filesize=10,filecount=2
> -Xlog:invalid
> :
> V [libjvm.so+0xeb6481] Monitor::lock_without_safepoint_check()+0xe1
> V [libjvm.so+0xd4c118] LogFileOutput::write(LogDecorations const&,
> char const*)+0x38
> V [libjvm.so+0xd4e5d0] LogTagSet::log(LogLevel::type, char const*)+0x60
> V [libjvm.so+0xd499b7] void Log<(LogTag::type)2, (LogTag::type)0,
> (LogTag::type)0, (LogTag::type)0, (LogTag::type)0,
> (LogTag::type)0>::vwrite<(LogLevel::type)6>(char const*,
> __va_list_tag*)+0x67
> V [libjvm.so+0xd49a5b] void Log<(LogTag::type)2, (LogTag::type)0,
> (LogTag::type)0, (LogTag::type)0, (LogTag::type)0,
> (LogTag::type)0>::write<(LogLevel::type)6>(char const*, ...)+0x8b
> V [libjvm.so+0xd49676]
> LogConfiguration::parse_command_line_arguments(char const*)+0x146
> V [libjvm.so+0x489530]
> Arguments::parse_each_vm_init_arg(JavaVMInitArgs const*, SysClassPath*,
> bool*, Flag::Flags)+0x1d40
> V [libjvm.so+0x48a354] Arguments::parse_vm_init_args(JavaVMInitArgs
> const*, JavaVMInitArgs const*, JavaVMInitArgs const*)+0x244
> V [libjvm.so+0x48c286] Arguments::parse(JavaVMInitArgs const*)+0xa46
> V [libjvm.so+0x1173052] Threads::create_vm(JavaVMInitArgs*, bool*)+0xb2
> V [libjvm.so+0xb502af] JNI_CreateJavaVM+0x8f
> C [libjli.so+0x72a3] JavaMain+0x83
> ------------------------
>
>
> LogConfiguration::parse_command_line_arguments() calls before
> initialization of main thread.
> So I think that Thread::current() returns NULL and crash at assert().
>
>
> Thanks,
>
> Yasumasa
>
>
> On 2015/11/03 14:37, David Holmes wrote:
>> On 2/11/2015 11:32 PM, 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.
>>
>> I'm unclear of the context in which this could be called by an
>> unattached thread (ie during early VM initialization). Could you
>> clarify the code-path for me please? It seems an odd check to make on
>> all rotate() requests rather then doing something only in the
>> problematic case.
>>
>> Note I am not reviewing this in general as I am not familiar with the
>> logging code, I am just commenting on the thread-safety issue.
>>
>> Thanks,
>> David
>>
>>>
>>> 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