|
Description
Didier Gautheron
2020-09-14 15:17:16 UTC
I'm more familiar with PostgreSQL deadlocks than MySQL deadlocks, but it looks to me like 2 separate Koha processes are trying to add renewals for different items for the same borrower, and perhaps the lock contention is over the issuesborridx index. Looking at Bug 20086, I see that those are unnecessarily large transactions. It's better to keep transactions as small as possible, especially to avoid scenarios like this. Looking at koha-tmpl/intranet-tmpl/prog/js/checkouts.js, I see that the renewals are POSTed to "/cgi-bin/koha/svc/renew" asynchronously, so that's how there would be multiple AddRenewal transactions running for the same borrower at the same time... Looking at https://dev.mysql.com/doc/refman/8.0/en/innodb-locking.html#innodb-record-locks, I think my theory is correct about the issue being contention over the issuesborridx. Now, I haven't noticed this / haven't gotten any reports of this, but I don't think we really use fines, so this report is interesting. I'm guessing that your renewals must be processed *very* slowly, and that your 2nd transaction is rolled back, because your 1st transaction is taking too long to release a lock on issuesborridx. I'd say the solution is to redo the transaction handling for C4::Circulation::AddRenewal. Didier, do you been able to reproduce this issue in koha-testing-docker? That would help in fixing the problem. I suppose one option would be to do 1 AJAX request with all the information, rather than 1 AJAX request for *each* issue. That would probably cause a performance degradation overall though. I suppose one obvious fix would be changing from UPDATE issues SET date_due = ?, renewals = ?, lastreneweddate = ? WHERE borrowernumber=? AND itemnumber=?" to: UPDATE issues SET date_due = ?, renewals = ?, lastreneweddate = ? WHERE issue_id=?" (In reply to David Cook from comment #1) > I'm more familiar with PostgreSQL deadlocks than MySQL deadlocks, but it > looks to me like 2 separate Koha processes are trying to add renewals for > different items for the same borrower, and perhaps the lock contention is > over the issuesborridx index. > > Looking at Bug 20086, I see that those are unnecessarily large transactions. > It's better to keep transactions as small as possible, especially to avoid > scenarios like this. > > Looking at koha-tmpl/intranet-tmpl/prog/js/checkouts.js, I see that the > renewals are POSTed to "/cgi-bin/koha/svc/renew" asynchronously, so that's > how there would be multiple AddRenewal transactionsissuesborridx running for the same > borrower at the same time... It's also our analysis, there's redundant indexes on issues which may on may not compound the problem. PRIMARY KEY (`issue_id`), UNIQUE KEY `itemnumber` (`itemnumber`), KEY `issuesborridx` (`borrowernumber`), KEY `itemnumber_idx` (`itemnumber`), KEY `branchcode_idx` (`branchcode`), KEY `bordate` (`borrowernumber`,`timestamp`), itemnumber_idx and issuesborridx are redundant. > > Looking at > https://dev.mysql.com/doc/refman/8.0/en/innodb-locking.html#innodb-record- > locks, I think my theory is correct about the issue being contention over > the issuesborridx. > > Now, I haven't noticed this / haven't gotten any reports of this, but I > don't think we really use fines, so this report is interesting. > > I'm guessing that your renewals must be processed *very* slowly, and that > your 2nd transaction is rolled back, because your 1st transaction is taking > too long to release a lock on issuesborridx. > > I'd say the solution is to redo the transaction handling for > C4::Circulation::AddRenewal. I'm not sure block to redo is idempotent... > > Didier, do you been able to reproduce this issue in koha-testing-docker? > That would help in fixing the problem. I'll try, maybe adding a fat sleep(5) in transaction block. (In reply to didier from comment #3) > It's also our analysis, there's redundant indexes on issues which may on may > not compound the problem. > PRIMARY KEY (`issue_id`), > UNIQUE KEY `itemnumber` (`itemnumber`), > KEY `issuesborridx` (`borrowernumber`), > KEY `itemnumber_idx` (`itemnumber`), > KEY `branchcode_idx` (`branchcode`), > KEY `bordate` (`borrowernumber`,`timestamp`), > > itemnumber_idx and issuesborridx are redundant. I doubt that the indexes compound the problem, but I suppose more investigation would be needed. I see that itemnumber_idx is redundant, but how is issuesborridx redundant? It's not the same as bordate. > I'll try, maybe adding a fat sleep(5) in transaction block. Certainly worth experimenting. (In reply to David Cook from comment #4) > > I see that itemnumber_idx is redundant, but how is issuesborridx redundant? > It's not the same as bordate. bordate is a composed index with borrowernumber first and mysql is able to use it for search on borrowernumber only. explain select * from issues where borrowernumber = 3; +------+-------------+--------+------+-----------------------+---------------+---------+-------+------+-------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +------+-------------+--------+------+-----------------------+---------------+---------+-------+------+-------+ | 1 | SIMPLE | issues | ref | issuesborridx,bordate | issuesborridx | 5 | const | 1 | | +------+-------------+--------+------+-----------------------+---------------+---------+-------+------+-------+ drop index issuesborridx on issues; explain select * from issues where borrowernumber = 3; +------+-------------+--------+------+---------------+---------+---------+-------+------+-------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +------+-------------+--------+------+---------------+---------+---------+-------+------+-------+ | 1 | SIMPLE | issues | ref | bordate | bordate | 5 | const | 1 | | +------+-------------+--------+------+---------------+---------+---------+-------+------+-------+ > > > I'll try, maybe adding a fat sleep(5) in transaction block. > > Certainly worth experimenting. I did it but was unable to reproduce the deadlock even with a sleep(5) and 8 concurrent plack workers. (In reply to didier from comment #5) > (In reply to David Cook from comment #4) > > > > I see that itemnumber_idx is redundant, but how is issuesborridx redundant? > > It's not the same as bordate. > bordate is a composed index with borrowernumber first and mysql is able to > use it for search on borrowernumber only. That's interesting! I've had mixed experiences (with PostgreSQL) with composite indexes being used when searching for only part of the index. I hadn't thought about column order, but maybe that explains some of my experiences. Food for thought! > > > I'll try, maybe adding a fat sleep(5) in transaction block. > > > > Certainly worth experimenting. > I did it but was unable to reproduce the deadlock even with a sleep(5) and 8 > concurrent plack workers. How many renewals did you try to do? I figure if you have maybe 32+ renewals and the browser does about 8 requests in parallel, maybe you'd be able to reproduce it with that. (In reply to David Cook from comment #6) > How many renewals did you try to do? I figure if you have maybe 32+ renewals > and the browser does about 8 requests in parallel, maybe you'd be able to > reproduce it with that. 8 or 9 so there was 8 requests in parallel. (In reply to didier from comment #7) > 8 or 9 so there was 8 requests in parallel. Hmm and did they have all fine generation? I keep thinking that has to be part of it, as I haven't noticed any deadlock issues, but we don't use fines typically. (In reply to David Cook from comment #8) > (In reply to didier from comment #7) > > 8 or 9 so there was 8 requests in parallel. > > Hmm and did they have all fine generation? I keep thinking that has to be > part of it, as I haven't noticed any deadlock issues, but we don't use fines > typically. As far I can tell they don't fine overdue. If you want to fix that you should follow what is done in C4::Circulation::SendCirculationAlert (In reply to Jonathan Druart from comment #10) > If you want to fix that you should follow what is done in > C4::Circulation::SendCirculationAlert Reading the other comments, maybe this is not needed. I've tried hard to recreate the problem but failed (ktd).
40 plack workers, limit 50 renewals
I created a bunch of checkouts for a given patron:
use Koha::Items;
use C4::Circulation;
use t::lib::Mocks;
my $items = Koha::Items->search();
my $patron = Koha::Patrons->find(51);
t::lib::Mocks::mock_userenv({ patron => $patron });
while ( my $item = $items->next ) {
C4::Circulation::AddIssue($patron->unblessed, $item->barcode);
}
Then opened 5 tabs /cgi-bin/koha/circ/circulation.pl?borrowernumber=51
And click "Renewal all" as soon as I could.
Everything got renewed correctly.
Hi, Thanks for looking at it. We have a second library with the same issue, but they have only issuesborridx. we are using nginx and mariadb mysql --version mysql Ver 15.1 Distrib 10.4.13-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2 Investigating this, as near as I can tell it only occurs during 'Renew all' when too many processes hit the server at once. I cannot recreate locally, but can verify on larger active koha instances The renewals silently fail and the user is never notified leading to problems later. We have other issues from the multiple concurrent renewals, see bug 26208 I attached a patch there to perform the actions serially which I believe will mitigate this issue It would be good to have more data from real life examples. (In reply to David Cook from comment #15) > It would be good to have more data from real life examples. From the access logs, there are three requests with the same timestamp: somesite.bywatersolutions.com:80 IP.IP.IP.IP - - [30/Nov/2020:16:02:14 -0700] "POST /cgi-bin/koha/svc/renew HTTP/1.1" 200 349 "https://staff.somesite.bywatersolutions.com/cgi-bin/koha/circ/circulation.pl?borrowernumber=250710" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.198 Safari/537.36" somesite.bywatersolutions.com:80 IP.IP.IP.IP - - [30/Nov/2020:16:02:14 -0700] "POST /cgi-bin/koha/svc/renew HTTP/1.1" 200 350 "https://staff.somesite.bywatersolutions.com/cgi-bin/koha/circ/circulation.pl?borrowernumber=250710" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.198 Safari/537.36" somesite.bywatersolutions.com:80 IP.IP.IP.IP - - [30/Nov/2020:16:02:14 -0700] "POST /cgi-bin/koha/svc/renew HTTP/1.1" 200 349 "https://staff.somesite.bywatersolutions.com/cgi-bin/koha/circ/circulation.pl?borrowernumber=250710" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.198 Safari/537.36" In the plack log: DBD::mysql::st execute failed: Deadlock found when trying to get lock; try restarting transaction [for Statement "UPDATE issues SET date_due = ?, renewals = ?, lastreneweddate = ? WHERE borrowernumber=? AND itemnumber=?" with ParamValues: 0='2020-12-30 23:59', 1=1, 2=DateTime=HASH(0x5561e7d4fb08), 3="borrowernumber", 4="itemnumber"] at /usr/share/koha/lib/C4/Circulation.pm line 2964. In the action_logs: *************************** 15. row *************************** action_id: 10050103 timestamp: 2020-11-30 16:02:14 user: staff_borrowernumber module: CIRCULATION action: RENEWAL object: borrowernumber info: itemnumber interface: intranet Statistics: *************************** 19. row *************************** datetime: 2020-11-30 16:02:14 branch: BRANCH value: 0.0000 type: renew other: itemnumber: itemnumber itemtype: BOOK location: ADULT borrowernumber: borrowernumber ccode: FICTION Issues table: *************************** 1. row *************************** Table: issues Create Table: CREATE TABLE `issues` ( `issue_id` int(11) NOT NULL AUTO_INCREMENT, `borrowernumber` int(11) NOT NULL, `itemnumber` int(11) NOT NULL, `date_due` datetime DEFAULT NULL, `branchcode` varchar(10) COLLATE utf8mb4_unicode_ci DEFAULT NULL, `returndate` datetime DEFAULT NULL, `lastreneweddate` datetime DEFAULT NULL, `renewals` tinyint(4) NOT NULL DEFAULT '0', `auto_renew` tinyint(1) DEFAULT '0', `auto_renew_error` varchar(32) COLLATE utf8mb4_unicode_ci DEFAULT NULL, `timestamp` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP, `issuedate` datetime DEFAULT NULL, `onsite_checkout` int(1) NOT NULL DEFAULT '0', `note` longtext COLLATE utf8mb4_unicode_ci, `notedate` datetime DEFAULT NULL, `noteseen` int(1) DEFAULT NULL, PRIMARY KEY (`issue_id`), KEY `issuesborridx` (`borrowernumber`), KEY `bordate` (`borrowernumber`,`timestamp`), KEY `itemnumber_idx` (`itemnumber`), KEY `branchcode_idx` (`branchcode`), CONSTRAINT `issues_ibfk_1` FOREIGN KEY (`borrowernumber`) REFERENCES `borrowers` (`borrowernumber`) ON UPDATE CASCADE, CONSTRAINT `issues_ibfk_2` FOREIGN KEY (`itemnumber`) REFERENCES `items` (`itemnumber`) ON UPDATE CASCADE ) ENGINE=InnoDB AUTO_INCREMENT=increment DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci Server version: 10.1.47-MariaDB-0+deb9u1 Debian 9.13 Koha 19.1108000 Created attachment 114184 [details] [review] Bug 26457: Throw exception if update of issues table fails While this won't prevent the deadlock, it should catch the case where a deadlock causes the DB update to fail and provide feedback to the user and rollback the transaction I don't know how to trigger the deadlock, I can only confirm that we see it, and that this should catch it. To test: 1 - Apply patches 2 - Confirm that 'Renew all' feature continues to work as expected Created attachment 114185 [details] [review] Bug 26457: Throw exception if update of issues table fails While this won't prevent the deadlock, it should catch the case where a deadlock causes the DB update to fail and provide feedback to the user and rollback the transaction I don't know how to trigger the deadlock, I can only confirm that we see it, and that this should catch it. To test: 1 - Apply patches 2 - Confirm that 'Renew all' feature continues to work as expected Created attachment 114186 [details] [review] Bug 26457: Throw exception if update of issues table fails While this won't prevent the deadlock, it should catch the case where a deadlock causes the DB update to fail and provide feedback to the user and rollback the transaction I don't know how to trigger the deadlock, I can only confirm that we see it, and that this should catch it. To test: 1 - Apply patches 2 - Confirm that 'Renew all' feature continues to work as expected Created attachment 114187 [details] [review] Bug 26457: Throw exception if update of issues table fails While this won't prevent the deadlock, it should catch the case where a deadlock causes the DB update to fail and provide feedback to the user and rollback the transaction I don't know how to trigger the deadlock, I can only confirm that we see it, and that this should catch it. To test: 1 - Apply patches 2 - Confirm that 'Renew all' feature continues to work as expected Created attachment 114190 [details] [review] Bug 26457: Throw exception if update of issues table fails While this won't prevent the deadlock, it should catch the case where a deadlock causes the DB update to fail and provide feedback to the user and rollback the transaction I don't know how to trigger the deadlock, I can only confirm that we see it, and that this should catch it. To test: 1 - Apply patches 2 - Confirm that 'Renew all' feature continues to work as expected Could you provide a test? Thanks for the info, Nick. And yeah I think throwing an exception is a good immediate improvement. Looking at Bug 20086, I think that we're trying to do way too much in 1 database transaction. I've seen this on other systems with a lot of concurrent activity, and debugging these deadlocks is a struggle. The AddRenewal function is a bit of a mess in general... After applying the patch , while restarting the services, I have a compilation issue.
root@kohadevbox:koha((6982680ae9...))$ restart_all
Restarting Apache httpd web server: apache2.
Restarting Koha ILS: koha-commonStopping Plack daemon for kohadev:.
Stopping Z39.50/SRU daemon for kohadev:.
Stopping Koha worker daemon for kohadev:.
Stopping Koha indexing daemon for kohadev:.
Starting Plack daemon for kohadev:.
Starting Z39.50/SRU daemon for kohadev:syntax error at /kohadevbox/koha/C4/Circulation.pm line 3091, near "->errstr;"
Type of arg 1 to List::MoreUtils::any must be block or sub {} (not reference constructor) at /kohadevbox/koha/C4/Circulation.pm line 4397, near "} )"
Type of arg 1 to List::MoreUtils::any must be block or sub {} (not reference constructor) at /kohadevbox/koha/C4/Circulation.pm line 4400, near "}) "
> 2 - Confirm that 'Renew all' feature continues to work as expected
Is testing the "Renew all" button in a patron's checkout list enough?
Created attachment 114669 [details] [review] Bug 26457: Throw exception if update of issues table fails While this won't prevent the deadlock, it should catch the case where a deadlock causes the DB update to fail and provide feedback to the user and rollback the transaction I don't know how to trigger the deadlock, I can only confirm that we see it, and that this should catch it. To test: 1 - Apply patches 2 - Checkout several items to a patron 3 - Confirm that 'Renew all' feature continues to work as expected and all items are renewed (In reply to Jonathan Druart from comment #22) > Could you provide a test? I have tried, but it seems it requires a lot of mocking and I have not been successful, help would be appreciated :-) (In reply to Nick Clemens from comment #26) > (In reply to Jonathan Druart from comment #22) > > Could you provide a test? > > I have tried, but it seems it requires a lot of mocking and I have not been > successful, help would be appreciated :-) Couldn't you add a unit test for AddRenewal that just puts in junk data to trigger the exception? Created attachment 114697 [details] [review] Bug 26457: Unit test (In reply to David Cook from comment #27) > (In reply to Nick Clemens from comment #26) > > (In reply to Jonathan Druart from comment #22) > > > Could you provide a test? > > > > I have tried, but it seems it requires a lot of mocking and I have not been > > successful, help would be appreciated :-) > > Couldn't you add a unit test for AddRenewal that just puts in junk data to > trigger the exception? Indeed I can! Turns out we pass 'lastreneweddate' right through, so adding junk data in the call lets us trigger the exception Created attachment 117227 [details] [review] Bug 26457: Throw exception if update of issues table fails While this won't prevent the deadlock, it should catch the case where a deadlock causes the DB update to fail and provide feedback to the user and rollback the transaction I don't know how to trigger the deadlock, I can only confirm that we see it, and that this should catch it. To test: 1 - Apply patches 2 - Checkout several items to a patron 3 - Confirm that 'Renew all' feature continues to work as expected and all items are renewed Signed-off-by: David Nind <david@davidnind.com> Created attachment 117228 [details] [review] Bug 26457: Unit test Signed-off-by: David Nind <david@davidnind.com> Tested by: - Following test plan (checking out 11 items to a patron, renewing all items 5 times) - Running prove t/db_dependent/Circulation.t (all tests pass) QAing Created attachment 117371 [details] [review] Bug 26457: Throw exception if update of issues table fails While this won't prevent the deadlock, it should catch the case where a deadlock causes the DB update to fail and provide feedback to the user and rollback the transaction I don't know how to trigger the deadlock, I can only confirm that we see it, and that this should catch it. To test: 1 - Apply patches 2 - Checkout several items to a patron 3 - Confirm that 'Renew all' feature continues to work as expected and all items are renewed Signed-off-by: David Nind <david@davidnind.com> Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> Created attachment 117372 [details] [review] Bug 26457: Unit test Signed-off-by: David Nind <david@davidnind.com> Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> Created attachment 117373 [details] [review] Bug 26457: (QA follow-up) Switch to PK index in UPDATE on issues The deadlock reports tell us that multiple transactions are waiting for a X lock on a record but using a secondary index on borrowernumber and itemnumber. Since we have the issue_id at hand already, we should use that and benefit from the clustered index (on PK) instead of using a secondary index. Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> Just for completeness, from sql man: To avoid deadlocks when performing multiple concurrent write operations on a single InnoDB table, acquire necessary locks at the start of the transaction by issuing a SELECT ... FOR UPDATE statement for each group of rows expected to be modified, even if the data change statements come later in the transaction. Pushed to master for 21.05, thanks to everybody involved! Pushed to 20.11.x for 20.11.04 Doesn't apply cleanly to 20.05. Thought I'd cleared merge errors, but ended up with an error when trying to restart services:
Global symbol "$unseen_renewals" requires explicit package name (did you forget to declare "my $unseen_renewals"?) at /kohadevbox/koha/C4/Circulation.pm line 2977.
Type of arg 1 to List::MoreUtils::any must be block or sub {} (not reference constructor) at /kohadevbox/koha/C4/Circulation.pm line 4213, near "} )"
Type of arg 1 to List::MoreUtils::any must be block or sub {} (not reference constructor) at /kohadevbox/koha/C4/Circulation.pm line 4216, near "}) "
Please rebase for backport.
Created attachment 117876 [details] [review] Bug 26457: [20.05.x] Throw exception if update of issues table fails While this won't prevent the deadlock, it should catch the case where a deadlock causes the DB update to fail and provide feedback to the user and rollback the transaction I don't know how to trigger the deadlock, I can only confirm that we see it, and that this should catch it. To test: 1 - Apply patches 2 - Checkout several items to a patron 3 - Confirm that 'Renew all' feature continues to work as expected and all items are renewed Signed-off-by: David Nind <david@davidnind.com> Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> Bug 26457: Unit test Signed-off-by: David Nind <david@davidnind.com> Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> Bug 26457: (QA follow-up) Switch to PK index in UPDATE on issues The deadlock reports tell us that multiple transactions are waiting for a X lock on a record but using a secondary index on borrowernumber and itemnumber. Since we have the issue_id at hand already, we should use that and benefit from the clustered index (on PK) instead of using a secondary index. Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> Pushed to 20.05.x for 20.05.10 Issue when trying to backport to 19.11.x, failing test.
kohadev-koha@be9bfe372adf:/kohadevbox/koha$ prove t/db_dependent/Circulation.t
t/db_dependent/Circulation.t .. 40/47 DBD::mysql::st execute failed: Incorrect datetime value: 'HASH(0x562f3aaf8048)' for column 'lastreneweddate' at row 1 [for Statement "UPDATE issues SET date_due = ?, renewals = ?, lastreneweddate = ? WHERE issue_id = ?" with ParamValues: 0='2021-04-12 23:59', 1=1, 2=HASH(0x562f3aaf8048), 3=264] at /kohadevbox/koha/C4/Circulation.pm line 2969.
# No tests run!
t/db_dependent/Circulation.t .. 42/47
# Failed test 'No tests run for subtest "AddRenewal and AddIssuingCharge tests"'
# at t/db_dependent/Circulation.t line 3201.
Update of issue# 264 failed with error: Incorrect datetime value: 'HASH(0x562f3aaf8048)' for column 'lastreneweddate' at row 1# Looks like your test exited with 255 just after 42.
The conflicts weren't tricky to solve and I don't see how the patch affects lastreneweddate.
So help needed for backporting to 19.11.x
Created attachment 118647 [details] [review] Bug 26457: [19.11.x] Throw exception if update of issues table fails While this won't prevent the deadlock, it should catch the case where a deadlock causes the DB update to fail and provide feedback to the user and rollback the transaction I don't know how to trigger the deadlock, I can only confirm that we see it, and that this should catch it. To test: 1 - Apply patches 2 - Checkout several items to a patron 3 - Confirm that 'Renew all' feature continues to work as expected and all items are renewed Signed-off-by: David Nind <david@davidnind.com> Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> Bug 26457: Unit test Signed-off-by: David Nind <david@davidnind.com> Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> Bug 26457: (QA follow-up) Switch to PK index in UPDATE on issues The deadlock reports tell us that multiple transactions are waiting for a X lock on a record but using a secondary index on borrowernumber and itemnumber. Since we have the issue_id at hand already, we should use that and benefit from the clustered index (on PK) instead of using a secondary index. Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> I had a try with the conflict on 19.11, can you test this patch? Thanks a lot Jonathan, it works! :D Backported: Pushed to 19.11.x branch for 19.11.16 *** Bug 29650 has been marked as a duplicate of this bug. *** |