virtual void MYSQL_BIN_LOG::xlock(): Assertion `!snapshot_lock_acquired' failed in sql/binlog.cc:7566

[Ramesh Sivaraman]

** Testcase

SET @@global.binlog_order_commits = OFF;
START TRANSACTION READ ONLY, WITH CONSISTENT SNAPSHOT; ;

To reproduce the issue we need to run multi thread pquery binary. The attached tarball gives the testcase as an exact match of our system, including some handy utilities
$ vi {epoch}_mybase # Update base path in this file (the only change
required!)
$ ./{epoch}_init # Initializes the data dir
$ ./{epoch}_start # Starts mysqld
$ ./{epoch}_cl # To check mysqld is up
$ ./{epoch}_run_pquery # Run the testcase with pquery binary(produces
output)
$ vi /dev/shm/{epoch}/error.log.out # Verify the error log
$ ./{epoch}_gdb # Brings you to a gdb prompt attached to correct
mysqld
& generated core
$ ./{epoch}_parse_core # Create {epoch}_STD.gdb and {epoch}_FULL.gdb;
standard and full var gdb stack traces
etc.

** Startup

--innodb_track_changed_page --innodb_file_per_table=1 --innodb_flush_method=O_DIRECT --log-bin=binlog --binlog_format=MIXED --event-scheduler=ON --maximum-bulk_insert_buffer_size=1M --maximum-join_buffer_size=1M --maximum-max_heap_table_size=1M --maximum-max_join_size=1M --maximum-myisam_max_sort_file_size=1M --maximum-myisam_mmap_size=1M --maximum-myisam_sort_buffer_size=1M --maximum-optimizer_trace_max_mem_size=1M --maximum-preload_buffer_size=1M --maximum-query_alloc_block_size=1M --maximum-query_prealloc_size=1M --maximum-range_alloc_block_size=1M --maximum-read_buffer_size=1M --maximum-read_rnd_buffer_size=1M --maximum-sort_buffer_size=1M --maximum-tmp_table_size=1M --maximum-transaction_alloc_block_size=1M --maximum-transaction_prealloc_size=1M

** GDB info

#0 0x00007f21ec01b5c9 in raise () from /lib64/libc.so.6
#1 0x00007f21ec01ccd8 in abort () from /lib64/libc.so.6
#2 0x00007f21ec014536 in __assert_fail_base () from /lib64/libc.so.6
#3 0x00007f21ec0145e2 in __assert_fail () from /lib64/libc.so.6
#4 0x0000000000a4deb4 in MYSQL_BIN_LOG::xlock (this=0x18ae3c0 <mysql_bin_log>) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.22-71.0/sql/binlog.cc:7566
#5 0x0000000000641838 in ha_start_consistent_snapshot (thd=0x7f21d4b17000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.22-71.0/sql/handler.cc:2384
#6 0x00000000008b80af in trans_begin (thd=0x7f21d4b17000, flags=3) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.22-71.0/sql/transaction.cc:194
#7 0x00000000007e87c9 in mysql_execute_command (thd=0x7f21d4b17000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.22-71.0/sql/sql_parse.cc:4760
#8 0x00000000007edf41 in mysql_parse (thd=0x7f21d4b17000, rawbuf=0x7f21c901f010 "START TRANSACTION READ ONLY, WITH CONSISTENT SNAPSHOT", length=53, parser_state=0x7f21ebd25df0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.22-71.0/sql/sql_parse.cc:6922
#9 0x00000000007dfdb7 in dispatch_command (command=COM_QUERY, thd=0x7f21d4b17000, packet=0x7f21d4b1f001 "START TRANSACTION READ ONLY, WITH CONSISTENT SNAPSHOT; ;", packet_length=56) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.22-71.0/sql/sql_parse.cc:1434
#10 0x00000000007decd5 in do_command (thd=0x7f21d4b17000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.22-71.0/sql/sql_parse.cc:1051
#11 0x00000000007a6c4d in do_handle_one_connection (thd_arg=0x7f21d4b17000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.22-71.0/sql/sql_connect.cc:1532
#12 0x00000000007a6755 in handle_one_connection (arg=0x7f21d4b17000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.22-71.0/sql/sql_connect.cc:1443
#13 0x0000000000dc9e6c in pfs_spawn_thread (arg=0x7f21e6b46740) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.22-71.0/storage/perfschema/pfs.cc:1860
#14 0x00007f21ed412df3 in start_thread () from /lib64/libpthread.so.0
#15 0x00007f21ec0dc1ad in clone () from /lib64/libc.so.6
(gdb) +set logging off

[Yura Sorokin (yura-sorokin)]

Although I did not manage to reproduce this on 5.6 (commit f3f9359). The potential problem seems to be with the following method in "binlog.cc".

void MYSQL_BIN_LOG::xlock(void)
{
  DBUG_ASSERT(!snapshot_lock_acquired);

  mysql_mutex_lock(&LOCK_log);

  if (opt_binlog_order_commits)
  {
    mysql_mutex_lock(&LOCK_commit);
  }
  else
  {
    snapshot_lock_acquired= true;
    mysql_rwlock_wrlock(&LOCK_consistent_snapshot);
  }
}

One thread may successfully call "xlock()" and set "snapshot_lock_acquired" to "true" whereas another one may call the same "xlock()" method and end up in "DBUG_ASSERT(!snapshot_lock_acquired);" assertion.

The fix would be in putting "DBUG_ASSERT(!snapshot_lock_acquired);" after "mysql_mutex_lock(&LOCK_log);"

[Yura Sorokin (yura-sorokin)]

This is not a bug in the logic. Just incorrect assertion.
The assertion will not be triggered in Release mode.

[Laurynas Biveinis (laurynas-biveinis)]

Yura, please push the one-liner fix. In theory it should be possible to make a DEBUG_SYNC testcase, but I don't think it's worth the effort here

[Yura Sorokin (yura-sorokin)]

https://github.com/percona/percona-server/pull/230

[Roel Van de Paar (roel11)]

Fantastic, thanks Yura

[Shahriyar Rzayev (rzayev-sehriyar)]

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