Can the performance be increased

[ufobat]

I've Added Log::Any to Bailador. unfortunatelly the test cases increased quite a bit:

with logging
Files=33, Tests=1223, 68 wallclock secs ( 0.38 usr 0.05 sys + 53.90 cusr 1.89 csys = 56.22 CPU)
without:
Files=33, Tests=1223, 42 wallclock secs ( 0.35 usr 0.03 sys + 28.52 cusr 1.42 csys = 30.32 CPU)

I was wondering if you could think of something that could improve the performance.

I guess that this is the place why it is slow in bailador: https://github.com/jsimonet/log-any/blob/master/lib/Log/Any/Filter.pm6#L20-L22 maybe this calculation could be cached?

[jsimonet]

I'll check what it's slow. I think it's possible to cache filters values.
I tried to run tests without logging, but they don't pass anymore. How could I disable logging in Bailador ?

Is it possible to use the asynchronous logging method ? It should accelerate the logging phase.

[ufobat]

what i did was running tests on the commit before and after i've added Log::Any.

Yesterday I tried to profile Bailadors "t/03*" test. I figured out that most of the time gets lost in SETTINGS::src/core/Lock.pm. So it is threads (e.g Channel, Promise, ..) related?

I figured out that passing (or leaving ) :category() parameter makes a increase of 6sec to the testcase. This is still round about 6sec longer compared to no logging at all.

[ufobat]

i am afraid if i swich to async logging it locks even more, but we could give it a try, what do i need to to?

[jsimonet]

Ok, I'll test with 439de4cc383f5d1c6ea1778e93d2f24d1cff75be.

It should not use Channel nor Promise. They are used for the asynchronous part.

You can use Log::Any.add( Log::Any::Pipeline.new( :asynchronous ), :overwrite ); before adding the adapters.
The idea is to push the message to a Channel, which will be consumed by another thread so it should not block Bailador's one. Filters, formatters and handlers are computed in the "log" thread.

[ufobat]

thats the different things i did in /lib/Bailador/App.pm.
( i am quite surprised that the category doesnt really matter. i must did something wrong yesterday, or it was in combination with perl6 --profile, i dont know :/
i am sorry for that! )

@@ -43,6 +43,7 @@ class Bailador::App is Bailador::Route {
         # probably a good place for a hook
         my $formatter = $.config.log-format;
         my @filter    = $.config.log-filter;
->>       Log::Any.add( Log::Any::Pipeline.new( :asynchronous ), :overwrite );
         Log::Any.add($.log-adapter, :$formatter, :@filter);
     }
@@ -150,7 +150,8 @@ class Bailador::App is Bailador::Route {
 
             LEAVE {
                 my $http-code = self.response.code;
->>                Log::Any.warning("Serving $method $uri with $http-code");
->>                Log::Any.warning("Serving $method $uri with $http-code", :category("Bailador::App"));
                 self!done-rendering();
             }

no log at all:

perl6 -Ilib t/03-response-content.t  18,54s user 0,42s system 95% cpu 19,956 total
perl6 -Ilib t/03-response-content.t  17,67s user 0,30s system 96% cpu 18,544 total
perl6 -Ilib t/03-response-content.t  17,70s user 0,28s system 97% cpu 18,529 total

log with category

perl6 -Ilib t/03-response-content.t  26,80s user 0,37s system 96% cpu 28,043 total
perl6 -Ilib t/03-response-content.t  26,91s user 0,39s system 96% cpu 28,385 total
perl6 -Ilib t/03-response-content.t  26,50s user 0,39s system 96% cpu 27,784 total

log without category

perl6 -Ilib t/03-response-content.t  28,91s user 0,39s system 96% cpu 30,269 total
perl6 -Ilib t/03-response-content.t  28,73s user 0,43s system 96% cpu 30,063 total
perl6 -Ilib t/03-response-content.t  28,31s user 0,40s system 96% cpu 29,660 total

with: Log::Any.add( Log::Any::Pipeline.new( :asynchronous ), :overwrite ); && without category

perl6 -Ilib t/03-response-content.t  34,46s user 0,55s system 122% cpu 28,503 total
perl6 -Ilib t/03-response-content.t  35,20s user 0,57s system 123% cpu 28,918 total
perl6 -Ilib t/03-response-content.t  36,71s user 0,54s system 121% cpu 30,738 total

[jsimonet]

Hello,

while working on performance improvements, I found that adding Log::Any.add( Log::Any::Pipeline.new(), :overwrite ); in lib/Bailador/App.pm in before-run() method improves greatly the performances.

The problem is: I don't know why… It should not to change anything since this method is just replacing the pipeline with a new one which is identical.

#Without the new pipeline
$ PERL6LIB=lib/ prove -e 'perl6' t/03-response-content.t
t/03-response-content.t .. ok       
All tests successful.
Files=1, Tests=498, 31 wallclock secs ( 0.18 usr  0.02 sys + 30.33 cusr  0.29 csys = 30.82 CPU)
Result: PASS

# With the new pipeline:
$ PERL6LIB=lib/ prove -e 'perl6' t/03-response-content.t
t/03-response-content.t .. ok       
All tests successful.
Files=1, Tests=498, 22 wallclock secs ( 0.16 usr  0.02 sys + 21.24 cusr  0.31 csys = 21.73 CPU)
Result: PASS

According to the profiles I ran with perl6 --profile, the time is mostly consumed in DateTime.new and Backtrace generation, I'm writing some code to allow disabling them if not needed.

[ufobat]

i can confirm this:

Files=39, Tests=1642, 128 wallclock secs ( 0.45 usr 0.08 sys + 105.48 cusr 3.60 csys = 109.61 CPU)
Files=39, Tests=1642, 126 wallclock secs ( 0.46 usr 0.07 sys + 102.82 cusr 4.04 csys = 107.39 CPU)

=>

Files=39, Tests=1642, 94 wallclock secs ( 0.42 usr 0.06 sys + 72.68 cusr 3.56 csys = 76.72 CPU)
Files=39, Tests=1642, 92 wallclock secs ( 0.42 usr 0.07 sys + 70.36 cusr 3.37 csys = 74.22 CPU)