Bug #77075 for Log-Dispatch-FileRotate: It's buggy

Wed May 09 05:13:59 2012 alessio.palma [...] buongiorno.com - Ticket created

Subject:

It's buggy

1) take tons of CPU cicle to log ( 2x the Appender File ) 2) under heavy load there are multiple rotations: -rw-r--r-- 1 jmr jmr 870255847 May 9 08:51 d..c_all.log -rw-r--r-- 1 jmr jmr 10201 May 8 23:59 d..c_all.log.1 <-- -rw-r--r-- 1 jmr jmr 10908 May 8 23:59 d..c_all.log.2 <-- -rw-rwxr--+ 1 jmr jmr 2047950874 May 9 08:49 d..c_all.log.3 log4perl.appender.LALL1 = Log::Dispatch::FileRotate log4perl.appender.LALL1.DatePattern = 0:0:0:1*23:59:59 log4perl.appender.LALL1.TZ = UTC log4perl.appender.LALL1.max = 9 log4perl.appender.LALL1.filename = /logs/.../d..c_all.log log4perl.appender.LALL1.umask = 0033 log4perl.appender.LALL1.mode = append log4perl.appender.LALL1.layout = Log::Log4perl::Layout::PatternLayout::Multiline log4perl.appender.LALL1.layout.ConversionPattern = %d{yyyy-MM-dd HH:mm:ss} %H APIDM[%P]: [%X{apiuser} %X{msisdn}] %m %n Please have a look. Logging runs at 60K/70K / sec

Thu Oct 06 12:51:18 2016 MSCHOUT [...] cpan.org - Correspondence added

Hi. Thanks for your report on Log::Dispatch::FileRotate I appologize for the delayed responses. I have recently obtained COMAINT on this module and am working to bring this module up to date and resolve the numerous issues reported over the years. On Wed May 09 05:13:59 2012, ozw wrote: Show quoted text

> 1) take tons of CPU cicle to log ( 2x the Appender File )

This doesn't really surprise me given that FileRotate does all of the following for every message logged: - obtains an lock on the logfile - stat()'s he logfile file handle multiple times - stat()'s the logfile filename to determine if the logfile was rotated out from underneath FileRotate (e.g.: by logrotate). Thats a lot of syscalls for every logged message. This does make FileRotate safer and avoid losing messages in some cases, but it is not without cost as you have discovered. I will be doing some work to try to improve performance in the near future (but without sacrificing the safety checks that FileRotate has) In the meantime, if you have not already discovered it, you might take a look at lighter-weight Log::Dispatch plugins such as Log::Dispatch::File::Stamped if thats appropriate for you. That plugin does not have any of these performance penalties. Show quoted text

> 2) under heavy load there are multiple rotations:

Looking through the code I *think* I know why this happens. If multiple processes or threads enter log_message at the same time, and time_to_rotate() returns true for both of them. Then a lock is obtained by one process on the log file, which causes the other thread/process to wait. The first thread/process will then rotate the log file and release the lock. Then the second process will continue, and rotate the file again, causing a duplicate rotation. Probably the best solution to fix this is to obtain the lock *FIRST* before calling time_to_rotate(). I'm working on a test case to reproduce this and hope to have a fix soon. -- Regards, Michael Schout

Thu Oct 06 12:51:18 2016 The RT System itself - Status changed from 'new' to 'open'

Thu Jul 27 14:42:47 2017 MSCHOUT [...] cpan.org - Correspondence added

On Wed May 09 05:13:59 2012, ozw wrote: Show quoted text

> 1) take tons of CPU cicle to log ( 2x the Appender File ) > 2) under heavy load there are multiple rotations:

Hi. I believe the "Multiple rotations" issue was caused by a race condition that has been fixed in v1.28, just released to CPAN. If you continue to see this with v1.28 or later please let me know. As for the CPU load issue, if that is truly an issue for you, you should look at lighter weight log appenders such as Log::Dispatch::File::Stamped. -- Regards, Michael Schout

Sat Aug 05 13:07:11 2017 MSCHOUT [...] cpan.org - Status changed from 'open' to 'resolved'