OpenQA::Log: Optimize, fix time format and simplify #4248
Conversation
|
Updated: Fixed "Too few arguments for subroutine 'OpenQA::Log::setup_log' at /home/squamata/project/lib/OpenQA/WebAPI.pm line 55" |
doesn't look like. maybe you forgot to commit something? |
okurz
force-pushed
the
feature/log
branch
2 times, most recently
from
a4c69fd
to
f4f6744
Compare
Based on local test results.
Based on local test results.
okurz
force-pushed
the
feature/log
branch
2 times, most recently
from
3e1db10
to
5dc605a
Compare
After finding many more alternatives which are all bad or worse I found https://metacpan.org/pod/Time::Moment which is already in Factory and Leap and shows a 43% improvement vs. our current solution and looks much cleaner ``` Rate Mojo::Log 35714/s print with localtime+Time::Piece->strftime 62500/s print with localtime 83333/s print with gmtime 83333/s print with gettimeofday+localtime 100000/s print with Time::Moment 142857/s plain print 333333/s ``` http://blogs.perl.org/users/chansen/2014/08/timemoment-vs-datetime.html also explains how Time::Moment can provide better performance Also I found out that the timestamp that is generated in os-autoinst and openQA is incorrect. There is `%%04d` filled with the calculation result of `1000 * ($time - int($time))` meaning the milliseconds of current time but with a leading zero leading to values like `.0513` which should be `.513`. Code sample to check: ``` use Time::HiRes 'gettimeofday'; use POSIX 'strftime'; $time = gettimeofday; printf(sprintf(strftime("[%FT%T.%%04d %Z]", localtime($time)), 1000 * ($time - int($time))) . " " . Time::Moment->now); ``` this for example outputs: ``` [2021-10-03T20:46:57.0513 CEST] [] 2021-10-03T20:46:57.513202+02:00 ``` See the difference `.0513` vs. `.513202`. So this commit now uses Time::Moment for the custom log callback which is better than both the previous version as well as the default format from Mojo::Log. Complete script used for benchmarking and comparing different solutions: ``` use strictures; use Time::HiRes 'gettimeofday'; use POSIX 'strftime'; use Benchmark qw(:all); use Mojo::Log; my $level = 'debug'; my $fixed_time = gettimeofday; my $log = Mojo::Log->new; my $results = timethese($ENV{RUNS} // 10000, { 'plain print' => sub { printf("[2021-09-28T13:45:08.0461 CEST] [debug]\n") }, 'print with gettimeofday+localtime' => sub { my $time = gettimeofday; printf(sprintf(strftime("[%FT%T.%%04d %Z] [$level] ", localtime($time)), 1000 * ($time - int($time))) . "\n")}, 'print with localtime' => sub { printf(sprintf(strftime("[%FT%T.%%04d %Z] [$level] ", localtime($fixed_time)), 1000 * ($fixed_time - int($fixed_time))) . "\n")}, 'print with gmtime' => sub { printf(sprintf(strftime("[%FT%T.%%04d %Z] [$level] ", gmtime($fixed_time)), 1000 * ($fixed_time - int($fixed_time))) . "\n")}, 'print with localtime+Time::Piece->strftime' => sub { use Time::Piece; printf(sprintf(localtime($fixed_time)->strftime("[%FT%T.%%04d %Z] [$level] "), 1000 * ($fixed_time - int($fixed_time))) . "\n")}, 'print with Time::Moment' => sub { use Time::Moment; printf("[" . Time::Moment->now->with_precision(3) . "] [$level] \n")}, 'Mojo::Log' => sub { $log->debug() }, }); cmpthese($results); 1; ``` Related progress issue: https://progress.opensuse.org/issues/99426
Codecov Report
@@ Coverage Diff @@
## master #4248 +/- ##
==========================================
- Coverage 97.92% 97.92% -0.01%
==========================================
Files 369 369
Lines 33435 33428 -7
==========================================
- Hits 32742 32735 -7
Misses 693 693
Continue to review full report at Codecov.
|
|
oops, I should have asked you if you agree with my later change which is introducing the use of Time::Moment. I would still welcome your feedback after the fact now |
I had only seen the proof of concept with even worse performance before, So I'm kind of amazed you found an alternative afterall 🤓️ Neither the blog post nor the docs tell me why |
These are only remotely related because after some longer times I ran all openQA tests locally finding these failing. I would say has nothing to do with logging. |
okurz
changed the title
See individual commit messages for details.
See: https://progress.opensuse.org/issues/99426