RFR: JDK-8140556: Add force rotation option to VM.log jcmd
Yasumasa Suenaga
yasuenag at gmail.com
Tue Nov 3 14:45:15 UTC 2015
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.
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 serviceability-dev
mailing list