Bug 24027 - Adding multiple items is slow
Summary: Adding multiple items is slow
Status: Pushed to master
Alias: None
Product: Koha
Classification: Unclassified
Component: Cataloging (show other bugs)
Version: master
Hardware: All All
: P5 - low major (vote)
Assignee: Andrew Nugged
QA Contact: Jonathan Druart
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-11-13 07:54 UTC by Andrew Nugged
Modified: 2020-05-12 10:22 UTC (History)
6 users (show)

See Also:
Change sponsored?: ---
Patch complexity: ---
Who signed the patch off:
Text to go in the release notes:
Version(s) released in:
20.05.00


Attachments
Bug 24027: dbh handler not passed through all chain (2.45 KB, patch)
2019-11-13 22:57 UTC, Andrew Nugged
Details | Diff | Splinter Review
Bug 24027: (follow-up) ModZebra should be called once after all items added, not on each item add (5.68 KB, patch)
2019-11-14 00:02 UTC, Andrew Nugged
Details | Diff | Splinter Review
Bug 24027: (follow-up) Don't combine long items-add POST page with list generation (5.41 KB, patch)
2019-11-14 11:25 UTC, Andrew Nugged
Details | Diff | Splinter Review
Bug 24027: ModZebra should be called once after all items added, not on each item add (5.93 KB, patch)
2019-11-14 18:07 UTC, Andrew Nugged
Details | Diff | Splinter Review
Bug 24027: Call ModZebra only once after all items have been added (5.91 KB, patch)
2019-11-16 21:18 UTC, Andrew Nugged
Details | Diff | Splinter Review
Bug 24027: (follow-up) Don't combine multiple items add POST page with list generation (7.03 KB, patch)
2019-11-21 15:21 UTC, Andrew Nugged
Details | Diff | Splinter Review
Bug 24027: Call ModZebra only once after all items have been added (5.95 KB, patch)
2020-01-31 21:22 UTC, Michal Denar
Details | Diff | Splinter Review
Bug 24027: (follow-up) Don't combine multiple items add POST page with list generation (7.09 KB, patch)
2020-01-31 21:22 UTC, Michal Denar
Details | Diff | Splinter Review
Bug 24027: Call ModZebra only once after all items have been added (5.95 KB, patch)
2020-01-31 21:23 UTC, Michal Denar
Details | Diff | Splinter Review
Bug 24027: (follow-up) Don't combine multiple items add POST page with list generation (7.09 KB, patch)
2020-01-31 21:23 UTC, Michal Denar
Details | Diff | Splinter Review
Bug 24027: Call ModZebra once after all items added/deleted in a batch (7.07 KB, patch)
2020-04-06 16:20 UTC, Andrew Nugged
Details | Diff | Splinter Review
Bug 24027: Call ModZebra once after all items added/deleted in a batch (7.07 KB, patch)
2020-04-07 07:29 UTC, Andrew Nugged
Details | Diff | Splinter Review
Bug 24027: Call ModZebra once after all items added/deleted in a batch (7.13 KB, patch)
2020-04-08 13:21 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 24027: (QA follow-up) Fix POD warning (731 bytes, patch)
2020-04-08 13:22 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 24027: Add POD about the new parameter in Koha::Item->store (979 bytes, patch)
2020-04-08 14:18 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 24027: Call ModZebra once after all items added/deleted in a batch (7.25 KB, patch)
2020-04-08 14:59 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 24027: (QA follow-up) Fix POD warning (805 bytes, patch)
2020-04-08 14:59 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 24027: Add POD about the new parameter in Koha::Item->store (1.03 KB, patch)
2020-04-08 14:59 UTC, Jonathan Druart
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Andrew Nugged 2019-11-13 07:54:56 UTC
In cataloguing/additem.pl?biblionumber=XXX when we choose "add multiple copies of the item" it's adds very slowly. I did analysis and there's one big inefficiency of calling 

    ModZebra( $item->{biblionumber}, "specialUpdate", "biblioserver" );

in every AddItem call: it requests update for same biblionumber after adding each new item and time for execution of this ModZebra grows exponentially.

My set of patches (preparatory + fix) I will provide here will make this call to ModZebra happen once in the end of adding of the whole number of these items once.

Also I will attach a few smaller follow-up patches where I propose optimisations for extra operations.
Comment 1 Andrew Nugged 2019-11-13 22:57:42 UTC Comment hidden (obsolete)
Comment 2 Andrew Nugged 2019-11-14 00:02:05 UTC Comment hidden (obsolete)
Comment 3 Jonathan Druart 2019-11-14 11:08:38 UTC
Hi Andrew,

Thanks for the patch, that's a great idea.
Is it ready for signoff?

Only one thing, we will certainly reject the first patch, $dbh must be retrieved from C4::Context->dbh only.
Also we prefer to have a hashref as parameters to make the flag explicit:
  { postpone_indexes_update => 1 }

Cheers,
Jonathan
Comment 4 Andrew Nugged 2019-11-14 11:25:20 UTC Comment hidden (obsolete)
Comment 5 Andrew Nugged 2019-11-14 11:30:44 UTC
Thanks Jonathan,

> Only one thing, we will certainly reject the first patch, $dbh must be retrieved from C4::Context->dbh only.

so I will rework in opposite direction, removing mine + old dbh in params: that


> Also we prefer to have a hashref as parameters to make the flag explicit:
>  { postpone_indexes_update => 1 }

yes, this is good coding style for not to seding unknown ", 1" or ", 0" in params :),
thought about that but was afraid to announce it because it is more bigger change then (calling style from sequential params to hash with options). But both thumbs up for this!


I will recreate now patches/chain,
please then give feedback on last GUI change one:

Bug 24027: (follow-up) Don't combine long items-add POST page with list generation

... so I will rework them in a batch :), and then I will ask for Sign-Off.
Comment 6 Jonathan Druart 2019-11-14 12:12:34 UTC
I understand the need of the UI patch, but I am worry it will not fit all needs, as it adds an extra step. I am pretty sure catalogers want to see if the last action did what they wanted :)

We have something similar for the batch item edit/del tools, driven by a sysprefs. We could hardcoded it for now (50, 100?) and see if it passes QA :)
Comment 7 Jonathan Druart 2019-11-14 12:17:25 UTC
(In reply to Jonathan Druart from comment #6)
> I understand the need of the UI patch, but I am worry it will not fit all
> needs, as it adds an extra step. I am pretty sure catalogers want to see if
> the last action did what they wanted :)
> 
> We have something similar for the batch item edit/del tools, driven by a
> sysprefs. We could hardcoded it for now (50, 100?) and see if it passes QA :)

I meant: do not display the item list if X items are added in one go.

But it will not fix the problem if there are already thousands of items. So maybe a pref to limit the display of the number of items.
I feel like we should ask the list to get feedbacks from catalogers.
Comment 8 Jonathan Druart 2019-11-14 12:33:23 UTC
(for the OPAC we have OpacMaxItemsToDisplay, to limit the number of items to display on the biblio detail view)
Comment 9 Andrew Nugged 2019-11-14 12:36:01 UTC
> OpacMaxItemsToDisplay

thought to make it configurable but hezitated :). Will be more brave then. Okay will use your vision and present rework for all the chain this week.
Comment 10 Andrew Nugged 2019-11-14 18:07:08 UTC Comment hidden (obsolete)
Comment 11 Andrew Nugged 2019-11-16 21:18:50 UTC Comment hidden (obsolete)
Comment 12 Andrew Nugged 2019-11-21 15:21:03 UTC Comment hidden (obsolete)
Comment 13 Michal Denar 2020-01-06 21:41:31 UTC
Hi,
any test plan?
Comment 14 Michal Denar 2020-01-31 21:22:29 UTC Comment hidden (obsolete)
Comment 15 Michal Denar 2020-01-31 21:22:33 UTC Comment hidden (obsolete)
Comment 16 Michal Denar 2020-01-31 21:23:52 UTC Comment hidden (obsolete)
Comment 17 Michal Denar 2020-01-31 21:23:56 UTC Comment hidden (obsolete)
Comment 18 Jonathan Druart 2020-02-05 11:07:21 UTC
We should not reuse OpacMaxItemsToDisplay but create a new pref here.
Comment 19 Andrew Nugged 2020-04-06 16:16:29 UTC
(In reply to Jonathan Druart from comment #18)
> We should not reuse OpacMaxItemsToDisplay but create a new pref here.

I will separate this ticket into two – 

First one, current, will be without GUI update, but to fix this "ModZebra" call with ElasticSearch enabled which takes really crazy amount of time to perform.

Second one – I will create another ticket – with pref or with API/ajax pagination or some other solution (we will decide I will think + ask in IRC/etc), 

it's really separated update so ok to have major speed affecting this one ModZebra issue,

publishing updated patch + explanation: ...
Comment 20 Andrew Nugged 2020-04-06 16:20:10 UTC Comment hidden (obsolete)
Comment 21 Andrew Nugged 2020-04-07 07:29:17 UTC
(+ did rebase to latest master)
Comment 22 Andrew Nugged 2020-04-07 07:29:39 UTC
Created attachment 102474 [details] [review]
Bug 24027: Call ModZebra once after all items added/deleted in a batch

Issue description:
- call to ModZebra was unconditional inside 'store' method for Koha::Item,
  so it was after each item added, or deleted.
- ModZebra called with param biblionumber, so it is the same parameter
  across calls for each items with same biblionumber, especially when we
  adding/removing in a batch.
- with ElasticSearch enabled this makes even more significant load
  and it is also progressively grows when more items already in DB

Solution:
- to add extra parameter 'skip_modzebra_update' and propagate it down to
 'store' method call to prevent call of ModZebra,
- but to call ModZebra once after the whole batch loop in the upper layer

Test plan / how to replicate:
- make sure that you have in the admin settings "SearchEngine" set to
  "Elasticsearch" and your ES is configured and working
  ( /cgi-bin/koha/admin/preferences.pl?op=search&searchfield=SearchEngine )
- select one of biblioitems without items
  ( /cgi-bin/koha/cataloguing/additem.pl?biblionumber=XXX )
- press button "add multiple copies of this item",
- enter 200 items, start measuring time and submit the page/form...

On my test machine when adding 200 items 3 times in a row (so 600 in
total, but to show that time grows with every next batch gradually):

WHEN ElasticSearch DISABLED (only Zebra queue):
- 9s, 12s, 13s
WHEN ElasticSearch ENABLED:
- 1.3m, 3.2m, 4.8m
WITH PATCH WHEN ElasticSearch ENABLED:
- 10s, 13s, 15s

Same slowness (because also same call to ModZebra) happens when you try
to delete items in a batch or delete all items ("op=delallitems"). And same fix.
Comment 23 Jonathan Druart 2020-04-07 09:13:17 UTC
Hi Andrew, can you explain why did you change your mind?
The patches were almost ready, I was only asking for a new pref. The changes to add a new pref is minimal, I can help if needed.
Comment 24 Andrew Nugged 2020-04-07 10:17:49 UTC
Those were anyway two patches, which not related to each other.
One for "ModZebra" calls and another for GUI changes.
Yet both improving the same site page(s) section.

so:
Comment 25 Andrew Nugged 2020-04-07 10:19:26 UTC
(In reply to Jonathan Druart from comment #23)

About FIRST patch which I just posted – it was "full separate one" and it is the same one, but more clear and proper:

I re-created and re-tested/re-described, because:

- I now found the real cause (Elasticsearch enabled) why it happens to be tested well,
- I also found that "deleteallitems" had the same issue so change also added,
- the parameter name (skip_modzebra_update) and propagation down below to "store" made better now
- overall rebase (with rework) was needed because old patch used "AddItem" sub which now removed in favor of Koha::Item->...->store.


And this first patch had main and most SERIOUS impact on execution speed.

(but second patch: ... )
Comment 26 Andrew Nugged 2020-04-07 10:31:11 UTC
(In reply to Jonathan Druart from comment #23)

But second patch not based nor related to the first one, that's why I propose to separate it and do it right: 

- it was an UGLY tradeoff solution with not so good UX improvement: it just not shown all number of items on the post-POST page if it is more than that parameter, just saying "XXX items added" only. Adding extra branching in the template and pre-template call, but not adding so much improvement because of the next page:

- it anyway had plain normal mode page which loaded all 1000 (or how much there) items on a single page in non-POST request then, so anyway page gen time is long and usefulness of displaying all-items-on-one page for an operator is very questionable,

- that's why I propose to separate this into another ticket and do it,
- but (and) yes, I can re-create it with the separate new pref-parameter as it was on the beginning if you want, but I feet myself "bad senior coder" with this "plumber" solution :)


but CORRECT solution (two options) I propose/see:

- complex but beautiful: create ajax pagination as it made on patrons page (for example)

- straight simple dumb but robust without any extra pref-parameters:
unconditionally, without any "prefs", just NOT to generate items list on post-POST page, but add the link (or forward with delay) to full list+form page in non-POST mode (i.e. usual post-POST page "xxx items added" + link or forward)
Comment 27 Andrew Nugged 2020-04-07 10:34:58 UTC
s/feet/feel/ :P
Comment 28 Jonathan Druart 2020-04-07 10:50:03 UTC
(In reply to Andrew Nugged from comment #26)
> but CORRECT solution (two options) I propose/see:
> 
> - complex but beautiful: create ajax pagination as it made on patrons page
> (for example)
> 
> - straight simple dumb but robust without any extra pref-parameters:
> unconditionally, without any "prefs", just NOT to generate items list on
> post-POST page, but add the link (or forward with delay) to full list+form
> page in non-POST mode (i.e. usual post-POST page "xxx items added" + link or
> forward)

Yes, that's definitely the way to go, but not trivial.

Make sure you are aware of the latest moves from Tomas in this area (see bug 20212) before starting!
Comment 29 Andrew Nugged 2020-04-07 12:19:24 UTC
(In reply to Jonathan Druart from comment #28)


... so we can proceed with this single ModZebra update patch?
and queue the Ajax-one for later (and to combine with Tomas'es updates?)



And in my prev. message I proposed two options (it was unclear as one single solution):
1. ajax
2. OR simply post-POST page to make it without listing all added items on the same page



So about p2 above:

> - straight simple ... just NOT to generate list but show on post-POST page "xxx items added" + link or forward to list page

i.e. no "prefs",
I will just add after items added:
"xxx items added. Follow this link to return to the list: ..."
message on post-POST page without list generation.

Do you think this p2 (quick-patch) needed here in this ticket? Should I create?
Comment 30 Andrew Nugged 2020-04-07 12:21:22 UTC Comment hidden (obsolete)
Comment 31 Jonathan Druart 2020-04-07 12:29:30 UTC
I do not think we should have an additional click. I guess cataloguers want to see the result of their last changes after the POST.
Comment 32 Andrew Nugged 2020-04-07 13:26:27 UTC
Agreed. There will be another ticket from me for this new "Max pref" and post-POST page.
Comment 33 Andrew Nugged 2020-04-07 13:27:11 UTC
... so I support conclusion that we can proceed with this ticket as finished / to be signed+tested.
Comment 34 Tomás Cohen Arazi 2020-04-07 20:39:15 UTC
Lets implement pagination as all the framework is completed to accomplish that! No more Max items.

For references on using the API to render (paginated) datatables, see bug 20212. The important bits are embedding related objects for rendering and filtering, and rendering properly :-D So you need to add embeds and build the right renderers for each column.

Regarding my work on the performance front, I identified this situations:
- We retrieve (cached or not) the frameworks inside loops without a real need, and really deep in the code. Take a biblio, as the outer situation: it only has one framework assigned, we can pass it down to the last portion of the code we call instead of doing it inside the loop (and many times as we do).
- The same applies for code related to OpacHiddenItems and friends. Bug 23247 is a good example of how I think it should be done. It might still need fetching the framework outside now that I look at it with fresh eyes :-D
Comment 35 Tomás Cohen Arazi 2020-04-07 21:09:43 UTC
I don't know you, Andrew, and I think your patches are doing a good job (well spotted the bottleneck, the loop design issue, etc. Well done!). But I think it is time for all of us to think more in the long term.

ModZebra (in the Elasticsearch case) is fetching the MARC record so it gets indexed by ES. The main problem here is that this is not an async call, but a blocking one. It doesn't hurt Zebra because in that case we have task queue and a script that takes care of the queue.

I think it is the way to go: have a task queue and leverage on that.

That said, I never liked that we call ModZebra from Koha::Item->store, and while I understand the reasons for that and agree to just move forward and fix later, I wouldn't add even more things related to ModZebra to the method signature like this. We would just be polluting things even more.

To put it clear, my POV is that this post-success-actions (i.e. actions that take place if storing the new/updated Item is successful) should be something that happens in the controller code. If Koha::Item->store didn't call ModZebra by itself, I'd do something like:

    try {
        # This is just fiction code
        while ( my $item = $items_to_store->next ) {
            $item->store;
        }
    }
    catch {
        handle_exception($_);
    }
    finally {
      if (@_) {
        notify_the_error();
      }
      else {
        # No error
        if (ES) {
            trigger_es_reindex( $item->biblionumber );
        }
        elsif (Zebra) {
            ModZebra(...);
        }
        else {
            Koha::Exception::WTF->throw();
        }
      }
    };

So, I understand the optimization, I fear from my QA POV that we are introducing even more code that we will need to remove, in the place we wouldn't want to. And this is always the excuse we use for not doing things right!

If I was to fix this, I would look into moving the code for ES from plain triggering the indexing, into using zebraqueue (probably renaming some things while on it).

I hope this discussion doesn't discourage you, Andrew! I don't want to block this if the QA team thinks we could live with this.
Comment 36 Tomás Cohen Arazi 2020-04-08 12:44:48 UTC
Talked to the author of most of Koha::Item->store (Jonathan) and we agreed this should move forward with a FIXME or similar. I'm testing this ATM for sign-off
Comment 37 Tomás Cohen Arazi 2020-04-08 13:21:56 UTC
Created attachment 102567 [details] [review]
Bug 24027: Call ModZebra once after all items added/deleted in a batch

Issue description:
- call to ModZebra was unconditional inside 'store' method for Koha::Item,
  so it was after each item added, or deleted.
- ModZebra called with param biblionumber, so it is the same parameter
  across calls for each items with same biblionumber, especially when we
  adding/removing in a batch.
- with ElasticSearch enabled this makes even more significant load
  and it is also progressively grows when more items already in DB

Solution:
- to add extra parameter 'skip_modzebra_update' and propagate it down to
 'store' method call to prevent call of ModZebra,
- but to call ModZebra once after the whole batch loop in the upper layer

Test plan / how to replicate:
- make sure that you have in the admin settings "SearchEngine" set to
  "Elasticsearch" and your ES is configured and working
  ( /cgi-bin/koha/admin/preferences.pl?op=search&searchfield=SearchEngine )
- select one of biblioitems without items
  ( /cgi-bin/koha/cataloguing/additem.pl?biblionumber=XXX )
- press button "add multiple copies of this item",
- enter 200 items, start measuring time and submit the page/form...

On my test machine when adding 200 items 3 times in a row (so 600 in
total, but to show that time grows with every next batch gradually):

WHEN ElasticSearch DISABLED (only Zebra queue):
- 9s, 12s, 13s
WHEN ElasticSearch ENABLED:
- 1.3m, 3.2m, 4.8m
WITH PATCH WHEN ElasticSearch ENABLED:
- 10s, 13s, 15s

Same slowness (because also same call to ModZebra) happens when you try
to delete items in a batch or delete all items ("op=delallitems"). And same fix.

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 38 Tomás Cohen Arazi 2020-04-08 13:22:06 UTC
Created attachment 102568 [details] [review]
Bug 24027: (QA follow-up) Fix POD warning

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 39 Jonathan Druart 2020-04-08 14:18:40 UTC
Created attachment 102572 [details] [review]
Bug 24027: Add POD about the new parameter in Koha::Item->store
Comment 40 Jonathan Druart 2020-04-08 14:22:22 UTC
From the commit message:
"""
Same slowness (because also same call to ModZebra) happens when you try to delete items in a batch or delete all items ("op=delallitems"). And same fix.
"""

What do you mean by "delete items in a batch"?
Comment 41 Jonathan Druart 2020-04-08 14:59:37 UTC
Created attachment 102578 [details] [review]
Bug 24027: Call ModZebra once after all items added/deleted in a batch

Issue description:
- call to ModZebra was unconditional inside 'store' method for Koha::Item,
  so it was after each item added, or deleted.
- ModZebra called with param biblionumber, so it is the same parameter
  across calls for each items with same biblionumber, especially when we
  adding/removing in a batch.
- with ElasticSearch enabled this makes even more significant load
  and it is also progressively grows when more items already in DB

Solution:
- to add extra parameter 'skip_modzebra_update' and propagate it down to
 'store' method call to prevent call of ModZebra,
- but to call ModZebra once after the whole batch loop in the upper layer

Test plan / how to replicate:
- make sure that you have in the admin settings "SearchEngine" set to
  "Elasticsearch" and your ES is configured and working
  ( /cgi-bin/koha/admin/preferences.pl?op=search&searchfield=SearchEngine )
- select one of biblioitems without items
  ( /cgi-bin/koha/cataloguing/additem.pl?biblionumber=XXX )
- press button "add multiple copies of this item",
- enter 200 items, start measuring time and submit the page/form...

On my test machine when adding 200 items 3 times in a row (so 600 in
total, but to show that time grows with every next batch gradually):

WHEN ElasticSearch DISABLED (only Zebra queue):
- 9s, 12s, 13s
WHEN ElasticSearch ENABLED:
- 1.3m, 3.2m, 4.8m
WITH PATCH WHEN ElasticSearch ENABLED:
- 10s, 13s, 15s

Same slowness (because also same call to ModZebra) happens when you try
to delete all items ("op=delallitems"). And same fix.

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Amended commit message: the fix does not include the batch item
deletion.
Comment 42 Jonathan Druart 2020-04-08 14:59:42 UTC
Created attachment 102579 [details] [review]
Bug 24027: (QA follow-up) Fix POD warning

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Comment 43 Jonathan Druart 2020-04-08 14:59:48 UTC
Created attachment 102580 [details] [review]
Bug 24027: Add POD about the new parameter in Koha::Item->store

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Comment 44 Jonathan Druart 2020-04-08 15:00:20 UTC
(In reply to Jonathan Druart from comment #40)
> From the commit message:
> """
> Same slowness (because also same call to ModZebra) happens when you try to
> delete items in a batch or delete all items ("op=delallitems"). And same fix.
> """
> 
> What do you mean by "delete items in a batch"?

Confirmed by Andrew (pm), I amended the commit message.
Comment 45 Martin Renvoize 2020-04-14 07:36:48 UTC
Nice work everyone!

Pushed to master for 20.05
Comment 46 Joy Nelson 2020-05-04 20:50:15 UTC
does not apply to 19.11.x branch please rebase if needed.
Comment 47 Martin Renvoize 2020-05-12 10:22:01 UTC
Nice work everyone!

Pushed to master for 20.05