https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 Jesse Weaver <jweaver@bywatersolutions.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Patch complexity|--- |Small patch Status|ASSIGNED |Needs Signoff -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 --- Comment #2 from Jesse Weaver <jweaver@bywatersolutions.com> --- Created attachment 49488 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=49488&action=edit Bug 16140: don't clone cache results for framework/authvals This is needed so as not to cancel out the performance gains of the L1 cache. -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 Tomás Cohen Arazi <tomascohen@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |tomascohen@gmail.com --- Comment #3 from Tomás Cohen Arazi <tomascohen@gmail.com> --- Are we sure it doesn't cost more to calculate the invalidated-status than to retrieve the data on each request? -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 --- Comment #5 from Jonathan Druart <jonathan.druart@bugs.koha-community.org> --- Quick benchmarks: % more /dev/null > /tmp/time; % export KOHA_INTRANET_URL=http://pro.koha-qa.vm % for i in {1..10}; do {time perl test.t > /dev/null} 2>> /tmp/time;done; echo $((`perl -pe 's/.*cpu ([^s]*) total/$1/' /tmp/time| tr '\n' '+'|sed 's/+$//'`)) # Before 16044 git reset --hard ffb17a2914c43e536155856a86fed374b7f26e9c # just before 16044 71.23 (7.389+6.932+6.966+6.937+6.941+6.663+7.827+7.237+7.075+7.259) # After 16044 git reset --hard origin/master # + last patch on 16044 72.09 6.881+7.236+8.261+7.005+7.975+6.909+6.816+6.860+7.043+7.100+% # With 16140 git bz apply 16140 63.60 (6.952+7.158+6.481+6.424+6.428+6.338+6.003+6.034+6.004+5.782) # With 16088 git reset --hard origin/master # + last patch on 16044 git bz apply 16088 73.43 (9.092+7.246+7.020+7.053+6.859+7.081+7.045+6.932+7.068+8.037) # With 16140 and 16088 git bz apply 16140 61.21 (7.403+6.036+6.127+5.881+5.674+5.971+5.779+5.901+5.643+6.794) The standard deviation is very high and it seems that my laptop is not stable enough to get correct values. Could someone confirm/contradict them? -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 --- Comment #7 from Jonathan Druart <jonathan.druart@bugs.koha-community.org> --- Comment 5 was for 20 results. Here the time for 100 results: # Before 16044 262.99 (28.134+32.617+24.995+26.349+25.525+24.629+25.725+24.349+26.063+24.601) # After 16044 255.346 (24.791+25.713+24.151+25.569+26.977+23.780+25.005+23.722+30.042+25.596) # With 16140 219.02 (20.512+21.213+22.303+25.897+20.029+19.469+20.842+19.974+26.847+21.936) # With 16088 293.16 (28.449+28.928+27.206+28.886+28.276+29.433+32.831+30.136+28.632+30.329) # With 16140 and 16088 218.33 (21.278+23.491+20.935+21.529+21.854+19.016+21.408+23.760+21.577+23.485) -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 --- Comment #9 from Jonathan Druart <jonathan.druart@bugs.koha-community.org> --- (In reply to Jonathan Druart from comment #8)

For the record, just retry the same on fc640d2 # just before bug 11998:

134.578 (13.868+12.963+13.374+13.732+13.039+13.538+12.972+13.200+14.647+13.245)

For 20! so to compare with comment 5 :) -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 --- Comment #11 from Jonathan Druart <jonathan.druart@bugs.koha-community.org> --- Now let's try to compare the idea of this first patch (Bug 16140: Only clear L1 cache when needed) and the one on bug 16088 (avoid excessive L1 flush): # 16044 + Bug 16140: Only clear L1 cache when needed 89.07 (9.606+8.805+8.416+9.685+8.629+9.392+8.956+8.631+8.281+8.670) -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 --- Comment #13 from Jonathan Druart <jonathan.druart@bugs.koha-community.org> --- To reinforce these numbers, I have reused the selenium scripts (bug 13691) used on https://wiki.koha-community.org/wiki/Benchmark_for_3.22: v3.22.00 CP main = 3.45 CP add patron category = 4.83 CP add patron = 4.72 CP add items = 15.17 CP checkout = 11.57 CP checkin = 9.53 before 11998 (fc640d2) CP main = 4.04 CP add patron category = 4.86 CP add patron = 4.87 CP add items = 16.38 CP checkout = 10.91 CP checkin = 10.99 master + 16140 + 16088 - intelligent flushing CP main = 3.42 CP add patron category = 4.17 CP add patron = 4.67 CP add items = 12.82 CP checkout = 8.36 CP checkin = 7.56 -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 Jonathan Druart <jonathan.druart@bugs.koha-community.org> changed: What |Removed |Added ---------------------------------------------------------------------------- See Also| |https://bugs.koha-community | |.org/bugzilla3/show_bug.cgi | |?id=16166 -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 --- Comment #15 from Jacek Ablewicz <abl@biblos.pk.edu.pl> --- I've tried to review GetMarcStructure() calls in the existing code as an attempt to establish it's "safety level". As general rule, framework hash-of-hashes-of hashes returned by GetMarcStructure() tends to be abused a little bit here and there, we have a lot of statements like this $tagslib->{$fieldvalue}->{$subfvalue}->{'hidden'} || 0 i.e., this structure is prone to be messed up in many places, due to autovivification of hash keys. However, if it is messed up everywhere in the same, somehow predictable way, maybe it will be not such a big problem (?). But there are places in the code where we do foreach my $field ( keys %$tagslib ) foreach my $subfield ( sort( keys %{ $tagslib->{$tag} } and so on, so adding { unsafe => 1 } to GetMarcStructure() certainly has quite a bit of potential for introducting some hard-to-catch regressions, especially under plack. -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 --- Comment #17 from Jesse Weaver <jweaver@bywatersolutions.com> --- I'm starting to think there's something very oddly system dependent here. Running the same tests (each number inside the parentheses is the total runtime of 10 runs of Jonathan's tests, and the number of front is the total of those totals): master (6a04ba598, which includes the last batch on bug 16044 to set the L1 cache more often): 232.81 (22.93+23.21+23.21+23.07+23.41+23.01+23.51+23.25+23.51+23.70) master + 16088: 441.07 (43.28+43.87+44.00+43.90+44.35+44.54+44.96+44.53+43.92+43.72) # I suspect this is because L1 cache hits, and thus deep-cloning, is increased. master + 16088 + the second patch here (don't clone framework/authvals): 137.90 (13.28+13.81+14.02+13.79+13.81+13.32+13.96+14.00+13.95+13.96) master + 16140 - intelligent flushing: 233.67 (23.61+23.02+23.48+23.64+22.98+23.62+23.44+23.54+23.60+22.74) master + 16140: 137.34 (13.92+13.90+13.75+13.70+13.42+13.84+13.93+13.74+13.83+13.3 master + 16140 + 16088 - intelligent flushing: 139.33 (14.03+14.03+13.96+14.06+13.60+13.88+13.87+14.02+14.18+13.70) master + 16140 + 16088: 134.67 (13.40+13.33+13.52+13.38+14.03+13.43+12.97+13.42+13.59+13.60) This makes sense to me. Reducing deep cloning makes the biggest difference, and as we add 16088 then 16140 the number of L1 flushes drops from: 4200 (100 runs * 21 L1 flushes per request) to 100 (100 runs * 1 L1 flush per request) to 1. I'm currently trying an approach that recursively locks any refs passed to the L1 cache, but am having trouble making it performant. -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 --- Comment #19 from Jonathan Druart <jonathan.druart@bugs.koha-community.org> --- (In reply to Jesse Weaver from comment #17)

I'm starting to think there's something very oddly system dependent here.

Why do you say that, your numbers confirm mine. -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 --- Comment #21 from Jacek Ablewicz <abl@biblos.pk.edu.pl> --- (In reply to Jonathan Druart from comment #20)

(In reply to Jacek Ablewicz from comment #18)

...

(In reply to Jesse Weaver from comment #17)

...

master (6a04ba598, which includes the last batch on bug 16044 to set the L1 cache more often): 232.81 (22.93+23.21+23.21+23.07+23.41+23.01+23.51+23.25+23.51+23.70)

Btw, those numbers are in what units? Seconds, miliseconds (microfortnights, nanocenturies, ..) ? They look way too high to be in seconds (unless you are running Koha on Arduino Pro Mini or something like that) and way to low to be in miliseconds (unless you are running Koha on some liquid-helium-cooled test rig on steroids).

It's seconds: "(each number inside the parentheses is the total runtime of 10 runs of Jonathan's tests, and the number of front is the total of those totals)"

So 232.81 seconds is a total for 100 test runs (1 log in + 1 search taking 2.33 seconds on average), or is it a total for 10 test runs (log in + search taking 23.3 seconds on average)? -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 --- Comment #23 from Jacek Ablewicz <abl@biblos.pk.edu.pl> --- Some more benchmarks :), test setup: CGI, L2 = memcached, medium dataset (130K biblio records, 300K items), one test run = log in + staff catalogue search for 'z' term (like in comment #5), XSLT processing enabled, numSearchResults = 100 (i.e 100 results / page), maxRecordsForFacets = 200, StaffAuthorisedValueImages disabled (Bug 16041). # master 146.05 (14.52+14.63+14.63+14.73+14.81+14.71+14.16+14.65+14.60+14.61) # master + Bug 16166 90.7 (9.15+9.10+9.16+8.41+9.19+9.19+9.11+9.19+9.02+9.18) # master + 2nd patch from Bug 16140 (aka don't clone framework/authvals) 71.61 (7.22+7.19+7.13+7.16+7.13+7.10+7.27+7.18+7.05+7.18) # master + 2nd patch from Bug 16140 + Bug 16166 71.15 (7.11+7.10+7.20+7.22+7.19+6.52+7.24+7.28+7.10+7.19) Shell test script from comment #5 does not quite work for me for some reasons

% for i in {1..10}; do {time perl test.t > /dev/null} 2>> /tmp/time;done; echo $((`perl -pe 's/.*cpu ([^s]*) total/$1/' /tmp/time| tr '\n' '+'|sed > 's/+$//'`)

looks like 'time' used in it is an internal shell subroutine of some kind, specific for a given UX shell (which one - ?); instead, I used '/usr/bin/time -n', and postproceesed timing results throug this simple perl script: #!/usr/bin/perl use Modern::Perl; my @timings; while (<>) { chomp; /^real ([\d\.]+)/ || next; push(@timings, $1); } my $total = 0; map { $total += $_; } @timings; print $total." (".join('+', @timings).")\n"; Note that I'm measuring so-called "real" (wall clock) timings in here; I have no idea what exactly is being measured in comment #5 - hopefully someting similar? -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 --- Comment #25 from Jonathan Druart <jonathan.druart@bugs.koha-community.org> --- (In reply to Jacek Ablewicz from comment #23)

Shell test script from comment #5 does not quite work for me for some reasons

...

% for i in {1..10}; do {time perl test.t > /dev/null} 2>> /tmp/time;done; echo $((`perl -pe 's/.*cpu ([^s]*) total/$1/' /tmp/time| tr '\n' '+'|sed > 's/+$//'`)

It's zsh.

Note that I'm measuring so-called "real" (wall clock) timings in here; I have no idea what exactly is being measured in comment #5 - hopefully someting similar?

I have used the total CPU time (if the output looks like '1.95s user 0.05s system 68% cpu 2.920 total', I got 2.920). -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 Jacek Ablewicz <abl@biblos.pk.edu.pl> changed: What |Removed |Added ---------------------------------------------------------------------------- See Also| |https://bugs.koha-community | |.org/bugzilla3/show_bug.cgi | |?id=16365 -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 Jesse Weaver <jweaver@bywatersolutions.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #49488|0 |1 is obsolete| | --- Comment #27 from Jesse Weaver <jweaver@bywatersolutions.com> --- Created attachment 51025 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=51025&action=edit Bug 16140: don't clone cache results for framework/authvals This is needed so as not to cancel out the performance gains of the L1 cache. -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 Marcel de Rooy <m.de.rooy@rijksmuseum.nl> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |m.de.rooy@rijksmuseum.nl --- Comment #29 from Marcel de Rooy <m.de.rooy@rijksmuseum.nl> --- What is the current status of this discussion? ;) -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 --- Comment #31 from Jonathan Druart <jonathan.druart@bugs.koha-community.org> --- (In reply to Marcel de Rooy from comment #29)

What is the current status of this discussion? ;)

IIRC the flush_L1_if_needed is a good idea but we did not notice a high perf gain. We could try and revive it in a few months if we want to safe some ms per query. The patch 2 should be moved to its own bug report (note that GetMarcStructure is done on bug 16365). -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 Jonathan Druart <jonathan.druart@bugs.koha-community.org> changed: What |Removed |Added ---------------------------------------------------------------------------- Blocks| |17819 Referenced Bugs: https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=17819 [Bug 17819] Performance 16.11 - Omnibus -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 Katrin Fischer <katrin.fischer@bsz-bw.de> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |katrin.fischer@bsz-bw.de --- Comment #33 from Katrin Fischer <katrin.fischer@bsz-bw.de> --- (In reply to David Cook from comment #32)

Sounds like this one might be worth closing

Should we close? -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=16140 --- Comment #35 from David Cook <dcook@prosentient.com.au> --- (In reply to Jonathan Druart from comment #34)

I do not think so, there are interesting ideas that could be reused.

Perhaps those should be spun off into their own specific bug reports? I just re-read the comments, and I don't think it's clear what's being discussed here entirely? I am interested in L1 cache issues, which I think is what brought me here, but not sure what's the actual issue in this report? Maybe it just need to be renamed? -- You are receiving this mail because: You are watching all bug changes.