tbpl gets deadlocks setting last_activity_ts (Deadlock found when trying to get lock; try restarting transaction [for Statement "UPDATE profiles SET last_activity_ts = ? WHERE userid = ?"])

RESOLVED FIXED

Status

()

defect
RESOLVED FIXED
6 years ago
6 years ago

People

(Reporter: philor, Assigned: glob)

Tracking

Production
x86
macOS
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment)

+++ This bug was initially created as a clone of Bug #909278 +++

tbpl sez: "Bugzilla error submitting bug comment: DBD::mysql::db do failed: Deadlock found when trying to get lock; try restarting transaction [for Statement "UPDATE profiles SET last_activity_ts = ? WHERE userid = ?"] at /data/www/bugzilla.mozilla.org/extensions/UserProfile/Extension.pm line 42."

Comment added to bug 910486 comment 25 at 2013-09-04 09:12:12 PDT, but no comment added to bug 901908.
(In reply to Phil Ringnalda (:philor) from comment #0)
> no comment added to bug 901908.

what time did this error happen, and was it the same message?
that error is absent from our error log :(
Assignee: nobody → glob
And indeed intermittent, I starred the same two failures (near-permaorange is handy!) at 09:25:03 without error and got comments added to both bugs.
The same time and that is the single message - I'm not sure whether or not this is the only case where tbpl is hitting this problem (another likely case is where more than one of us is starring things at the same time), but in this case a single build run has two failures that are two separate bugs, so the person using tbpl tells tbpl to add comments to both of those bugs.
So, in checking this out via deadlock errors I found the below.

In layman's terms: query (1) and query (2) are identical, and started at the exact same time. 1 ran, 2 deadlocked off of 1, and in the long run it was successful, but it was somehow executed twice (causing the deadlock).

------------------------
LATEST DETECTED DEADLOCK
------------------------
130904  9:19:31
*** (1) TRANSACTION:
TRANSACTION C6DCC890, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 9 lock struct(s), heap size 1248, 4 row lock(s), undo log entries 2
MySQL thread id 46726132, OS thread handle 0x7f0d397e0700, query id 1198190742 10.22.70.209 bugs Updating
UPDATE profiles SET last_activity_ts = '2013-09-04 09:19:31' WHERE userid = '379349'
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 385 page no 4102 n bits 192 index `PRIMARY` of table `bugs`.`profiles` trx id C6DCC890 lock_mode X locks rec but not gap waiting
*** (2) TRANSACTION:
TRANSACTION C6DCC891, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
9 lock struct(s), heap size 1248, 4 row lock(s), undo log entries 2
MySQL thread id 46726134, OS thread handle 0x7f0d3a9d7700, query id 1198190744 10.22.70.209 bugs Updating
UPDATE profiles SET last_activity_ts = '2013-09-04 09:19:31' WHERE userid = '379349'
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 385 page no 4102 n bits 192 index `PRIMARY` of table `bugs`.`profiles` trx id C6DCC891 lock mode S locks rec but not gap
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 385 page no 4102 n bits 192 index `PRIMARY` of table `bugs`.`profiles` trx id C6DCC891 lock_mode X locks rec but not gap waiting
*** WE ROLL BACK TRANSACTION (2)
from bugzilla's perspective, tbpl updated both bugs in a single xmlrpc Bug.update call.


i'm thinking of adding another table which stores a list of users that we should re-calculate their last_activity_ts as part of the nightly run.

wrap the UPDATE statement in an eval block, and if it fails insert a row into the recalc table with the user-id.  if the UPDATE was successful, delete the user from that table.

this means the last_activity_ts may be incorrect until the next successful update, or until the nightly cronjob is executed.  i don't think this is a problem worth worrying about.
BzAPI must batch its calls, then, since from tbpl's perspective the browser client did two separate XHR POSTs to tbpl.m.o/php/submitBugzillaComment.php, and the two instances of that did separate curl POSTs to api-dev.b.m.o.
Attachment #800662 - Flags: review?(dkl)
Comment on attachment 800662 [details] [diff] [review]
912564_1.patch

Review of attachment 800662 [details] [diff] [review]:
-----------------------------------------------------------------

You also need the eval when updating an attachment as well.

@@ -153,7 +190,14 @@
         # if an attachment is created or updated, that counts as user activity
         my $user = Bugzilla->user;
         my $timestamp = Bugzilla->dbh->selectrow_array('SELECT LOCALTIMESTAMP(0)');
-        $user->set_last_activity_ts($timestamp);
+        eval {
+            $user->set_last_activity_ts($timestamp);
+            $self->_recalc_remove($user);
+        };
+        if ($@) {
+            warn $@;
+            $self->_recalc_insert($user);
+        }
         $user->update();
     }
     elsif ($object->isa('Bugzilla::Product') && exists $args->{changes}->{name}) {

Nit: Not related to this patch, I don't think $user->update is necessary. 

Otherwise looks/works good. r=dkl As you already know we will need to do a two stage push for the schema change.

dkl
Attachment #800662 - Flags: review?(dkl) → review+
schema-only:
Committing to: bzr+ssh://bjones%40mozilla.com@bzr.mozilla.org/bmo/4.2/
modified extensions/UserProfile/Extension.pm
Committed revision 8988.
Committing to: bzr+ssh://bjones%40mozilla.com@bzr.mozilla.org/bmo/4.2/
modified extensions/UserProfile/Extension.pm
modified extensions/UserProfile/bin/update.pl
Committed revision 8994.
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.