Bug #75782 Failing assertion: trx->read_only && trx->auto_commit && trx->isolation_level==1
Submitted: 5 Feb 2015 3:23 Modified: 20 May 2015 18:32
Reporter: Roel Van de Paar (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S6 (Debug Builds)
Version:5.7.5-m15 OS:Any
Assigned to: CPU Architecture:Any
Triage: Needs Triage: D1 (Critical)

[5 Feb 2015 3:23] Roel Van de Paar
Description:
2015-02-05 14:07:57 0x7f76274ac700  InnoDB: Assertion failure in thread 140145442080512 in file trx0trx.cc line 1270
InnoDB: Failing assertion: trx->read_only && trx->auto_commit && trx->isolation_level == 1

[...]

(gdb) bt
#0  0x00007fe20efbd771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000e15d58 in my_write_core (sig=6) at /bzr/mysql-5.7-percona-patches_dbg/mysys/stacktrace.c:247
#2  0x0000000000822044 in handle_fatal_signal (sig=6) at /bzr/mysql-5.7-percona-patches_dbg/sql/signal_handler.cc:219
#3  <signal handler called>
#4  0x00007fe20dbc15c9 in raise () from /lib64/libc.so.6
#5  0x00007fe20dbc2cd8 in abort () from /lib64/libc.so.6
#6  0x00000000010d4ccf in ut_dbg_assertion_failed (expr=0x14e8448 "trx->read_only && trx->auto_commit && trx->isolation_level == 1", file=0x14e7870 "/bzr/mysql-5.7-percona-patches_dbg/storage/innobase/trx/trx0trx.cc", line=1270) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/ut/ut0dbg.cc:68
#7  0x00000000010c1818 in trx_start_low (trx=0x7fe1e9c00c90, read_write=true) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/trx/trx0trx.cc:1269
#8  0x00000000010c55e0 in trx_start_internal_low (trx=0x7fe1e9c00c90) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/trx/trx0trx.cc:3012
#9  0x0000000001197483 in dict_stats_fetch_from_ps (table=0x7fe1d711d598) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/dict/dict0stats.cc:2919
#10 0x0000000001197cb1 in dict_stats_update (table=0x7fe1ef3b0c98, stats_upd_option=DICT_STATS_FETCH_ONLY_IF_NOT_IN_MEMORY) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/dict/dict0stats.cc:3201
#11 0x0000000000f084ae in dict_stats_init (table=0x7fe1ef3b0c98) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/include/dict0stats.ic:173
#12 0x0000000000f0e859 in ha_innobase::open (this=0x7fe1d5ede420, name=0x7fe1d72c9390 "./test/t3", mode=2, test_if_locked=2) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/handler/ha_innodb.cc:5098
#13 0x0000000000880baf in handler::ha_open (this=0x7fe1d5ede420, table_arg=0x7fe1d721ec10, name=0x7fe1d72c9390 "./test/t3", mode=2, test_if_locked=2) at /bzr/mysql-5.7-percona-patches_dbg/sql/handler.cc:2471
#14 0x0000000000c179e0 in open_table_from_share (thd=0x7fe1d701c000, share=0x7fe1d72c9020, alias=0x7fe1d7028ae8 "t3", db_stat=39, prgflag=44, ha_open_flags=0, outparam=0x7fe1d721ec10, is_create_table=false) at /bzr/mysql-5.7-percona-patches_dbg/sql/table.cc:2378
#15 0x0000000000acafb7 in open_table (thd=0x7fe1d701c000, table_list=0x7fe1d734e020, ot_ctx=0x7fe20f572a40) at /bzr/mysql-5.7-percona-patches_dbg/sql/sql_base.cc:3417
#16 0x0000000000acd770 in open_and_process_table (thd=0x7fe1d701c000, lex=0x7fe1d701e370, tables=0x7fe1d734e020, counter=0x7fe1d701e420, flags=0, prelocking_strategy=0x7fe20f572b40, has_prelocking_list=false, ot_ctx=0x7fe20f572a40) at /bzr/mysql-5.7-percona-patches_dbg/sql/sql_base.cc:4903
#17 0x0000000000ace4fe in open_tables (thd=0x7fe1d701c000, start=0x7fe20f572b00, counter=0x7fe1d701e420, flags=0, prelocking_strategy=0x7fe20f572b40) at /bzr/mysql-5.7-percona-patches_dbg/sql/sql_base.cc:5357
#18 0x0000000000acf745 in open_normal_and_derived_tables (thd=0x7fe1d701c000, tables=0x7fe1d7028558, flags=0) at /bzr/mysql-5.7-percona-patches_dbg/sql/sql_base.cc:6085
#19 0x0000000000b4ecca in execute_sqlcom_select (thd=0x7fe1d701c000, all_tables=0x7fe1d7028558) at /bzr/mysql-5.7-percona-patches_dbg/sql/sql_parse.cc:5004
#20 0x0000000000b47775 in mysql_execute_command (thd=0x7fe1d701c000) at /bzr/mysql-5.7-percona-patches_dbg/sql/sql_parse.cc:2488
#21 0x0000000000b4fcc1 in mysql_parse (thd=0x7fe1d701c000, parser_state=0x7fe20f573e60) at /bzr/mysql-5.7-percona-patches_dbg/sql/sql_parse.cc:5427
#22 0x0000000000b44814 in dispatch_command (command=COM_QUERY, thd=0x7fe1d701c000, packet=0x7fe1d7033011 "SELECT t1.c1,t3.c1 FROM t1 NATURAL RIGHT JOIN t3  WHERE t1.c1 <=> 5;", packet_length=68) at /bzr/mysql-5.7-percona-patches_dbg/sql/sql_parse.cc:1250
#23 0x0000000000b4354d in do_command (thd=0x7fe1d701c000) at /bzr/mysql-5.7-percona-patches_dbg/sql/sql_parse.cc:834
#24 0x0000000000c4d49e in handle_connection (arg=0x7fe1f0fffee0) at /bzr/mysql-5.7-percona-patches_dbg/sql/conn_handler/connection_handler_per_thread.cc:298
#25 0x0000000000e39538 in pfs_spawn_thread (arg=0x7fe1f17f70d0) at /bzr/mysql-5.7-percona-patches_dbg/storage/perfschema/pfs.cc:2137
#26 0x00007fe20efb8df3 in start_thread () from /lib64/libpthread.so.0
#27 0x00007fe20dc821ad in clone () from /lib64/libc.so.6

How to repeat:
This bug is extremely hard to reproduce. The attached scripts will make it semi-easy, but expect to see some hacky methods employed (you'll see lot of unrelated errors both in the error log and in pquery output...)

$ 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
$ while(true); do ./1422600023_run_pquery; done
  # This runs the testcase in a loop. Expect to see lots of unrelated errors (Error 1040: Too many connections/double free or corruption/trying to destroy uninialized mutex/invalid next size/segmentation faults/Aborts/... and so on). Ignore them all. ** Watch/wait ** for the occurence of "Error 2002: Can't connect to local MySQL server through socket '/dev/shm/1422600023/socket.sock' (111)" - maybe quickly, maybe after a while - it will scroll very fast over the screen (much faster then other original errors):

===================
Error 2002: Can't connect to local MySQL server through socket '/dev/shm/1422600023/socket.sock' (111)
* PQUERY: Unable to continue [2], exiting
Executing testcase ./1422600023.sql against mysqld with socket /dev/shm/1422600023/socket.sock using pquery...
Infile is ./1422600023.sql
Database is test
Starting with 300 threads
Query limit per thread is 100000
User is root
Socket is /dev/shm/1422600023/socket.sock
Error 2002: Can't connect to local MySQL server through socket '/dev/shm/1422600023/socket.sock' (111)
===================

 - This is your sign that the mysqld server is gone/has crashed. Press CTRL+C and review error log/gdb to confirm.
$ 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.
[5 Feb 2015 3:23] Roel Van de Paar
Stopping the while() loop a few times with CTRL+C and restarting may also aid reproduction.
[5 Feb 2015 3:31] Roel Van de Paar
Tarball with all scripts required

Attachment: bug_75782.tar.gz (application/gzip, text), 93.78 KiB.

[9 Feb 2015 20:27] Sveta Smirnova
Thank you for the report.

Verified as described.

To repeat report I had to modify paths in the scripts provided to reflect them my environment, change export LD_LIBRARY_PATH=$(cat ${SCRIPT_PWD}/1422600023_mybase)/lib to export LD_LIBRARY_PATH=$(cat ${SCRIPT_PWD}/1422600023_mybase)/lib:$LD_LIBRARY_PATH in 1422600023_run_pquery , so my custom LD_LIBRARY_PATH still works and re-compile pquery, taken from http://bazaar.launchpad.net/~percona-core/percona-qa/trunk/files

Also I had to run test for 3 hours before crash occurred.
[9 Feb 2015 20:30] Sveta Smirnova
Posted by developer:
 
I have different back trace:

2015-02-09 21:19:27 0x50c39940  InnoDB: Assertion failure in thread 1354996032 in file ha_innodb.cc line 3537
InnoDB: Failing assertion: !trx_is_started(trx)
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
20:19:27 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=152
max_threads=151
thread_count=152
connection_count=152
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 68128 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x2aaab83c6000
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 50c39010 thread_stack 0x40000
/home/ssmirnov/blade12/build/mysql-trunk/bin/mysqld(my_print_stacktrace+0x35)[0x13c15e0]
/home/ssmirnov/blade12/build/mysql-trunk/bin/mysqld(handle_fatal_signal+0x405)[0xbc523c]
/lib64/libpthread.so.0[0x2aca340aebe0]
/lib64/libc.so.6(gsignal+0x35)[0x2aca3530b285]
/lib64/libc.so.6(abort+0x110)[0x2aca3530cd30]
/home/ssmirnov/blade12/build/mysql-trunk/bin/mysqld[0x15df5f7]
/home/ssmirnov/blade12/build/mysql-trunk/bin/mysqld[0x13e8fc5]
/home/ssmirnov/blade12/build/mysql-trunk/bin/mysqld[0xc25f4e]
/home/ssmirnov/blade12/build/mysql-trunk/bin/mysqld(_Z24plugin_foreach_with_maskP3THDPFcS0_PP13st_plugin_intPvEijS4_+0x333)[0x10e9fc5]
/home/ssmirnov/blade12/build/mysql-trunk/bin/mysqld(_Z28ha_start_consistent_snapshotP3THD+0x34)[0xc25f90]
/home/ssmirnov/blade12/build/mysql-trunk/bin/mysqld(_Z11trans_beginP3THDj+0x3d0)[0x11b1383]
/home/ssmirnov/blade12/build/mysql-trunk/bin/mysqld(_Z21mysql_execute_commandP3THD+0x4da3)[0x10be064]
/home/ssmirnov/blade12/build/mysql-trunk/bin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x54a)[0x10c16db]
/home/ssmirnov/blade12/build/mysql-trunk/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcm+0xfd8)[0x10b7045]
/home/ssmirnov/blade12/build/mysql-trunk/bin/mysqld(_Z10do_commandP3THD+0x362)[0x10b5b57]
/home/ssmirnov/blade12/build/mysql-trunk/bin/mysqld(handle_connection+0x1b9)[0x11db03c]
/home/ssmirnov/blade12/build/mysql-trunk/bin/mysqld(pfs_spawn_thread+0x15a)[0x175019c]
/lib64/libpthread.so.0[0x2aca340a677d]
/lib64/libc.so.6(clone+0x6d)[0x2aca353aec1d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (2aaab83cf020): START TRANSACTION WITH CONSISTENT SNAPSHOT
Connection ID (thread ID): 83905
Status: NOT_KILLED

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
Writing a core file
[19 Feb 2015 7:11] Naga Satyanarayana Bodapati
Posted by developer:
 
From the bug reporter stack trace, it looks like

1. attachable trx is started
2. trx->is_dd_trx is set
3. trx returns to pool without clearing the is_dd_trx flag <--- Bug probably here
4. Some other thread(dict stats thread in this case) requesting trx, got the trx which is earlier used for attachable trx
5. Assertion raised because of left over flag trx->is_dd_trx
[19 Feb 2015 7:32] Naga Satyanarayana Bodapati
Posted by developer:
 
I was wrong, We do have a assertion to make sure trx->is_dd_trx is set to false before returning the trx to pool.

in
trx_free(trx_t*& trx)
{
...
  ut_ad(trx->is_dd_trx == false);
...
}

So there is some mystery around this
[23 Feb 2015 9:46] Naga Satyanarayana Bodapati
On Ctrl-C pquery is crashing frequently :)

(gdb) bt
#0  0x00007f5b490d4cc9 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1  0x00007f5b490d80d8 in __GI_abort () at abort.c:89
#2  0x00007f5b49111f24 in __libc_message (do_abort=do_abort@entry=1, fmt=fmt@entry=0x7f5b492206c8 "*** Error in `%s': %s: 0x%s ***\n") at ../sysdeps/posix/libc_fatal.c:175
#3  0x00007f5b4911e1fe in malloc_printerr (ptr=<optimized out>, str=0x7f5b492207b0 "double free or corruption (!prev)", action=1) at malloc.c:4996
#4  _int_free (av=<optimized out>, p=<optimized out>, have_lock=0) at malloc.c:3840
#5  0x00007f5b49cd6a3b in my_once_free () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18
#6  0x00007f5b49cd5ebd in my_end () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18
#7  0x00007f5b49cb1f07 in mysql_server_end () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18
#8  0x0000000000403674 in executor (number=261, qlist=...) at pquery.cpp:83
#9  0x00007f5b49a31bf0 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#10 0x00007f5b48e88182 in start_thread (arg=0x7f5a4672c700) at pthread_create.c:312
#11 0x00007f5b4919900d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
[24 Feb 2015 12:42] Naga Satyanarayana Bodapati
Posted by developer:
 
Am not able to reproduce :(
[24 Feb 2015 12:45] Naga Satyanarayana Bodapati
I have few questions to the bug reporter:

1) Is it possible to compile pquery with gcc-4.4?
2) Is it possible to fix the pquery crash(not important, it may help)
3) Is it possible to get minimum sequence of queries in .sql to reproduce the crash? (similar to RQG simplifier)
[24 Feb 2015 12:46] Naga Satyanarayana Bodapati
Setting the status to Need Feedback to get attention
[24 Feb 2015 18:19] Sveta Smirnova
Naga,

I waited 3 hours for crash to occur.

Regarding to q.1 - yes, it is possible: just download sources from Launchpad repo, modify paths and compile the tool. Building is not automated, but it is possible. Ping me if you need help.
[25 Feb 2015 5:41] Naga Satyanarayana Bodapati
Sveta,

gcc-4.4 doesn't support the option -std=gnu++11

I've tried on my laptop and pquery completes its run successfully. At the end it prints summary

Also, the assert you have got is different from the assert reported by bug reporter.
[25 Mar 2015 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".
[27 Mar 2015 5:46] Naga Satyanarayana Bodapati
Using the sql provided and pumping that SQL using multiple threads, we are able to reproduce the bug.
[27 Mar 2015 6:13] Roel Van de Paar
Very nice Naga! Very appreciated too. 

We are in the process of building 3 new pquery binaries (oracle/maria/percona), so there is no more lib issues (and hopefully no more of the issues you saw). More on this on the Percona blog when it's released.
[1 Apr 2015 0:21] Roel Van de Paar
Small update, not directly related to bug, pquery binaries are as good as ready, and we also resolved a memory bug, which may have been the one you were seeing. So hopefully reproduction issues like the one seen in this bug are a thing of the past.
[20 May 2015 18:32] Daniel Price
Posted by developer:
 
Fixed as of the upcoming 5.7.8, 5.8.0 releases, and here's the changelog entry:

Attempting to kill statements that use attachable transactions caused
subsequent statements to function improperly, resulting in assertion
failures. A "max_statement_time" timeout on such statements could produce
a similar outcome. 

Thanks for the bug report.