InnoDB: Failing assertion: dict_table_get_format(table) >= UNIV_FORMAT_B in file row0sel.cc line 115 | abort in row_sel_sec_rec_is_for_blob

[Roel Van de Paar]

2013-04-11 21:00:41 2107 [ERROR] /data/opt/roel/Percona-Server-5.6.8-alpha60.2-314-debug.Linux.x86_64/bin/mysqld-debug: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
2013-04-11 21:00:42 7fcd04045700 InnoDB: Assertion failure in thread 140518512416512 in file row0sel.cc line 115
InnoDB: Failing assertion: dict_table_get_format(table) >= UNIV_FORMAT_B

Thread 1 (Thread 0x7fcd04045700 (LWP 2176)):
+bt
#0 0x00007fcd205a269c in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000000673dce in handle_fatal_signal (sig=6) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/signal_handler.cc:249
#2 <signal handler called>
#3 0x00007fcd1f2518a5 in raise () from /lib64/libc.so.6
#4 0x00007fcd1f253085 in abort () from /lib64/libc.so.6
#5 0x0000000000a8272d in row_sel_sec_rec_is_for_blob (sec_rec=0x7fcd11c9c591 "\377\377\377\377\066-02-11 07:19:29.017433\200", sec_index=0x7fcce41f94a8, clust_rec=0x7fcd11c520ab "\377\377\377\377", clust_index=0x7fcce41ed0d8) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/storage/innobase/row/row0sel.cc:115
#6 row_sel_sec_rec_is_for_clust_rec (sec_rec=0x7fcd11c9c591 "\377\377\377\377\066-02-11 07:19:29.017433\200", sec_index=0x7fcce41f94a8, clust_rec=0x7fcd11c520ab "\377\377\377\377", clust_index=0x7fcce41ed0d8) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/storage/innobase/row/row0sel.cc:232
#7 0x0000000000a85746 in row_sel_get_clust_rec_for_mysql (buf=0x7fcca40fce20 "\357\276\347\377", mode=2, prebuilt=0x7fcca40f15c8, match_mode=1, direction=<value optimized out>) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/storage/innobase/row/row0sel.cc:3162
#8 row_search_for_mysql (buf=0x7fcca40fce20 "\357\276\347\377", mode=2, prebuilt=0x7fcca40f15c8, match_mode=1, direction=<value optimized out>) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/storage/innobase/row/row0sel.cc:4689
#9 0x000000000099ea71 in ha_innobase::index_read (this=0x7fcca41b3f10, buf=0x7fcca40fce20 "\357\276\347\377", key_ptr=<value optimized out>, key_len=<value optimized out>, find_flag=<value optimized out>) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/storage/innobase/handler/ha_innodb.cc:7437
#10 0x00000000005ab754 in handler::ha_index_read_map (this=0x7fcca41b3f10, buf=0x7fcca40fce20 "\357\276\347\377", key=0x7fcc6c08f360 "\001", keypart_map=1, find_flag=HA_READ_KEY_EXACT) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/handler.cc:2668
#11 0x00000000005acc37 in handler::read_range_first (this=0x7fcca41b3f10, start_key=0x7fcca41b3ff0, end_key=0x7fcca41b4010, eq_range_arg=<value optimized out>, sorted=<value optimized out>) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/handler.cc:6578
#12 0x00000000005aae95 in handler::multi_range_read_next (this=0x7fcca41b3f10, range_info=0x7fcd04042a88) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/handler.cc:5749
#13 0x00000000005ad8a8 in DsMrr_impl::dsmrr_next (this=0x7fcca41b59d8, range_info=0x7fcd04042a88) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/handler.cc:6108
#14 0x000000000082d98d in QUICK_RANGE_SELECT::get_next (this=0x7fcc6c09b720) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/opt_range.cc:10409
#15 0x0000000000803064 in find_all_keys (param=0x7fcd04042f10, select=0x7fcc6c08f648, fs_info=0x7fcd04042f90, buffpek_pointers=0x7fcd04042cd0, tempfile=0x7fcd04042df0, pq=0x0, found_rows=0x7fcd04043230) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/filesort.cc:756
#16 0x0000000000804567 in filesort (thd=0x2f74250, table=<value optimized out>, filesort=<value optimized out>, sort_positions=208, examined_rows=0x7fcd04043238, found_rows=0x7fcd04043230) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/filesort.cc:337
#17 0x00000000006dcf1e in create_sort_index (this=0x7fcc6c08ed60) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/sql_executor.cc:3306
#18 st_join_table::sort_table (this=0x7fcc6c08ed60) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/sql_executor.cc:2471
#19 0x00000000006dd1ee in join_init_read_record (tab=0x7fcc6c08ed60) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/sql_executor.cc:2382
#20 0x00000000006dc7bd in sub_select (join=0x7fcc6c1da4b0, join_tab=0x7fcc6c08ed60, end_of_records=<value optimized out>) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/sql_executor.cc:1256
#21 0x00000000006db2a6 in do_select (this=0x7fcc6c1da4b0) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/sql_executor.cc:941
#22 JOIN::exec (this=0x7fcc6c1da4b0) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/sql_executor.cc:191
#23 0x0000000000724058 in mysql_execute_select (thd=0x2f74250, tables=0x7fcc6c0052c0, wild_num=0, fields=..., conds=0x7fcc6c005950, order=<value optimized out>, group=0x2f76b88, having=0x0, select_options=2147748608, result=0x7fcc6c1da488, unit=0x2f76448, select_lex=0x2f76a88) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/sql_select.cc:1100
#24 mysql_select (thd=0x2f74250, tables=0x7fcc6c0052c0, wild_num=0, fields=..., conds=0x7fcc6c005950, order=<value optimized out>, group=0x2f76b88, having=0x0, select_options=2147748608, result=0x7fcc6c1da488, unit=0x2f76448, select_lex=0x2f76a88) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/sql_select.cc:1221
#25 0x0000000000724a23 in handle_select (thd=0x2f74250, result=0x7fcc6c1da488, setup_tables_done_option=0) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/sql_select.cc:110
#26 0x00000000006f9cfd in execute_sqlcom_select (thd=0x2f74250, all_tables=<value optimized out>) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/sql_parse.cc:5065
#27 0x00000000006ff3ef in mysql_execute_command (thd=0x2f74250) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/sql_parse.cc:2592
#28 0x0000000000705408 in mysql_parse (thd=0x2f74250, rawbuf=<value optimized out>, length=<value optimized out>, parser_state=<value optimized out>) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/sql_parse.cc:6195
#29 0x0000000000707174 in dispatch_command (command=COM_QUERY, thd=0x2f74250, packet=0x7fcd04044ab0 "PB\367\002", packet_length=1811958864) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/sql_parse.cc:1335
#30 0x0000000000707819 in do_command (thd=0x2f74250) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/sql_parse.cc:1037
#31 0x00000000006cd7bf in do_handle_one_connection (thd_arg=<value optimized out>) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/sql_connect.cc:970
#32 0x00000000006cd8e7 in handle_one_connection (arg=0x2f74250) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/sql/sql_connect.cc:886
#33 0x000000000097ca19 in pfs_spawn_thread (arg=0x2ecf8e0) at /ssd/ps56-univ-log-archive-qa_HACK/Percona-Server-5.6.8-alpha60.2/storage/perfschema/pfs.cc:1853
#34 0x00007fcd2059d851 in start_thread () from /lib64/libpthread.so.0
#35 0x00007fcd1f30711d in clone () from /lib64/libc.so.6

[Roel Van de Paar (roel11)]

======================== Run details
[roel@hppro1 531287]$ cat cmd605
ps -ef | grep 'cmdrun_605' | grep -v grep | awk '{print $2}' | xargs sudo kill -9
rm -Rf /data/opt/roel/531287/cmdrun_605
mkdir /data/opt/roel/531287/cmdrun_605
cd /data/opt/roel/randgen
bash -c "set -o pipefail; perl runall.pl --queries=100000000 --seed=22399 --duration=900 --sqltrace --querytimeout=60 --short_column_names --reporter=Shutdown,B
acktrace,QueryTimeout,ErrorLog,ErrorLogAlarm --mysqld=--log-output=none --mysqld=--sql_mode=ONLY_FULL_GROUP_BY --grammar=conf/percona_qa/percona_qa.yy --gendata=conf/percona_qa/percona_qa.zz --basedir=/ssd/Percona-Server-5.6.8-alpha60.2-314-debug.Linux.x86_64 --threads=25 --views --notnull --mysqld=--innodb_log_archive=1 --mysqld=--innodb_log_arch_expire_sec=1 --mysqld=--innodb_log_file_size=10485761 --mysqld=--innodb_log_files_in_group=3 --mysqld=--innodb_log_buffer_size=1048577 --mysqld=--innodb_fast_shutdown=0 --mysqld=--skip-innodb_doublewrite --mysqld=--innodb_file_per_table=1 --mysqld=--innodb_flush_log_at_trx_commit=2 --mysqld=--innodb_flush_log_at_timeout=1 --mtr-build-thread=766 --mask=50689 --vardir1=/data/opt/roel/531287/cmdrun_605 > /data/opt/roel/531287/cmdrun605.log 2>&1"

[Laurynas Biveinis (laurynas-biveinis)]

My first guess that this is not log archiving-related, nor that this is Percona-related neither.

Roel, would it be possible to test with Oracle MySQL?

[Roel Van de Paar (roel11)]

Tested w/ mysql-5.6.10-linux-glibc2.5-x86_64 w/o AL options. Did not assert.

[Roel Van de Paar (roel11)]

Tested s/--mysqld=--innodb_log_archive=1 --mysqld=--innodb_log_arch_expire_sec=1/--mysqld=--innodb_log_archive=0/. Did still assert. So, looks to be PS+InnoDB related, but not AL.

[Roel Van de Paar (roel11)]

If this is a debug assert, it may still be present in mysql 5.6 (which was compiled optimized)

[Alexey Kopytov (akopytov)]

Yes, it is a debug assertion.

[Roel Van de Paar (roel11)]

Likely upstream, and marking as such ftm.

[Shahriyar Rzayev (rzayev-sehriyar)]

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