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" <yasue...@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
