Assertion failure in thread 140433424082688 in file ha_innodb.cc line 6207 | prebuilt->trx->conc_state == 1 | prebuilt->trx->state == 1 (in case of PS)

Bug #1208921 reported by Raghavendra D Prabhu
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
MySQL Server
Unknown
Unknown
MySQL patches by Codership
New
Undecided
Unassigned
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
High
Unassigned
5.1
Won't Fix
Undecided
Unassigned
5.5
Fix Released
High
Unassigned
5.6
Fix Released
High
Unassigned
Percona XtraDB Cluster moved to https://jira.percona.com/projects/PXC
Status tracked in 5.6
5.5
Fix Committed
High
Unassigned
5.6
Fix Committed
High
Unassigned

Bug Description

Repeatable with RQG with galera grammar:

# 2013-08-06T22:18:31 [41182] Killing remaining worker process with pid 41740...
# 2013-08-06T22:18:31 [41182] Killing remaining worker process with pid 41732...
# 2013-08-06T22:18:31 [41182] Killing remaining worker process with pid 41753...
# 2013-08-06T22:18:31 [41182] Killing remaining worker process with pid 41751...
# 2013-08-06T22:18:31 [41182] Killing remaining worker process with pid 41749...
# 2013-08-06T22:18:31 [41182] Killing remaining worker process with pid 41730...
# 2013-08-06T22:18:31 [41182] Killing remaining worker process with pid 41728...
# 2013-08-06T22:18:31 [41182] Killing remaining worker process with pid 41757...
# 2013-08-06T22:18:32 [41182] Killing periodic reporting process with pid 41727...
# 2013-08-06T22:18:32 [41182] Kill GenTest::ErrorFilter(41726)
# 2013-08-06T22:18:32 [41182] Server crash reported, initiating post-crash analysis...
# 2013-08-06T22:18:32 [41182] The last 100 lines from /chip/mysql-test/var/node0/data//../mysql.err :
130806 22:18:24 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:24 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:25 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:25 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:28 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:28 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:28 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:28 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:28 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:28 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:28 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:28 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:28 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:28 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:28 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:28 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:28 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:28 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:30 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:30 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:30 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:30 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:30 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:30 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:30 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:30 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:30 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:30 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:30 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:30 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:31 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:31 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:31 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:31 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:31 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:31 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:31 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:31 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:31 [ERROR] /chip/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:31 [ERROR] /chip/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130806 22:18:31 InnoDB: Assertion failure in thread 140433424082688 in file ha_innodb.cc line 6207
InnoDB: Failing assertion: prebuilt->trx->conc_state == 1
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.5/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
16:48:31 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.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.

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

Thread pointer: 0x28cc5a0
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 = 7fb9345b5e68 thread_stack 0x40000
/chip/bin/mysqld(my_print_stacktrace+0x2c)[0x8007ca]
/chip/bin/mysqld(handle_fatal_signal+0x2f9)[0x6c256d]
/usr/lib/libpthread.so.0(+0xf0e0)[0x7fb946c310e0]
/usr/lib/libc.so.6(gsignal+0x39)[0x7fb9453e01c9]
/usr/lib/libc.so.6(abort+0x148)[0x7fb9453e15c8]
/chip/bin/mysqld[0x815a1b]
/chip/bin/mysqld(_ZN12ha_partition10unlock_rowEv+0x4a)[0xa1774e]
/chip/bin/mysqld(_Z8filesortP3THDP5TABLEP13st_sort_fieldjP10SQL_SELECTybPy+0x1af6)[0x6c1483]
/chip/bin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyy+0x808)[0x7b76ab]
/chip/bin/mysqld(_Z21mysql_execute_commandP3THD+0x34a8)[0x59ff10]
/chip/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x142)[0x5a52e8]
/chip/bin/mysqld[0x5a5dfb]
/chip/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x994)[0x5a6d02]
/chip/bin/mysqld(_Z10do_commandP3THD+0x679)[0x5a8bd3]
/chip/bin/mysqld(_Z24do_handle_one_connectionP3THD+0x13a)[0x64fbfd]
/chip/bin/mysqld(handle_one_connection+0x49)[0x64fded]
/usr/lib/libpthread.so.0(+0x7dd2)[0x7fb946c29dd2]
/usr/lib/libc.so.6(clone+0x6d)[0x7fb945490cdd]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7fb900004c10): DELETE IGNORE FROM `table10000_innodb_key_pk_parts_2_int` WHERE `col_char_12_key` IN ( SELECT `col_char_12_key` FROM `table1_innodb_int` WHERE `pk` = 0 ) ORDER BY `col_char_12`,`col_char_12_key`,`col_int`,`col_int_key`,`pk` LIMIT 3
Connection ID (thread ID): 10
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
# 2013-08-06T22:18:32 [41182] datadir is /chip/mysql-test/var/node0/data/
# 2013-08-06T22:18:32 [41182] binary is /chip/../chip/bin/mysqld
# 2013-08-06T22:18:32 [41182] bindir is /chip/../chip/bin
# 2013-08-06T22:18:32 [41182] WARNING: Core file not found!
"/media/Tintin/Work/code/randgen/mariadb-patches" is not a core dump: Is a directory
backtrace.gdb:19: Error in sourced command file:
No stack.
# 2013-08-06T22:18:33 [41182] Whether to confirm potentially dangerous operations is on.
"/media/Tintin/Work/code/randgen/mariadb-patches" is not a core dump: Is a directory
# 2013-08-06T22:18:33 [41182] Whether to confirm potentially dangerous operations is on.
# 2013-08-06T22:18:33 [41182] Test completed with failure status STATUS_SERVER_CRASHED (101)
# 2013-08-06T22:18:33 [41182] GenTest exited with exit status STATUS_SERVER_CRASHED (101)
# 2013-08-06T22:18:33 [41182] Stopping server on port 19300
# 2013-08-06T22:18:33 [41182] Stale connection. Reconnecting
# 2013-08-06T22:18:33 [41182] Reconnect failed due to 2003:Can't connect to MySQL server on '127.0.0.1' (111)
# 2013-08-06T22:18:33 [41182] Server would not shut down properly. Terminate it
# 2013-08-06T22:18:33 [41182] Terminated process 41533
# 2013-08-06T22:18:33 [41182] Stopping server on port 19301
# 2013-08-06T22:18:33 [41182] Stale connection. Reconnecting
# 2013-08-06T22:18:33 [41182] [41182] runall-new.pl will exit with exit status STATUS_SERVER_CRASHED (101)

Cmdline:

perl runall-new.pl --basedir=/chip --galera=ms --grammar=$PWD/conf/galera/galera_stress.yy --gendata=$PWD/conf/galera/galera_stress.zz --threads=10 --queries=1000000 --mysqld=--wsrep-provider=/pxc/lib/libgalera_smm.so

The galera grammar from:
bzr+ssh://bazaar.launchpad.net/~elenst/randgen/mariadb-patches/

Tags: upstream

Related branches

Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

Related Commit info:

     revno: 4334.1.2
     committer: Jon Olav Hauglid <email address hidden>
     branch nick: mysql-5.5.32-release
     timestamp: Mon 2013-05-06 16:06:32 +0200
     message:
       Bug#16757869: INNODB: POSSIBLE REGRESSION IN 5.5.31, BUG#16004999

       The problem was that if UPDATE with subselect caused a
       deadlock inside InnoDB, this deadlock was not properly
       handled by the SQL layer. This meant that the SQL layer
       would try to unlock the row after InnoDB had rolled
       back the transaction. This caused an assertion inside
       InnoDB.

       This patch fixes the problem by checking for errors
       reported by SQL_SELECT::skip_record() and not calling
       unlock_row() if any errors have been reported.

       This bug is similar to Bug#13586591, but for UPDATE
      rather than DELETE. Similar issues in filesort/opt_range/
       sql_select will be investigated and handled in the scope
       of Bug#16767929
=====================================
Looks like filesort is still not fixed (in 5.5.32, need to test with 5.5.33), and Bug#16767929 is still not in log.

description: updated
Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

Repeatable with debug builds of codership-mysql and PXC.

Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :
Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :
Download full text (22.3 KiB)

I am able to repeat this on PS as well, hence adding PS. (from #1 it looked like a larger bug)

(Note: galera_stress.* is not galera specific, just that they contain subselects which trigger this).

perl runall-new.pl --basedir=/usr --vardir=/tmp/tmp.lHuvJw1ODo --grammar=conf/galera/galera_stress.yy --gendata=conf/galera/galera_stress.zz --threads=16 --queries=10000 --seed=time

   # 2013-08-08T05:27:16 [57301] Using Log::Log4perl
# 2013-08-08T05:27:16 [57301] Copyright (c) 2010,2011 Oracle and/or its affiliates. All rights reserved. Use is subject to license terms.
# 2013-08-08T05:27:16 [57301] Please see http://forge.mysql.com/wiki/Category:RandomQueryGenerator for more information on this test framework.
# 2013-08-08T05:27:16 [57301] Starting
# 2013-08-08T05:27:16 [57301] # runall-new.pl \
# 2013-08-08T05:27:16 [57301] # --basedir=/usr \
# 2013-08-08T05:27:16 [57301] # --vardir=/tmp/tmp.lHuvJw1ODo \
# 2013-08-08T05:27:16 [57301] # --grammar=conf/galera/galera_stress.yy \
# 2013-08-08T05:27:16 [57301] # --gendata=conf/galera/galera_stress.zz \
# 2013-08-08T05:27:16 [57301] # --threads=16 \
# 2013-08-08T05:27:16 [57301] # --queries=10000 \
# 2013-08-08T05:27:16 [57301] # --seed=time
# 2013-08-08T05:27:16 [57301] master_port : 19300 slave_port : 19302 ports : 19300 19302 MTR_BUILD_THREAD : 930
# 2013-08-08T05:27:16 [57301] /media/Tintin/Work/code/randgen/pxc Revno: 867
# 2013-08-08T05:27:16 [57301] /media/Tintin/Work/code/randgen/pxc Revision-Id: <email address hidden>
# 2013-08-08T05:27:17 [57301] /usr does not look like a bzr branch, cannot get revision info.
# 2013-08-08T05:27:17 [57301] Creating MySQL 5.5.32 database at /tmp/tmp.lHuvJw1ODo/data
# 2013-08-08T05:27:23 [57301] MySQL Version:5.5.32
# 2013-08-08T05:27:23 [57301] Binary: /usr/bin/mysqld
# 2013-08-08T05:27:23 [57301] Type: Debug
# 2013-08-08T05:27:23 [57301] Datadir: /tmp/tmp.lHuvJw1ODo/data
# 2013-08-08T05:27:23 [57301] Tmpdir: /tmp/tmp.lHuvJw1ODo/tmp
# 2013-08-08T05:27:23 [57301] Corefile: /tmp/tmp.lHuvJw1ODo/data/core.
# 2013-08-08T05:27:23 [57301] Starting MySQL 5.5.32: "/usr/bin/mysqld" "--no-defaults" "--basedir=/usr" "--datadir=/tmp/tmp.lHuvJw1ODo/data" "--lc-messages-dir=/usr/share/mysql" "--character-sets-dir=/usr/share/mysql/charsets" "--tmpdir=/tmp/tmp.lHuvJw1ODo/tmp" "--core-file" "--max-allowed-packet=128Mb" "--port=19300" "--socket=/tmp/tmp.lHuvJw1ODo/mysql.sock" "--pid-file=/tmp/tmp.lHuvJw1ODo/mysql.pid" "--general-log" "--general-log-file=/tmp/tmp.lHuvJw1ODo/mysql.log" --sql-mode=no_engine_substitution
# 2013-08-08T05:27:24 [57301] Converting --seed=time to --seed=1375919844
# 2013-08-08T05:27:24 [57301] -------------------------------
# 2013-08-08T05:27:24 [57301] Configuration
# 2013-08-08T05:27:24 [57301] debug_server => ['', '']
# 2013-08-08T05:27:24 [57301] dsn => ['dbi:mysql:host=127.0.0.1:port=19300:user=root:database=test']
# 2013-08-08T05:27:24 [57301] duration => 3600
# 2013-08-08T05:27:24 [57301] gendata => conf/galera/galera_stress.zz
# 2013-08-08T05:27:24 [57301] generator => FromGrammar
# 2013-08-08T05:27:24 [57301] grammar => conf/galera/galera_stress.yy
# 2013-08-08T...

Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

Note the above is with 5.5.32 code (no 5.5.33 merge yet, however, I didn't see mention of Bug#16767929 fix in bzr log of mysql-5.5)

summary: Assertion failure in thread 140433424082688 in file ha_innodb.cc line
- 6207 | prebuilt->trx->conc_state == 1
+ 6207 | prebuilt->trx->conc_state == 1 | prebuilt->trx->state == 1 (in
+ case of PS)
Revision history for this message
Roel Van de Paar (roel11) wrote :

A number of bugs I logged recently also had some errors (similar to "Sort aborted: Deadlock found" iirc) just before (and at the same time off) crashing. May be related.

Revision history for this message
Valerii Kravchuk (valerii-kravchuk) wrote :

Looks like a result of/same as upstream http://bugs.mysql.com/bug.php?id=69127 to me.

Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

@Valerii,

Check the commit pasted in #1, the bug you are referring to is fixed and relates to only part of the issue.

I also plan on testing this with 5.5.33 MySQL and report upstream (or if others are able to repeat and report it, paste the bug here).

Changed in mysql-server:
importance: Unknown → Undecided
status: Unknown → New
Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

Full backtrace (thread apply all bt full) attached.

Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

Reproducible on 5.5.33 MySQL, reporting upstream.

Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :
Changed in mysql-server:
importance: Undecided → Unknown
status: New → Unknown
tags: added: upstream
Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Bug attachments

Remote bug watches

Bug watches keep track of this bug in other bug trackers.