Bug 33972 - Remove unnecessary batch status change in C4::ImportBatch
Summary: Remove unnecessary batch status change in C4::ImportBatch
Status: RESOLVED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: Tools (show other bugs)
Version: Main
Hardware: All All
: P5 - low minor (vote)
Assignee: Nick Clemens (kidclamp)
QA Contact: Marcel de Rooy
URL:
Keywords:
Depends on: 27421
Blocks:
  Show dependency treegraph
 
Reported: 2023-06-09 13:16 UTC by Nick Clemens (kidclamp)
Modified: 2023-12-28 20:47 UTC (History)
6 users (show)

See Also:
Change sponsored?: ---
Patch complexity: Trivial patch
Documentation contact:
Documentation submission:
Text to go in the release notes:
Version(s) released in:
23.11.00,23.05.02,22.11.08


Attachments
Bug 33972: Set importing status to batch outside of transaction (1.74 KB, patch)
2023-06-09 13:39 UTC, Nick Clemens (kidclamp)
Details | Diff | Splinter Review
Bug 33972: Set importing status to batch outside of transaction (1.83 KB, patch)
2023-06-16 08:07 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 33972: (follow-up) Remove status change to importing (1.54 KB, patch)
2023-06-16 08:07 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 33972: Set importing status to batch outside of transaction (1.39 KB, patch)
2023-06-16 12:32 UTC, Katrin Fischer
Details | Diff | Splinter Review
Bug 33972: (follow-up) Remove status change to importing (1.50 KB, patch)
2023-06-16 12:32 UTC, Katrin Fischer
Details | Diff | Splinter Review
Bug 33972: Set importing status to batch outside of transaction (1.45 KB, patch)
2023-06-23 20:24 UTC, Katrin Fischer
Details | Diff | Splinter Review
Bug 33972: (follow-up) Remove status change to importing (1.56 KB, patch)
2023-06-23 20:24 UTC, Katrin Fischer
Details | Diff | Splinter Review
Bug 33972: Remove settings of batch status to imorting (1.06 KB, patch)
2023-06-27 13:27 UTC, Nick Clemens (kidclamp)
Details | Diff | Splinter Review
Bug 33972: Remove settings of batch status to importing (1.16 KB, patch)
2023-06-27 13:45 UTC, Marcel de Rooy
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Nick Clemens (kidclamp) 2023-06-09 13:16:23 UTC
In BatchCommitRecords we currently

Start a transaction
...
SetImportBatchStatus($batch_id, 'importing');
...
SetImportBatchStatus($batch_id, 'finished');
...
Finish the transaction


In certain settings the second call fails as it is waiting for the first to commit it seems:
[Fri Jun  9 09:06:29 2023] background_jobs_worker.pl: C4::ImportBatch::SetImportBatchStatus(): DBI Exception: DBD::mysql::db do failed: Lock wait timeout exceeded; try restarting transaction at /usr/share/koha/lib/C4/ImportBatch.pm line 717

Setting the status twice inside the transaction doesn't make sense - the DB will never show the 'importing' status - as it will either be rolled back when the transaction fails, or set to 'finished' when it completes
Comment 1 Jonathan Druart 2023-06-09 13:26:46 UTC
Is it a recent regression?
Comment 2 Nick Clemens (kidclamp) 2023-06-09 13:39:11 UTC
Created attachment 152249 [details] [review]
Bug 33972: Set importing status to batch outside of transaction

This patch moves the setting of the 'importing' status for the batch
outside fo the transaction.

This prevents a scenario seen on some setups where a deadlock is created:
background_jobs_worker.pl: C4::ImportBatch::SetImportBatchStatus(): DBI Exception: DBD::mysql::db do failed: Lock wait timeout exceeded; try restarting transaction at /usr/share/koha/lib/C4/ImportBatch.pm line 717

To test:
1 - Apply patch
2 - Stage and import some files
3 - Confirm the imports successfully complete
Comment 3 Nick Clemens (kidclamp) 2023-06-09 13:44:04 UTC
(In reply to Jonathan Druart from comment #1)
> Is it a recent regression?

Yes, only seen in 22.11, suspect it is from the move of the transaction on 27421
Comment 4 Marcel de Rooy 2023-06-15 14:27:14 UTC
(In reply to Nick Clemens from comment #0)
> In BatchCommitRecords we currently
> 
> Start a transaction
> ...
> SetImportBatchStatus($batch_id, 'importing');
> ...
> SetImportBatchStatus($batch_id, 'finished');
> ...
> Finish the transaction
> 
> 
> In certain settings the second call fails as it is waiting for the first to
> commit it seems:
> [Fri Jun  9 09:06:29 2023] background_jobs_worker.pl:
> C4::ImportBatch::SetImportBatchStatus(): DBI Exception: DBD::mysql::db do
> failed: Lock wait timeout exceeded; try restarting transaction at
> /usr/share/koha/lib/C4/ImportBatch.pm line 717
> 
> Setting the status twice inside the transaction doesn't make sense - the DB
> will never show the 'importing' status - as it will either be rolled back
> when the transaction fails, or set to 'finished' when it completes

Normally, you should be able to update the same record within the same transaction. And only another transaction trying to get/update this same record in import_batches should be locked.
So, are you sure that there was no second process involved?

The other thing, though, is that SetImportBatchStatus asks for another db handle via Context/Koha::Database. Since you have a connection, you would not expect a problem. But is it possible that somehting there somehow goes wrong?

Would it be an idea to move the second SetImportBatchStatus call at the end also after the transaction?

Hard to verify if we dont know the exact cause and cannot reproduce..
Comment 5 Nick Clemens (kidclamp) 2023-06-15 14:45:34 UTC
Also see 33987 - similar deadlock when accessing the same import record row multiple times

I can say, I can't reproduce in KTD, but I can replicate every time on our production servers.

In terms of setting the status, doing so twice in a transaction doesn't make sense. It will revert to the original if it fails, or use the final if it succeeds. 

Moving the first one made sense because then the status will be left at 'importing' - the job should be 'failed' so we know there is a problem?

Here and on 33987 I think the code makes sense on its own, even if the problem doesn't always occur
Comment 6 Marcel de Rooy 2023-06-16 06:11:27 UTC
(In reply to Nick Clemens from comment #5)
> Also see 33987 - similar deadlock when accessing the same import record row
> multiple times

Will have a look too

> I can say, I can't reproduce in KTD, but I can replicate every time on our
> production servers.

What are the specs? Koha version, SQL version ?
Do you also confirm herewith that you can no longer reproduce with your fix applied?
Comment 7 Jonathan Druart 2023-06-16 06:49:35 UTC
Are you using --max-processes in the worker?
Comment 8 Marcel de Rooy 2023-06-16 07:16:02 UTC
(In reply to Jonathan Druart from comment #7)
> Are you using --max-processes in the worker?

If another process is involved, we should look for a statement that locks the whole table. Since normally these processes only work on a single batch record and the associated import records ?
Comment 9 Marcel de Rooy 2023-06-16 08:07:24 UTC
Created attachment 152400 [details] [review]
Bug 33972: Set importing status to batch outside of transaction

This patch moves the setting of the 'importing' status for the batch
outside fo the transaction.

This prevents a scenario seen on some setups where a deadlock is created:
background_jobs_worker.pl: C4::ImportBatch::SetImportBatchStatus(): DBI Exception: DBD::mysql::db do failed: Lock wait timeout exceeded; try restarting transaction at /usr/share/koha/lib/C4/ImportBatch.pm line 717

To test:
1 - Apply patch
2 - Stage and import some files
3 - Confirm the imports successfully complete

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 10 Marcel de Rooy 2023-06-16 08:07:27 UTC
Created attachment 152401 [details] [review]
Bug 33972: (follow-up) Remove status change to importing

It actually is not used, checked, etc. It makes more sense to me to
remove it than to put it before the transaction.
If the transaction succeeds, we end up with imported. It it fails,
we will still be on staged (which is better than importing).
The job will be marked as failed in that case too.

Note: I am not convinced that this is the definitive solution. This
feels like a workaround. We might still need to dig further.
Are we simply doing too much in this transaction for large staged
imports? Or shouldnt we call Context->dbh constantly in several
subroutines? Is this just a Mariadb bug? No answers yet.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 11 Marcel de Rooy 2023-06-16 09:39:17 UTC
Katrin and I tested a few larger imports and could not reproduce the lock with and without the patches.
A file with 700 records went in with/without patches.
Another file had data issues, too bad.
Comment 12 Marcel de Rooy 2023-06-16 09:43:15 UTC
I also tested a script updating a record in import_batches constantly, getting new db handles, few updates, fetches and that 100.000 times.
Unfortuantely no deadlocks :)
Comment 13 Marcel de Rooy 2023-06-16 09:45:30 UTC
In conclusion, please add more details about Koha/SQL version.
And please test again. Can you still reproduce with these patches ?
Note that these patches are fine with me. But not the solution yet?
Comment 14 Nick Clemens (kidclamp) 2023-06-16 11:18:01 UTC
(In reply to Marcel de Rooy from comment #13)
> In conclusion, please add more details about Koha/SQL version.
> And please test again. Can you still reproduce with these patches ?
> Note that these patches are fine with me. But not the solution yet?

Server version: 10.6.12-MariaDB-log MariaDB Server


Koha version 22.11 - with some ByWater patches:
https://github.com/bywatersolutions/bywater-koha/commits/bywater-v22.11.06-03

Fixed in branch with this patch:
https://github.com/bywatersolutions/bywater-koha/commits/bywater-v22.11.06-06

(In reply to Marcel de Rooy from comment #6)
> Do you also confirm herewith that you can no longer reproduce with your fix
> applied?

I do, after this we do not see this deadlock occur


The deadlock happens consistently, with imports of any size, we are asking our DBA to take a deeper look
Comment 15 Katrin Fischer 2023-06-16 11:58:12 UTC
Could it be 22.11.x specific? I have tested on master today and while I bumped into 34029, things went mostly ok.
Comment 16 Katrin Fischer 2023-06-16 12:32:47 UTC
Created attachment 152409 [details] [review]
Bug 33972: Set importing status to batch outside of transaction

This patch moves the setting of the 'importing' status for the batch
outside fo the transaction.

This prevents a scenario seen on some setups where a deadlock is created:
background_jobs_worker.pl: C4::ImportBatch::SetImportBatchStatus(): DBI Exception: DBD::mysql::db do failed: Lock wait timeout exceeded; try restarting transaction at /usr/share/koha/lib/C4/ImportBatch.pm line 717

To test:
1 - Apply patch
2 - Stage and import some files
3 - Confirm the imports successfully complete

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 17 Katrin Fischer 2023-06-16 12:32:50 UTC
Created attachment 152410 [details] [review]
Bug 33972: (follow-up) Remove status change to importing

It actually is not used, checked, etc. It makes more sense to me to
remove it than to put it before the transaction.
If the transaction succeeds, we end up with imported. It it fails,
we will still be on staged (which is better than importing).
The job will be marked as failed in that case too.

Note: I am not convinced that this is the definitive solution. This
feels like a workaround. We might still need to dig further.
Are we simply doing too much in this transaction for large staged
imports? Or shouldnt we call Context->dbh constantly in several
subroutines? Is this just a Mariadb bug? No answers yet.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 18 Marcel de Rooy 2023-06-19 07:18:29 UTC
(In reply to Nick Clemens from comment #14)
> Server version: 10.6.12-MariaDB-log MariaDB Server

I tested with 10.5.17. Katrin also had a 10.5.X

> > Do you also confirm herewith that you can no longer reproduce with your fix
> > applied?
> I do, after this we do not see this deadlock occur

Great, but still weird.

> The deadlock happens consistently, with imports of any size, we are asking
> our DBA to take a deeper look

That sounds great too.
Comment 19 David Cook 2023-06-20 01:27:51 UTC
Side note: We assume that "Koha::Database->schema->storage->dbh" always returns the same database handle, but that's not necessarily true.

According to the documentation and source code at https://metacpan.org/pod/DBIx::Class::Storage::DBI#dbh it seems that it tries to fetch a cached database handle but if for whatever reason that cached database handle doesn't seem connected, it'll create a new handle and connect. 

Probably not related but just noticed that while looking at something else...
Comment 20 Marcel de Rooy 2023-06-20 11:57:21 UTC
(In reply to David Cook from comment #19)
> Side note: We assume that "Koha::Database->schema->storage->dbh" always
> returns the same database handle, but that's not necessarily true.
> 
> According to the documentation and source code at
> https://metacpan.org/pod/DBIx::Class::Storage::DBI#dbh it seems that it
> tries to fetch a cached database handle but if for whatever reason that
> cached database handle doesn't seem connected, it'll create a new handle and
> connect. 
> 
> Probably not related but just noticed that while looking at something else...

wait_timeout defaults to  28800 (seconds) == 8 hours. 
The worker is a continuous process. It does db reads itself for the job details. At some point probably a _resultset call in Koha objects or so triggers a reconnect and we get a new handle.
But this problem seems to be reproduced every time. The reconnect should logically not occur when we already read job details and continue in the child? So there must be something else going on too..
Comment 21 David Cook 2023-06-20 23:34:36 UTC
(In reply to Marcel de Rooy from comment #20)
> wait_timeout defaults to  28800 (seconds) == 8 hours. 
> The worker is a continuous process. It does db reads itself for the job
> details. At some point probably a _resultset call in Koha objects or so
> triggers a reconnect and we get a new handle.
> But this problem seems to be reproduced every time. The reconnect should
> logically not occur when we already read job details and continue in the
> child? So there must be something else going on too..

I'm thinking more along the lines of that dbh's ping not coming back as expected and it spawning a new connection, but it's too tough to know arm's length. Just trying to think of any angle that could be used to troubleshoot it.

Without being able to reproduce it outside of Bywater prod, it's a tough one :/.
Comment 22 Marcel de Rooy 2023-06-23 06:22:13 UTC
Nick, what did your DBA find ?
Comment 23 Nick Clemens (kidclamp) 2023-06-23 11:48:11 UTC
(In reply to Marcel de Rooy from comment #22)
> Nick, what did your DBA find ?

We are still investigating - we have now seen it both in our mariadb cluster, and on a local mariadb on a self hosted server

In both cases the problem is now occurring in _batchCommitItems -> AddItemFromMarc -> Koha::Item->store -> Koha::Object->store

The INSERT call on items is hanging and then failing:
DBIx::Class::Storage::DBI::_dbh_execute(): DBI Exception: DBD::mysql::st execute failed: Lock wait timeout exceeded; try restarting transaction at /usr/share/koha/lib/Koha/Object.pm line 170
Comment 24 Katrin Fischer 2023-06-23 20:22:16 UTC
It looks like I forgot to add my SO lines here earlier (see comment#16)
Comment 25 Katrin Fischer 2023-06-23 20:24:00 UTC
Created attachment 152654 [details] [review]
Bug 33972: Set importing status to batch outside of transaction

This patch moves the setting of the 'importing' status for the batch
outside fo the transaction.

This prevents a scenario seen on some setups where a deadlock is created:
background_jobs_worker.pl: C4::ImportBatch::SetImportBatchStatus(): DBI Exception: DBD::mysql::db do failed: Lock wait timeout exceeded; try restarting transaction at /usr/share/koha/lib/C4/ImportBatch.pm line 717

To test:
1 - Apply patch
2 - Stage and import some files
3 - Confirm the imports successfully complete

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Signed-off-by: Katrin Fischer <katrin.fischer.83@web.de>
Comment 26 Katrin Fischer 2023-06-23 20:24:04 UTC
Created attachment 152655 [details] [review]
Bug 33972: (follow-up) Remove status change to importing

It actually is not used, checked, etc. It makes more sense to me to
remove it than to put it before the transaction.
If the transaction succeeds, we end up with imported. It it fails,
we will still be on staged (which is better than importing).
The job will be marked as failed in that case too.

Note: I am not convinced that this is the definitive solution. This
feels like a workaround. We might still need to dig further.
Are we simply doing too much in this transaction for large staged
imports? Or shouldnt we call Context->dbh constantly in several
subroutines? Is this just a Mariadb bug? No answers yet.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Signed-off-by: Katrin Fischer <katrin.fischer.83@web.de>
Comment 27 Marcel de Rooy 2023-06-26 09:07:58 UTC
(In reply to Nick Clemens from comment #23)
> (In reply to Marcel de Rooy from comment #22)
> > Nick, what did your DBA find ?
> 
> We are still investigating - we have now seen it both in our mariadb
> cluster, and on a local mariadb on a self hosted server
> 
> In both cases the problem is now occurring in _batchCommitItems ->
> AddItemFromMarc -> Koha::Item->store -> Koha::Object->store
> 
> The INSERT call on items is hanging and then failing:
> DBIx::Class::Storage::DBI::_dbh_execute(): DBI Exception: DBD::mysql::st
> execute failed: Lock wait timeout exceeded; try restarting transaction at
> /usr/share/koha/lib/Koha/Object.pm line 170

Thats interesting. Will try to reproduce this first with two processes inserting items.
Comment 28 Marcel de Rooy 2023-06-26 10:09:17 UTC
I came across this remark:

https://stackoverflow.com/questions/64789956/mariadb-innodb-deadlock-while-doing-many-inserts
An InnoDB table with both a PRIMARY KEY and a secondary UNIQUE KEY has a large chance of causing a deadlock. Example of such a case is described clearly in this bug report: https://bugs.mysql.com/bug.php?id=86812

Note that items has PK on itemnumber and UNIQUE key on barcode.
When you temporarily remove the unique constraint, can you still reproduce?
Comment 29 Nick Clemens (kidclamp) 2023-06-26 15:41:33 UTC
We found the issue, it is related to plugins that create their own objects (Curbside is known offender)

The plugins use a trick:
    # register the additional schema classes
    Koha::Schema->register_class(CurbsidePickup => 'Koha::Schema::Result::CurbsidePickup');
    Koha::Schema->register_class(CurbsidePickupPolicy => 'Koha::Schema::Result::CurbsidePickupPolicy');
    Koha::Schema->register_class(CurbsidePickupIssue => 'Koha::Schema::Result::CurbsidePickupIssue');
    # ... and force a refresh of the database handle so that it includes
    # the new classes
    Koha::Database->schema({ new => 1 });
}

That forces a new DB connection - which means the transaction doesn't commit (the savepoint is released, but it is on a different connection, so moot)

The call:
 _after_biblio_action_hooks({ action => 'create', biblio_id => $biblionumber });
calls:
get_enabled_plugins
which calls:
my $plugin = eval { $plugin_class->new() };

which triggers the new schema/connection

when get_enabled_plugins is cached we call $plugin->can($method) which also instantiates the plugin/creates new connection

I think the patches on this report still make sense, they remove an unecessary status change.

We are fixing the plugin, but we probably should update:
https://koha-community.gitlab.io/KohaAdvent/2020-12-07-dbic/

and I think get_enabled_plugins should be using the plugin_methods table to avoid loading plugins that don't have the method we need?
Comment 30 Marcel de Rooy 2023-06-27 11:17:58 UTC
(In reply to Nick Clemens from comment #29)
> We found the issue, it is related to plugins that create their own objects
> (Curbside is known offender)

Great, you catched it. It is always something else ;)
Comment 31 Marcel de Rooy 2023-06-27 11:25:48 UTC
(In reply to Nick Clemens from comment #29)
>     # register the additional schema classes
>     Koha::Schema->register_class(CurbsidePickup =>
> 'Koha::Schema::Result::CurbsidePickup');
[...]
>     Koha::Database->schema({ new => 1 });
> }

If you use these plugins/tables, why not add these classes to the standard schema?

> I think the patches on this report still make sense, they remove an
> unecessary status change.

We dont really need them anymore. No strong opinion on that.

> and I think get_enabled_plugins should be using the plugin_methods table to
> avoid loading plugins that don't have the method we need?

Or just use normal connection or make a different connection later on ?
Comment 32 Marcel de Rooy 2023-06-27 13:04:39 UTC
(In reply to Marcel de Rooy from comment #31)
> (In reply to Nick Clemens from comment #29)
> > I think the patches on this report still make sense, they remove an
> > unecessary status change.
> 
> We dont really need them anymore. No strong opinion on that.

This got enough attention now to push it into the RM queue.
Comment 33 Marcel de Rooy 2023-06-27 13:10:05 UTC
It makes no sense anymore with bug 33987
Comment 34 Nick Clemens (kidclamp) 2023-06-27 13:13:10 UTC
That one deals with import_records updates - this one deals with import_batches - it removes a status change that will never be committed
Comment 35 Marcel de Rooy 2023-06-27 13:18:14 UTC
What happened with:

-    SetImportBatchStatus($batch_id, 'importing');
Comment 36 Marcel de Rooy 2023-06-27 13:23:17 UTC
This needs attention !
Comment 37 Nick Clemens (kidclamp) 2023-06-27 13:27:48 UTC
Created attachment 152738 [details] [review]
Bug 33972: Remove settings of batch status to imorting

This change was done in a transaction - it would either be set as imported
on success, or rolled back to staged on failure

There is no need for the intermediate status which is never committed

Signed-off-by: Nick Clemens <nick@bywatersolutions.com>
Comment 38 Marcel de Rooy 2023-06-27 13:45:16 UTC
Created attachment 152744 [details] [review]
Bug 33972: Remove settings of batch status to importing

This change was done in a transaction - it would either be set as imported
on success, or rolled back to staged on failure

There is no need for the intermediate status which is never committed

Signed-off-by: Nick Clemens <nick@bywatersolutions.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 39 Tomás Cohen Arazi 2023-06-29 14:08:50 UTC
Pushed to master for 23.11.

Nice work everyone, thanks!
Comment 40 Martin Renvoize 2023-07-17 14:47:02 UTC
Thanks for all the hard work!

Pushed to 23.05.x for the next release
Comment 41 Pedro Amorim 2023-07-18 11:54:47 UTC
Nice work everyone!

Pushed to 22.11.x for next release