InnoDB failing debug assertion: lock->high_priority_wait_ex_waiter == 0 in priority rw_lock_x_unlock_func

[Ramesh Sivaraman]

========================= Error log:
2014-07-02 00:15:16 15569 [Warning] InnoDB: Setting thread 15593 nice to -8 failed, current nice 14, errno 13
2014-07-02 00:16:19 7ff5c7ffe700 InnoDB: Assertion failure in thread 140693599151872 in file sync0rw.ic line 750
InnoDB: Failing assertion: lock->high_priority_wait_ex_waiter == 0
InnoDB: We intentionally generate a memory trap.
--
--
/lib64/libc.so.6(clone+0x6d)[0x7ff605ec394d]
You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server/. You may find information
in the manual which will help you identify the cause of the crash.
Writing a core file

========================= gdb :
+bt
#0 0x00007ff60715e69c in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000000aab116 in my_write_core (sig=6) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/my
sys/stacktrace.c:422
#2 0x0000000000727fc6 in handle_fatal_signal (sig=6) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-6
7.0/sql/signal_handler.cc:254
#3 <signal handler called>
#4 0x00007ff605e0d8e5 in raise () from /lib64/libc.so.6
#5 0x00007ff605e0f0c5 in abort () from /lib64/libc.so.6
#6 0x0000000000ce14d0 in rw_lock_x_unlock_func (pass=0, lock=0x7ff605024578) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64
/percona-server-5.6.19-67.0/storage/innobase/include/sync0rw.ic:750
#7 0x0000000000ce1845 in pfs_rw_lock_x_unlock_func (pass=0, lock=0x7ff605024578) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos
6-64/percona-server-5.6.19-67.0/storage/innobase/include/sync0rw.ic:1200
#8 0x0000000000ce6ed7 in btr_search_info_update_slow (info=0x7ff56804bd50, cursor=0x7ff5de3d53d0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/btr/btr0sea.cc:709
#9 0x0000000000ccee51 in btr_search_info_update (index=0x7ff568061378, cursor=0x7ff5de3d53d0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/include/btr0sea.ic:81
#10 0x0000000000cd1117 in btr_cur_search_to_nth_level (index=0x7ff568061378, level=0, tuple=0x7ff5bfc3c4f0, mode=4, latch_mode=2, cursor=0x7ff5de3d53d0, has_search_latch=0, file=0x107db68 "/mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/row/row0row.cc", line=734, mtr=0x7ff5c7ffd680) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/btr/btr0cur.cc:871
#11 0x0000000000c351d9 in btr_pcur_open_low (index=0x7ff568061378, level=0, tuple=0x7ff5bfc3c4f0, mode=4, latch_mode=2, cursor=0x7ff5de3d53d0, file=0x107db68 "/mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/row/row0row.cc", line=734, mtr=0x7ff5c7ffd680) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/include/btr0pcur.ic:440
#12 0x0000000000c36d27 in row_search_on_row_ref (pcur=0x7ff5de3d53d0, mode=2, table=0x7ff568038978, ref=0x7ff5bfc3c4f0, mtr=0x7ff5c7ffd680) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/row/row0row.cc:734
#13 0x0000000000c3006e in row_purge_reposition_pcur (mode=2, node=0x7ff5de3d5338, mtr=0x7ff5c7ffd680) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/row/row0purge.cc:105
#14 0x0000000000c3017c in row_purge_remove_clust_if_poss_low (node=0x7ff5de3d5338, mode=2) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/row/row0purge.cc:144
#15 0x0000000000c30362 in row_purge_remove_clust_if_poss (node=0x7ff5de3d5338) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/row/row0purge.cc:202
#16 0x0000000000c30b85 in row_purge_del_mark (node=0x7ff5de3d5338) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/row/row0purge.cc:539
#17 0x0000000000c313e7 in row_purge_record_func (node=0x7ff5de3d5338, undo_rec=0x7ff5bfc3c468 "#\346\016\\\020", thr=0x7ff5de3d5278, updated_extern=false) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/row/row0purge.cc:806
#18 0x0000000000c31618 in row_purge (node=0x7ff5de3d5338, undo_rec=0x7ff5bfc3c468 "#\346\016\\\020", thr=0x7ff5de3d5278) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/row/row0purge.cc:862
#19 0x0000000000c318fe in row_purge_step (thr=0x7ff5de3d5278) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/row/row0purge.cc:942
#20 0x0000000000bd0196 in que_thr_step (thr=0x7ff5de3d5278) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/que/que0que.cc:1115
#21 0x0000000000bd03bb in que_run_threads_low (thr=0x7ff5de3d5278) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/que/que0que.cc:1177
#22 0x0000000000bd058a in que_run_threads (thr=0x7ff5de3d5278) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/que/que0que.cc:1218
#23 0x0000000000c80df5 in trx_purge (n_purge_threads=6, batch_size=300, truncate=false) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/trx/trx0purge.cc:1251
#24 0x0000000000c65744 in srv_do_purge (n_threads=6, n_total_purged=0x7ff5c7ffde18) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/srv/srv0srv.cc:3217
#25 0x0000000000c65ea6 in srv_purge_coordinator_thread (arg=0x0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/srv/srv0srv.cc:3401
#26 0x00007ff607159851 in start_thread () from /lib64/libpthread.so.0
#27 0x00007ff605ec394d in clone () from /lib64/libc.so.6
(gdb) +set logging off

========================= Run details:

[ramesh@hppro1 BUNDLE_309]$ cat cmd309
if [ -r /usr/lib64/libjemalloc.so.1 ]; then export LD_PRELOAD=/usr/lib64/libjemalloc.so.1
elif [ -r /usr/lib/x86_64-linux-gnu/libjemalloc.so.1 ]; then export LD_PRELOAD=/usr/lib/x86_64-linux-gnu/libjemalloc.so.1
else echo 'Error: jemalloc not found, please install it first'; exit 1; fi
ps -ef | grep 'rundir1_309' | grep -v grep | awk '{print $2}' | xargs sudo kill -9 > /dev/null 2>&1
rm -Rf /ssd/qa56dbg/40/rundir1_309
rm -Rf /ssd/qa56dbg/40/rundir1_309_epoch
mkdir /ssd/qa56dbg/40/rundir1_309
mkdir /ssd/qa56dbg/40/rundir1_309_epoch
cd /data/bench/qa56dbg/randgen
bash -c "set -o pipefail; perl /data/bench/qa56dbg/randgen/runall.pl --queries=100000000 --seed=908 --duration=300 --querytimeout=60 --short_column_names --reporter=Shutdown,Backtrace,QueryTimeout,ErrorLog,ErrorLogAlarm --mysqld=--log-output=none --mysqld=--sql_mode=ONLY_FULL_GROUP_BY --mysqld=--plugin-load=tokudb=ha_tokudb.so --mysqld=--init-file=/data/bench/qa56dbg/randgen/conf/percona_qa/5.6/TokuDB.sql --mysqld=--utility-user-password=test --grammar=conf/percona_qa/5.6/5.6.yy --gendata=conf/percona_qa/5.6/5.6.zz1 --threads=15 --no-mask --basedir=/ssd/qa56dbg/Percona-Server-5.6.19-rel67.0-618.Linux.x86_64-debug --notnull --mysqld=--innodb_changed_pages=FORCE --mysqld=--innodb_fast_shutdown=2 --mysqld=--innodb_flush_log_at_trx_commit=0 --mysqld=--innodb_flush_method=O_DIRECT --mysqld=--innodb_log_arch_dir=/ssd/qa56dbg/40/rundir1_309_epoch --mysqld=--innodb_log_archive=1 --mysqld=--innodb_log_block_size=512 --mysqld=--innodb_log_buffer_size=1048577 --mysqld=--innodb_log_file_size=10485761 --mysqld=--innodb_log_files_in_group=2 --mysqld=--innodb_log_group_home_dir=/ssd/qa56dbg/40/rundir1_309_epoch --mysqld=--innodb_max_changed_pages=0 --mysqld=--innodb_track_changed_pages=1 --mysqld=--innodb_use_global_flush_log_at_trx_commit=0 --mysqld=--innodb-buffer-pool-populate --mysqld=--loose-readonly-key-cache-division-limit=0 --mysqld=--readonly-key-cache-block-size=0 --mysqld=--readonly-loose-max-connect-errors=1 --mysqld=--slow_query_log --mysqld=--userstat --mysqld=--utility-user=roel@% --mysqld=--utility-user-password=test --mysqld=--utility-user-schema-access=mysqlinformation_schema --mysqld=--innodb_purge_threads=6 --mysqld=--innodb_adaptive_hash_index_partitions=1 --mysqld=--innodb_buffer_pool_instances=8 --mtr-build-thread=762 --mask=30454 --vardir1=/ssd/qa56dbg/40/rundir1_309 > /ssd/qa56dbg/40/cmd309.log 2>&1"
tail -n1 /ssd/qa56dbg/40/cmd309.log
[ramesh@hppro1 BUNDLE_309]$

========================= version:
Server : 618 <email address hidden>
RQG : 973 <email address hidden>

[Laurynas Biveinis (laurynas-biveinis)]

Thread 74 (Thread 0x7ff607793700 (LWP 17466)):
+bt
#0 0x00007ff60715d43c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x0000000000b9e729 in os_cond_wait (cond=0x7ff5de59f1c0, fast_mutex=0x7ff5de59f180) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/os/os0sync.cc:214
#2 0x0000000000b9ec99 in os_event_wait_low (event=0x7ff5de59f180, reset_sig_count=48) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/os/os0sync.cc:610
#3 0x0000000000c6e25a in sync_array_wait_event (arr=0x7ff5e93fb900, index=4) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/sync/sync0arr.cc:433
#4 0x0000000000c714aa in rw_lock_x_lock_func (lock=0x7ff605024578, pass=0, file_name=0x10aaf60 "/mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/btr/btr0sea.cc", line=1653, priority_lock=true, high_priority=false) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/sync/sync0rw.cc:876
#5 0x0000000000c71531 in rw_lock_x_lock_func (lock=0x7ff605024578, pass=0, file_name=0x10aaf60 "/mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/btr/btr0sea.cc", line=1653) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/sync/sync0rw.cc:908
#6 0x0000000000ce16dc in pfs_rw_lock_x_lock_func (lock=0x7ff605024578, pass=0, file_name=0x10aaf60 "/mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/btr/btr0sea.cc", line=1653) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/include/sync0rw.ic:925

Thread 1 (Thread 0x7ff5c7ffe700 (LWP 15593)):
+bt
#0 0x00007ff60715e69c in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000000aab116 in my_write_core (sig=6) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/mysys/stacktrace.c:422
#2 0x0000000000727fc6 in handle_fatal_signal (sig=6) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/sql/signal_handler.cc:254
#3 <signal handler called>
#4 0x00007ff605e0d8e5 in raise () from /lib64/libc.so.6
#5 0x00007ff605e0f0c5 in abort () from /lib64/libc.so.6
#6 0x0000000000ce14d0 in rw_lock_x_unlock_func (pass=0, lock=0x7ff605024578) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/include/sync0rw.ic:750
#7 0x0000000000ce1845 in pfs_rw_lock_x_unlock_func (pass=0, lock=0x7ff605024578) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/include/sync0rw.ic:1200

[Laurynas Biveinis (laurynas-biveinis)]

This is caused by rw_lock_x_lock_wait with high_priority == true
entering the while (lock->lock_word < 0) loop, setting
high_priority_wait_ex_waiter, still observing lock_word < 0 at the
next if statement, sleeping, wakeing up, and optionally repeating the
while loop iteration until lock_word == 0 is observed at the while
(but not the inner if) statement.

This results in a correctly X locked latch (but with spuriously set
waiters flag). Then, if no S unlock happens (which would clear the
flag and raise its event spuriously) until the next X unlock, this
assert fires.

[Laurynas Biveinis (laurynas-biveinis)]

The previous comment on spurious event raise is incorrect. The flag does not decide which events are fired, the lock word value does. The flag value only decides whether low priority lock requests should yield because there exists a high priority waiter.

[Shahriyar Rzayev (rzayev-sehriyar)]

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