Bug #66402 Thread locks itself out with semaphore (crash)
Submitted: 15 Aug 2012 16:14 Modified: 28 Mar 2014 20:25
Reporter: Trey Raymond Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:5.5.21-55-log Percona OS:Linux
Assigned to: CPU Architecture:Any
Tags: crash, Semaphore

[15 Aug 2012 16:14] Trey Raymond
Description:
Server crashes itself due to long semaphore wait.  upon reading the log, it appears that a thread seems to have blocked itself, see below (see full output in log i will attach).  This happened once before.  It's using native AIO on an ext2 filesystem (I know, ext* sucks, but that's what it is) and I feel that may be related, even though status shows no pending IO, though it is supposedly supported without a problem...it just seems odd to me, and everything else on this looks fine.

Debian 6.0.5
16G ram, 8G buffer pool
240G ext2 partition

--Thread 140132563724032 has waited at btr0sea.c line 1939 for 926.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x10954328 'btr_search_latch_part[i]'
a writer (thread id 140132563724032) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0cur.c line 855
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.21-rel25.0/storage/innobase/btr/bt

which corresponds to this transaction

---TRANSACTION 53A23594, ACTIVE 926 sec updating or deleting
mysql tables in use 1, locked 1
2 lock struct(s), heap size 376, 1 row lock(s), undo log entries 1
MySQL thread id 64283, OS thread handle 0x7f7327aea700, query id 311598109 10.0.113.13 fppuser Updating
UPDATE
    ChatroomOnlineUser
  SET  
    LastPingedDateTime = NOW()
  WHERE
    ChatroomId =  NAME_CONST('IPChatroomId',1)
  AND
    ApplicationUserId =  NAME_CONST('IPUserId',163172)
TABLE LOCK table `dating`.`ChatroomOnlineUser` trx id 53A23594 lock mode IX
RECORD LOCKS space id 92418 page no 3 n bits 112 index `PRIMARY` of table `dating`.`ChatroomOnlineUser` trx id 53A23594 lock_mode X locks rec but not gap

this is an update on a small table (a dozen rows) that has primary key (chartoomid,applicationuserid) so it's a const,const lookup.  the table has three surrogate keys, non unique.

other examples:

--Thread 140122784970496 has waited at btr0cur.c line 2019 for 926.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x10955678 'btr_search_latch_part[i]'
a writer (thread id 140122784970496) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.c line 918
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.21-rel25.0/storage/innobase/btr/bt

--Thread 140122785974016 has waited at btr0sea.c line 669 for 923.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x10952fd8 'btr_search_latch_part[i]'
a writer (thread id 140122785974016) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.c line 918
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.21-rel25.0/storage/innobase/btr/bt

matching trx for these threads were not in output

How to repeat:
would seem difficult to do so.  something makes these pile up, it's happened twice now.

Suggested fix:
find out why it's blocking itself and other threads
[15 Aug 2012 16:15] Trey Raymond
error log

Attachment: bruno.log (application/octet-stream, text), 56.39 KiB.

[15 Aug 2012 16:15] Trey Raymond
global status (lots of spin waits)

Attachment: bruno.sts (application/octet-stream, text), 9.66 KiB.

[15 Aug 2012 16:15] Trey Raymond
global variables

Attachment: bruno.var (application/octet-stream, text), 10.56 KiB.

[19 Aug 2012 10:11] Valeriy Kravchuk
Please, check if this problem ever happens with a recent version from Oracle, 5.5.27.
[20 Aug 2012 19:35] Trey Raymond
I will try upgrading and watching, but there's no easy way to trigger the fault where I could test it.  However, I've gone over the change logs thoroughly, and seen nothing that might address this in any way.
[30 Aug 2012 17:59] MySQL Verification Team
Are you tried 5.5.27 and repeated the crash?. Thanks.
[3 Sep 2012 18:52] Trey Raymond
As mentioned earlier, it's impossible to trigger it, it has happened sporadically.  What bug fix in the change log do you suspect fixed it?  Nothing stood out to me.
[7 Sep 2012 18:27] Sveta Smirnova
Thank you for the feedback.

Well, any InnoDB lock bug fix can fix this issue. Also we need you to test with Oracle's MySQL, because Percona introduces own changes into InnoDB code and we should be sure problem happened in Oracle's part.
[12 Sep 2012 22:04] Trey Raymond
bug hasn't recurred yet on either the prod install or an identical test host with an up to date oracle-provided package, there's no way I've found to trigger it as mentioned earlier, but clearly something is going wrong with the locks.
[12 Sep 2012 22:50] Sveta Smirnova
Thank you for the update.

Please reopen bug when you meet same issue with latest Oracle MySQL.
[13 Oct 2012 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".
[25 Jan 2013 7:55] Laurynas Biveinis
Trey -

Should you ever again experience this crash, please report it on bugs.percona.com if you are using Percona Server, or here if you are using Oracle MySQL. Thanks.
[26 Feb 2013 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".
[26 Feb 2014 9:29] Serge Rivest
Experiencing the same problem here with 5.5.27. See innodb dump, I'll attach the file.
[26 Feb 2014 9:31] Serge Rivest
Massive pile up of threads that self-lock

Attachment: innodb-status (1).log.gz (application/x-gzip, text), 2.30 MiB.

[28 Feb 2014 20:25] Sveta Smirnova
Thank you for the feedback.

Please provide output of SHOW CREATE TABLE for tables teacher_class_activity, r.result, r.activity, a_session, a_data, ce_fulltext_search_log, student_flag, teacher_badges, l_certificate_download, a_reset, student_last_results, student_trial_activities, m_tracking, feedback, accounts_session, accounts_data, m_amazonses_bounced, student_access, parent_link_request, a_autoauth
[1 Apr 2014 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".