[prev in list] [next in list] [prev in thread] [next in thread] 

List:       openjdk-serviceability-dev
Subject:    Re: RFR: JDK-8140556: Add force rotation option to VM.log jcmd
From:       Yasumasa Suenaga <yasuenag () gmail ! com>
Date:       2015-10-31 15:10:52
Message-ID: 5634D9FC.6080502 () gmail ! com
[Download RAW message or body]

> 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()).

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


[prev in list] [next in list] [prev in thread] [next in thread]