Failing assertion: i->in_files.count > 0 in file log0online.cc line 1511 | abort in log_online_bitmap_iterator_init

[Roel Van de Paar]

2013-05-24 18:37:58 18c7f700 InnoDB: Assertion failure in thread 415758080 in file log0online.cc line 1511
InnoDB: Failing assertion: i->in_files.count > 0

Query (20fc4ef0): SELECT COUNT(*) FROM INFORMATION_SCHEMA.INNODB_CHANGED_PAGES

Thread 2 (LWP 10130):
+bt
#0 0x0000003fde20c69c in pthread_kill () from /lib64/libpthread.so.0
#1 0x00000000006e47ad in handle_fatal_signal (sig=6) at /ssd/5.6-merge-3_val/Percona-Server-5.6.10-alpha60.2/sql/signal_handler.cc:251
#2 <signal handler called>
#3 0x0000003fdde328a5 in raise () from /lib64/libc.so.6
#4 0x0000003fdde34085 in abort () from /lib64/libc.so.6
#5 0x00000000009e7703 in log_online_bitmap_iterator_init (i=0x18c7ce80, min_lsn=<optimized out>, max_lsn=<optimized out>) at /ssd/5.6-merge-3_val/Percona-Server-5.6.10-alpha60.2/storage/innobase/log/log0online.cc:1511
#6 0x00000000009b37f8 in i_s_innodb_changed_pages_fill (thd=0x11da0530, tables=<optimized out>, cond=0x0) at /ssd/5.6-merge-3_val/Percona-Server-5.6.10-alpha60.2/storage/innobase/handler/i_s.cc:8206
#7 0x0000000000797c0d in do_fill_table (thd=0x11da0530, table_list=0x20fc5260, join_table=0x20fc6ab8) at /ssd/5.6-merge-3_val/Percona-Server-5.6.10-alpha60.2/sql/sql_show.cc:7682
#8 0x0000000000797ef6 in get_schema_tables_result (join=0x20fc5e00, executed_place=PROCESSED_BY_JOIN_EXEC) at /ssd/5.6-merge-3_val/Percona-Server-5.6.10-alpha60.2/sql/sql_show.cc:7783
#9 0x000000000078fdf5 in JOIN::prepare_result (this=0x20fc5e00, columns_list=<optimized out>) at /ssd/5.6-merge-3_val/Percona-Server-5.6.10-alpha60.2/sql/sql_select.cc:823
#10 0x000000000074837a in JOIN::exec (this=0x20fc5e00) at /ssd/5.6-merge-3_val/Percona-Server-5.6.10-alpha60.2/sql/sql_executor.cc:116
#11 0x0000000000790208 in mysql_execute_select (thd=0x11da0530, select_lex=0x11da2ff0, free_join=true) at /ssd/5.6-merge-3_val/Percona-Server-5.6.10-alpha60.2/sql/sql_select.cc:1101
#12 0x0000000000790964 in mysql_select (thd=0x11da0530, tables=0x20fc5260, wild_num=0, fields=..., conds=<optimized out>, order=0x11da31b8, group=0x11da30f0, having=0x0, select_options=2684619520, result=0x20fc5dd8, unit=0x11da29a8, select_lex=0x11da2ff0) at /ssd/5.6-merge-3_val/Percona-Server-5.6.10-alpha60.2/sql/sql_select.cc:1222
#13 0x0000000000790b38 in handle_select (thd=0x11da0530, result=0x20fc5dd8, setup_tables_done_option=0) at /ssd/5.6-merge-3_val/Percona-Server-5.6.10-alpha60.2/sql/sql_select.cc:111
#14 0x0000000000765a7d in execute_sqlcom_select (thd=0x11da0530, all_tables=0x20fc5260) at /ssd/5.6-merge-3_val/Percona-Server-5.6.10-alpha60.2/sql/sql_parse.cc:5272
#15 0x0000000000767fd7 in mysql_execute_command (thd=0x11da0618) at /ssd/5.6-merge-3_val/Percona-Server-5.6.10-alpha60.2/sql/sql_parse.cc:2732
#16 0x000000000076d110 in mysql_parse (thd=0x11da0530, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>) at /ssd/5.6-merge-3_val/Percona-Server-5.6.10-alpha60.2/sql/sql_parse.cc:6443
#17 0x000000000076dbaf in dispatch_command (command=<optimized out>, thd=0x11da0530, packet=<optimized out>, packet_length=553406252) at /ssd/5.6-merge-3_val/Percona-Server-5.6.10-alpha60.2/sql/sql_parse.cc:1359
#18 0x000000000076e800 in do_command (thd=0x11da0530) at /ssd/5.6-merge-3_val/Percona-Server-5.6.10-alpha60.2/sql/sql_parse.cc:1051
#19 0x000000000073910f in do_handle_one_connection (thd_arg=<optimized out>) at /ssd/5.6-merge-3_val/Percona-Server-5.6.10-alpha60.2/sql/sql_connect.cc:1617
#20 0x0000000000739220 in handle_one_connection (arg=0x18a2fa50) at /ssd/5.6-merge-3_val/Percona-Server-5.6.10-alpha60.2/sql/sql_connect.cc:1528
#21 0x0000000000c0b949 in pfs_spawn_thread (arg=0x188f04f0) at /ssd/5.6-merge-3_val/Percona-Server-5.6.10-alpha60.2/storage/perfschema/pfs.cc:1853
#22 0x0000003fde207851 in start_thread () from /lib64/libpthread.so.0
#23 0x0000003fddee890d in clone () from /lib64/libc.so.6

[Roel Van de Paar (roel11)]

++Valgrinds seen in error log:

2013-05-24 17:15:32 10035 [Note] InnoDB: Highest supported file format is Barracuda.
==10035== Conditional jump or move depends on uninitialised value(s)
==10035== at 0x9E70F7: log_online_start_bitmap_file() (log0online.cc:526)
==10035== by 0x9E92CF: log_online_read_init() (log0online.cc:725)
==10035== by 0xA94A3C: init_log_online() (srv0start.cc:1456)
==10035== by 0xA97D81: innobase_start_or_create_for_mysql() (srv0start.cc:2327)
==10035== by 0x9A2E19: innobase_init(void*) (ha_innodb.cc:3492)
==10035== by 0x63CA4A: ha_initialize_handlerton(st_plugin_int*) (handler.cc:690)
==10035== by 0x77503F: plugin_initialize(st_plugin_int*) (sql_plugin.cc:1126)
==10035== by 0x7771A9: plugin_init(int*, char**, int) (sql_plugin.cc:1417)
==10035== by 0x624981: init_server_components() (mysqld.cc:4872)
==10035== by 0x6293CF: mysqld_main(int, char**) (mysqld.cc:5503)
==10035== by 0x3FDDE1ECDC: (below main) (in /lib64/libc-2.12.so)
==10035==
2013-05-24 17:15:33 10035 [Note] InnoDB: starting tracking changed pages from LSN 1625977

and

2013-05-24 17:15:41 10035 [Note] /ssd/Percona-Server-5.6.10-alpha60.2-347-debug-valgrind.Linux.x86_64/bin/mysqld-debug: ready for connections.
Version: '5.6.11-alpha60.2-debug-log' socket: '/ssd/271485/current1_4/tmp/master.sock' port: 13060 Percona Server with XtraDB (GPL), Release alpha60.2, Revision 347-debug-valgrind
2013-05-25T01:37:32 [11566] Query: INSERT IGNORE INTO `view_table100_innodb_default_int` ( `c65` , `c50` , `c74` ) VALUES ( e , 'all' , '22:02:49.049457' )
==10035== Thread 24:
==10035== Conditional jump or move depends on uninitialised value(s)
==10035== at 0x9E70F7: log_online_start_bitmap_file() (log0online.cc:526)
==10035== by 0x9E7451: log_online_purge_changed_page_bitmaps(unsigned long) (log0online.cc:1688)
==10035== by 0x9919A8: innobase_purge_changed_page_bitmaps(unsigned long long) (ha_innodb.cc:3633)
==10035== by 0x7722A5: plugin_foreach_with_mask(THD*, char (*)(THD*, st_plugin_int**, void*), int, unsigned int, void*) (sql_plugin.cc:2087)
==10035== by 0x6362B7: ha_purge_changed_page_bitmaps(unsigned long long) (handler.cc:7095)
==10035== by 0x781736: reload_acl_and_cache(THD*, unsigned long, TABLE_LIST*, int*) (sql_reload.cc:383)
==10035== by 0x767C33: mysql_execute_command(THD*) (sql_parse.cc:4374)
==10035== by 0x76D10F: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:6443)
==10035== by 0x76DBAE: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1359)
==10035== by 0x76E7FF: do_command(THD*) (sql_parse.cc:1051)
==10035== by 0x73910E: do_handle_one_connection(THD*) (sql_connect.cc:1617)
==10035== by 0x73921F: handle_one_connection (sql_connect.cc:1528)
==10035== by 0xC0B948: pfs_spawn_thread (pfs.cc:1853)
==10035== by 0x3FDE207850: start_thread (in /lib64/libpthread-2.12.so)
==10035== by 0x3FDDEE890C: clone (in /lib64/libc-2.12.so)
==10035==

[Roel Van de Paar (roel11)]

Blocks bitmap testing

[Roel Van de Paar (roel11)]

Another Valgrind found in another run (looks related, but may be different issue altogether)

Thread 12:
Conditional jump or move depends on uninitialised value(s)
   at 0x9E70F7: log_online_start_bitmap_file() (log0online.cc:526)
   by 0x9E8831: log_online_write_bitmap() (log0online.cc:1131)
   by 0x9E8AA2: log_online_follow_redo_log() (log0online.cc:1223)
   by 0xA8FC94: srv_redo_log_follow_thread (srv0srv.cc:2177)
   by 0x3FDE207850: start_thread (in /lib64/libpthread-2.12.so)
   by 0x3FDDEE890C: clone (in /lib64/libc-2.12.so)

[Laurynas Biveinis (laurynas-biveinis)]

The crash is either bug 1179974, either requires fixing that bug first. Closing as duplicate and raising 1179974 priority.

The Valgrind errors are yet another case of bug 1182793.

[Roel Van de Paar (roel11)]

This bug is still visible in QA tree (with latest updates 29/5/13). New details:

2013-05-29 03:15:34 7f169ffa0700 InnoDB: Assertion failure in thread 139735149971200 in file log0online.cc line 1562
InnoDB: Failing assertion: i->in_files.count > 0

#4 0x0000003fdde34085 in abort () from /lib64/libc.so.6
#5 0x0000000000972c1c in log_online_bitmap_iterator_init

Attaching full details in files.