InnoDB: Failing assertion: mutex_get_lock_word(mutex) == 0 in file sync0sync.cc line 369 | abort (sig=6) in mutex_free_func (from threadpool_remove_connection)

[Roel Van de Paar]

2013-12-07 08:59:51 7997 [Note] /ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld: ready for connections.
Version: '5.6.14-rel62.0-debug-log' socket: '/ssd/262479/current1_2/tmp/master.sock' port: 13020 Percona Server with XtraDB (GPL), Release rel62.0, Revision508-debug
2013-12-07 09:01:09 7f10704e0700 InnoDB: Assertion failure in thread 139708580366080 in file sync0sync.cc line 369
InnoDB: Failing assertion: mutex_get_lock_word(mutex) == 0

Thread 1 (LWP 8217):
+bt
#0 0x000000362fa0c69c in pthread_kill () from /lib64/libpthread.so.0
#1 0x00000000006a649f in handle_fatal_signal (sig=6) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/signal_handler.cc:254
#2 <signal handler called>
#3 0x000000362f2328e5 in raise () from /lib64/libc.so.6
#4 0x000000362f2340c5 in abort () from /lib64/libc.so.6
#5 0x0000000000afc693 in mutex_free_func (mutex=mutex@entry=0x7f0fd4000a90) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/storage/innobase/sync/sync0sync.cc:369
#6 0x0000000000b1b034 in pfs_mutex_free_func (mutex=0x7f0fd4000a90) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/storage/innobase/include/sync0sync.ic:568
#7 trx_free_low (trx=trx@entry=0x7f0fd4000a88) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/storage/innobase/trx/trx0trx.cc:384
#8 0x0000000000b1ee0c in trx_free (trx=0x7f0fd4000a88) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/storage/innobase/trx/trx0trx.cc:403
#9 trx_free_for_background (trx=trx@entry=0x7f0fd4000a88) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/storage/innobase/trx/trx0trx.cc:455
#10 0x0000000000b1f674 in trx_free_for_mysql (trx=trx@entry=0x7f0fd4000a88) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/storage/innobase/trx/trx0trx.cc:514
#11 0x00000000009d4ffe in innobase_close_connection (hton=<optimized out>, thd=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/storage/innobase/handler/ha_innodb.cc:4307
#12 0x00000000005df7c1 in closecon_handlerton (thd=thd@entry=0x3d4c500, plugin=plugin@entry=0x7f10704dfb58, unused=unused@entry=0x0) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/handler.cc:873
#13 0x000000000073f4dd in plugin_foreach_with_mask (thd=thd@entry=0x3d4c500, func=func@entry=0x5df770 <closecon_handlerton(THD*, plugin_ref, void*)>, type=type@entry=1, state_mask=4294967287, state_mask@entry=8, arg=arg@entry=0x0) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/sql_plugin.cc:2094
#14 0x00000000005e172e in ha_close_connection (thd=thd@entry=0x3d4c500) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/handler.cc:887
#15 0x00000000006fdcdf in THD::release_resources (this=this@entry=0x3d4c500) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/sql_class.cc:1746
#16 0x00000000007d7532 in threadpool_remove_connection (thd=0x3d4c500) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/threadpool_common.cc:251
#17 0x00000000007d87ac in connection_abort (connection=0x3bca450) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/threadpool_unix.cc:1278
#18 handle_event (connection=0x3bca450) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/threadpool_unix.cc:1479
#19 worker_main (param=param@entry=0x153cc00 <all_groups+1536>) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/threadpool_unix.cc:1521
#20 0x00000000009bbd73 in pfs_spawn_thread (arg=0x7f0ffc0302a0) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/storage/perfschema/pfs.cc:1858
#21 0x000000362fa07851 in start_thread () from /lib64/libpthread.so.0
#22 0x000000362f2e894d in clone () from /lib64/libc.so.6

[Roel Van de Paar (roel11)]

PS @ 508 <email address hidden>
RQG @ 940 <email address hidden>

[Laurynas Biveinis (laurynas-biveinis)]

Appears to be a threadpool-specific race condition between some trx->mutex locking thread and Thread 1. The mutex was already unlocked by the time assert crashes:

(gdb) print mutex->lock_word
$3 = 0 '\000'

thus the other racing thread has already advanced away from trx->mutex critical section, and I don't see any of the other threads still working with trx at 0x7f0fd4000a90.

It is not clear why Thread 1 chose to call connection_abort(), i.e. which one of threadpool_process_request() and start_io() calls returned err != 0 and why.

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.5 because there has been no activity for 60 days.]

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-747