runJobs returns Error: 1213 Deadlock found when trying to get lock during SMW::writePropertyTableRowUpdates-delete

[jthingelstad]

I’m currently running f4782a8 (few days old) and I've seen fairly random deadlock errors coming from my cron-based runJobs.php call. The error is

A database query error has occurred.
Query: DELETE FROM `smw_di_time` WHERE (s_id='835742' AND ((p_id = '63' AND o_serialized = '1/2014/2/27/18/51/41' AND o_sortkey = '2456716.2858912') OR (p_id = '105604' AND o_serialized = '1/2014/2/13/20/49/53' AND o_sortkey = '2456702.3679745') OR (p_id = '265041' AND o_serialized = '1/2013/6/3/20/57/30' AND o_sortkey = '2456447.3732639') OR (p_id = '699064' AND o_serialized = '1/2014/1/31/16/51/28' AND o_sortkey = '2456689.2024074')))
Function: SMW::writePropertyTableRowUpdates-delete-smw_di_time
Error: 1213 Deadlock found when trying to get lock; try restarting transaction

A database query error has occurred.
Query: DELETE FROM `smw_di_blob` WHERE (s_id='278253' AND ((p_id = '86' AND o_blob IS NULL AND o_hash = ' 1.23wmf14') OR (p_id = '263036' AND o_blob IS NULL AND o_hash = 'e50919a6345e0abe8e0f19c922871adcc611b166')))
Function: SMW::writePropertyTableRowUpdates-delete-smw_di_blob
Error: 1213 Deadlock found when trying to get lock; try restarting transaction

I haven't seen this error before. I haven't debugged this, but I’m seeing about 3-8 of them a day under normal usage. I wanted to note it in this issue. I’m going to update to newest commit and we'll see if they persist.

[mwjames]

I've never seen those before but it would be interesting if the entries correlate with those that show double entries.

I’m going to update to newest commit and we'll see if they persist.

No one has work on the SQLStore writer code for ages, I would be surprised if it were to disappear.

Some issues found in relation with MW and Error: 1213 Deadlock found when trying to get lock

• http://wikimedia.7.x6.nabble.com/Database-returned-error-quot-1213-quot-td4998163.html
• http://comments.gmane.org/gmane.org.wikimedia.mediawiki.bugs/390662
• http://comments.gmane.org/gmane.org.wikimedia.mediawiki.bugs/400193
• http://comments.gmane.org/gmane.org.wikimedia.mediawiki.bugs/394737

@JeroenDeDauw Any idea what Error: 1213 Deadlock found when trying to get lock; try restarting transaction means in MW terms?

[jthingelstad]

Tests of these two reveal no duplicates. Interesting idea though.

[JeroenDeDauw]

I don't know about this error... Though if people already ran into it with 1.7.2, than we know it is at least not yet another SQLStore3 regression.

[jthingelstad]

This is continuing to happen. There seems to have been some change since I don't recall every seeing one of these messages before about 2 weeks ago. I’m continuing to see a couple a day.

A database query error has occurred.
Query: DELETE FROM `smw_di_time` WHERE (s_id='294889' AND ((p_id = '63' AND o_serialized = '1/2014/2/28/21/37/50' AND o_sortkey = '2456717.4012731') OR (p_id = '105604' AND o_serialized = '1/2014/2/3/0/0/9' AND o_sortkey = '2456691.5001042')))
Function: SMW::writePropertyTableRowUpdates-delete-smw_di_time
Error: 1213 Deadlock found when trying to get lock; try restarting transaction

I’m not sure how to even start with debugging this. :-\

[JeroenDeDauw]

Increase is frequency might be caused by additional jobs @mwjames added

[mwjames]

Increase is frequency might be caused by additional jobs

Unless you have set the following configuration, no additional jobs are created because #204 and #152 have neither been merged nor implemented.

$GLOBALS['smwgOnDeleteAction'] = array(
    'smwgDeleteSubjectAsDeferredJob' => true,
    'smwgDeleteSubjectWithAssociatesRefresh' => true
);

There seems to have been some change since I don't recall every seeing one of these messages

The class that reports the problem SMW_SQLStore3_Writers.php have been changed only on Jan 12, 2014 which added a comment and Sep 19, 2013.

What means "Error: 1213 Deadlock found when trying to get lock" ?

Query: DELETE FROM smw_di_time WHERE

It is a native DB message where the writer class invokes $db = wfGetDB( DB_MASTER ); directly.

Since it is coming from the MW DB (or MySQL), I'm not really sure what it actually means but looking at bugzilla, wikibase had once a similar message which they resolved by using something like $dbw->deadlockLoop( ... ).

Not knowing what "Deadlock found" really means I looked for some hints and saw a comment from Aaron Schulz which states that

Deadlocks do occur in general from time to time. Unless they are common, it is not an issue.

or Niklas Laxström that

This error occasionally comes up in translatewiki.net and wmf, but it is relatively rare. I don't have ideas how to go forward with this.

MW release

Can the start of the occurrence correlate with an update to an MW release/patch?

[mwjames]

I’m not sure how to even start with debugging this. :-\

We need a stack trace, so when running runJobs it can tell us something about the origin of the deadlock.

[mwjames]

DatabaseBase::deadlockLoop

According to classDatabaseBase:

Perform a deadlock-prone transaction. This function invokes a callback function to perform a set of write queries. If a deadlock occurs during the processing, the transaction will be rolled back and the callback function will be called again.

See also the search results on deadlockLoop within MW.

[mwjames]

Another possibility is that if configurations like wgDevelopmentWarnings, wgShowExceptionDetails or wgShowDBErrorBacktrace are changed that we see an increase in reporting details for messages that were hidden before.

[mwjames]

More research on the deadlock topic with MySQL explaining:

Deadlocks are a classic problem in transactional databases, but they are not dangerous unless they are so frequent that you cannot run certain transactions at all. Normally, you must write your applications so that they are always prepared to re-issue a transaction if it gets rolled back because of a deadlock.

As noted earlier, the SQLStore currently does not make use of DatabaseBase::deadlockLoop and therefore is prone to deadlocks when being executed within another transaction.

[JeroenDeDauw]

@thingles I take it this no longer occurs?

[mwjames]

While the cause is still unclear, we hope by facilitating the DeferrableUpdate (#1435) that DB lock issues are less unlikely.