InnoDB: Failing assertion: bitmap_files->files[i].start_lsn >= bitmap_files->files[i - 1].start_lsn on inconsistent bitmap file directory

Bug #1342494 reported by Ramesh Sivaraman
14
This bug affects 3 people
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
Medium
Laurynas Biveinis
5.1
Won't Fix
Undecided
Unassigned
5.5
Fix Released
Medium
Laurynas Biveinis
5.6
Fix Released
Medium
Laurynas Biveinis

Bug Description

========================= Error log:
2014-07-13 12:54:33 7f6f2637c700 InnoDB: Assertion failure in thread 140115359287040 in file log0online.cc line 1461
InnoDB: Failing assertion: bitmap_files->files[i].start_lsn >= bitmap_files->files[i - 1].start_lsn
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.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
09:54:33 UTC - mysqld got signal 6 ;
--
--
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f6f18828010): SELECT start_lsn, end_lsn, space_id, page_id FROM INFORMATION_SCHEMA.INNODB_CHANGED_PAGES LIMIT 5
Connection ID (thread ID): 12
Status: NOT_KILLED

========================= gdb :
+bt
#0 0x00007f6fbe28f69c in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000000aab116 in my_write_core (sig=6) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/mysys/stacktrace.c:422
#2 0x0000000000727fc6 in handle_fatal_signal (sig=6) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/sql/signal_handler.cc:254
#3 <signal handler called>
#4 0x00007f6fbcf3e8e5 in raise () from /lib64/libc.so.6
#5 0x00007f6fbcf400c5 in abort () from /lib64/libc.so.6
#6 0x0000000000b81410 in log_online_setup_bitmap_file_range (bitmap_files=0x7f6f263792c8, range_start=0, range_end=18446744073709551615) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/log/log0online.cc:1460
#7 0x0000000000b816c4 in log_online_bitmap_iterator_init (i=0x7f6f263792c0, min_lsn=0, max_lsn=18446744073709551615) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/log/log0online.cc:1588
#8 0x0000000000b46b5e in i_s_innodb_changed_pages_fill (thd=0x7f6f883f8000, tables=0x7f6f18828650, cond=0x0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/innobase/handler/i_s.cc:8439
#9 0x0000000000838477 in do_fill_table (thd=0x7f6f883f8000, table_list=0x7f6f18828650, join_table=0x7f6f28511190) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/sql/sql_show.cc:7799
#10 0x0000000000838846 in get_schema_tables_result (join=0x7f6f18829200, executed_place=PROCESSED_BY_JOIN_EXEC) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/sql/sql_show.cc:7900
#11 0x000000000080b0c2 in JOIN::prepare_result (this=0x7f6f18829200, columns_list=0x7f6f26379820) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/sql/sql_select.cc:824
#12 0x00000000007a8557 in JOIN::exec (this=0x7f6f18829200) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/sql/sql_executor.cc:116
#13 0x000000000080bbbb in mysql_execute_select (thd=0x7f6f883f8000, select_lex=0x7f6f883fac58, free_join=true) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/sql/sql_select.cc:1101
#14 0x000000000080beb7 in mysql_select (thd=0x7f6f883f8000, tables=0x7f6f18828650, wild_num=0, fields=..., conds=0x0, order=0x7f6f883fae20, group=0x7f6f883fad58, having=0x0, select_options=2684619520, result=0x7f6f188291d8, unit=0x7f6f883fa610, select_lex=0x7f6f883fac58) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/sql/sql_select.cc:1222
#15 0x0000000000809f46 in handle_select (thd=0x7f6f883f8000, result=0x7f6f188291d8, setup_tables_done_option=0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/sql/sql_select.cc:111
#16 0x00000000007e26ea in execute_sqlcom_select (thd=0x7f6f883f8000, all_tables=0x7f6f18828650) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/sql/sql_parse.cc:5570
#17 0x00000000007dad14 in mysql_execute_command (thd=0x7f6f883f8000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/sql/sql_parse.cc:2955
#18 0x00000000007e4feb in mysql_parse (thd=0x7f6f883f8000, rawbuf=0x7f6f18828010 "SELECT start_lsn, end_lsn, space_id, page_id FROM INFORMATION_SCHEMA.INNODB_CHANGED_PAGES LIMIT 5", length=97, parser_state=0x7f6f2637ac90) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/sql/sql_parse.cc:6746
#19 0x00000000007d7586 in dispatch_command (command=COM_QUERY, thd=0x7f6f883f8000, packet=0x7f6f87e17001 "SELECT start_lsn, end_lsn, space_id, page_id FROM INFORMATION_SCHEMA.INNODB_CHANGED_PAGES LIMIT 5", packet_length=97) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/sql/sql_parse.cc:1434
#20 0x00000000007d64b2 in do_command (thd=0x7f6f883f8000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/sql/sql_parse.cc:1051
#21 0x00000000008ba17f in threadpool_process_request (thd=0x7f6f883f8000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/sql/threadpool_common.cc:319
#22 0x00000000008bca61 in handle_event (connection=0x7f6f887c6d30) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/sql/threadpool_unix.cc:1550
#23 0x00000000008bcc91 in worker_main (param=0x1881c00) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/sql/threadpool_unix.cc:1603
#24 0x0000000000af83b4 in pfs_spawn_thread (arg=0x7f6fa07be9c0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.19-67.0/storage/perfschema/pfs.cc:1860
#25 0x00007f6fbe28a851 in start_thread () from /lib64/libpthread.so.0
#26 0x00007f6fbcff494d in clone () from /lib64/libc.so.6
(gdb) +set logging off

========================= cmd details:
if [ -r /usr/lib64/libjemalloc.so.1 ]; then export LD_PRELOAD=/usr/lib64/libjemalloc.so.1
elif [ -r /usr/lib/x86_64-linux-gnu/libjemalloc.so.1 ]; then export LD_PRELOAD=/usr/lib/x86_64-linux-gnu/libjemalloc.so.1
elif [ -r /ssd/qa56dbg/45/lib/mysql/libjemalloc.so.1 ]; then export LD_PRELOAD=/ssd/qa56dbg/45/lib/mysql/libjemalloc.so.1
else echo 'Error: jemalloc not found, please install it first'; exit 1; fi
ps -ef | grep 'rundir1_587' | grep -v grep | awk '{print $2}' | xargs sudo kill -9 > /dev/null 2>&1
rm -Rf /ssd/qa56dbg/45/rundir1_587
rm -Rf /ssd/qa56dbg/45/rundir1_587_epoch
mkdir /ssd/qa56dbg/45/rundir1_587
mkdir /ssd/qa56dbg/45/rundir1_587_epoch
cd /data/bench/qa56dbg/randgen
bash -c "set -o pipefail; perl /data/bench/qa56dbg/randgen/runall.pl --queries=100000000 --seed=8854 --duration=300 --querytimeout=60 --short_column_names --reporter=Shutdown,Backtrace,QueryTimeout,ErrorLog,ErrorLogAlarm --mysqld=--log-output=none --mysqld=--sql_mode=ONLY_FULL_GROUP_BY --mysqld=--plugin-load=tokudb=ha_tokudb.so --mysqld=--init-file=/data/bench/qa56dbg/randgen/conf/percona_qa/5.6/TokuDB.sql --mysqld=--utility-user-password=test --grammar=conf/percona_qa/5.6/5.6.yy --gendata=conf/percona_qa/5.6/5.6.zz1 --threads=17 --mask-level=1 --validator=Transformer --basedir=/ssd/qa56dbg/Percona-Server-5.6.19-rel67.0-619.Linux.x86_64-debug --mysqld=--enforce-storage-engine=InnoDB --notnull --mysqld=--innodb_changed_pages=FORCE --mysqld=--innodb_fast_shutdown=0 --mysqld=--innodb_flush_log_at_trx_commit=2 --mysqld=--innodb_flush_method=O_DIRECT --mysqld=--innodb_log_arch_dir=/ssd/qa56dbg/45/rundir1_587_epoch --mysqld=--innodb_log_arch_expire_sec=120 --mysqld=--innodb_log_archive=1 --mysqld=--innodb_log_block_size=512 --mysqld=--innodb_log_buffer_size=1048577 --mysqld=--innodb_log_file_size=10485761 --mysqld=--innodb_log_files_in_group=3 --mysqld=--innodb_max_bitmap_file_size=4097 --mysqld=--innodb_max_changed_pages=0 --mysqld=--innodb_track_changed_pages=1 --mysqld=--innodb_use_global_flush_log_at_trx_commit=0 --mysqld=--innodb-buffer-pool-populate --mysqld=--loose-readonly-key-cache-division-limit=1 --mysqld=--thread_handling=pool-of-threads --mysqld=--transaction-isolation=READ-UNCOMMITTED --mysqld=--utility-user-password=test --mysqld=--innodb_purge_threads=1 --mysqld=--innodb_adaptive_hash_index_partitions=8 --mysqld=--innodb_buffer_pool_instances=4 --mtr-build-thread=716 --mask=44218 --vardir1=/ssd/qa56dbg/45/rundir1_587 > /ssd/qa56dbg/45/cmd587.log 2>&1"
tail -n1 /ssd/qa56dbg/45/cmd587.log

========================= version:
Server : 619 <email address hidden>
RQG: 973 <email address hidden>

Tags: bitmap xtradb

Related branches

Revision history for this message
Ramesh Sivaraman (rameshvs02) wrote :
Revision history for this message
Ramesh Sivaraman (rameshvs02) wrote :
Revision history for this message
Ramesh Sivaraman (rameshvs02) wrote :
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

I need a core dump and a listing of directory with xdb files (should be the datadir).

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

and the binaries + shared libs for the core dump

Revision history for this message
Ramesh Sivaraman (rameshvs02) wrote :
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Thanks, what about the other info I requested?

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

FYI please update the shared libs-taking script to include everything. (ping Roel for more info if needed). Bonus points if usr/lib64 lib64 directory structure is contained in the tar.gz too.

(gdb) info sharedlibrary
From To Syms Read Shared Object Library
                                        No /usr/lib64/libjemalloc.so.1
0x00007f6fbe288660 0x00007f6fbe293eb8 Yes (*) /home/laurynas/percona/core_587_150714-0546/lib64/libpthread.so.0
0x00007f6fbe082570 0x00007f6fbe082721 Yes (*) /home/laurynas/percona/core_587_150714-0546/lib64/libaio.so.1
0x00007f6fbde7c140 0x00007f6fbde7f4f8 Yes (*) /home/laurynas/percona/core_587_150714-0546/lib64/librt.so.1
0x00007f6fbdc43c00 0x00007f6fbdc489a8 Yes (*) /home/laurynas/percona/core_587_150714-0546/lib64/libcrypt.so.1
0x00007f6fbda3fde0 0x00007f6fbda40998 Yes (*) /home/laurynas/percona/core_587_150714-0546/lib64/libdl.so.2
0x00007f6fbd78f3f0 0x00007f6fbd7fc376 Yes (*) /home/laurynas/percona/core_587_150714-0546/usr/lib64/libstdc++.so.6
0x00007f6fbd4b8e70 0x00007f6fbd4f8f48 Yes (*) /home/laurynas/percona/core_587_150714-0546/lib64/libm.so.6
0x00007f6fbd2a1910 0x00007f6fbd2b1f78 Yes (*) /home/laurynas/percona/core_587_150714-0546/lib64/libgcc_s.so.1
0x00007f6fbcf2aa20 0x00007f6fbd04b76c Yes (*) /home/laurynas/percona/core_587_150714-0546/lib64/libc.so.6
0x00007f6fbe6d1a60 0x00007f6fbe6ec460 Yes /lib64/ld-linux-x86-64.so.2
0x00007f6fbcca36c0 0x00007f6fbccea868 Yes (*) /home/laurynas/percona/core_587_150714-0546/lib64/libfreebl3.so
                                        No /data/bench/qa56dbg/Percona-Server-5.6.19-rel67.0-619.Linux.x86_64-debug/lib/mysql/plugin/ha_tokudb.so
                                        No ions

Revision history for this message
Ramesh Sivaraman (rameshvs02) wrote :

Data directory is getting uploaded.

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

This is caused by inconsistent bitmap file directory, where old bitmap data has been partially overwritten by a new bitmap data with restarted LSN. Will be finally confirmed by a directory listing with timestamps.

(gdb) print bitmap_files->files[0]
$4 = {name = "ib_modified_log_1_0.xdb", '\000' <repeats 488 times>, start_lsn = 0, seq_num = 1}
(gdb) print bitmap_files->files[1]
$5 = {name = "ib_modified_log_2_1627177563.xdb", '\000' <repeats 479 times>, start_lsn = 1627177563, seq_num = 2}
(gdb) print bitmap_files->files[2]
$6 = {name = "ib_modified_log_3_49941516.xdb", '\000' <repeats 481 times>, start_lsn = 49941516, seq_num = 3}
(gdb) print bitmap_files->files[3]
$7 = {name = "ib_modified_log_4_1658108010.xdb", '\000' <repeats 479 times>, start_lsn = 1658108010, seq_num = 4}
(gdb) print bitmap_files->files[4]
$8 = {name = "ib_modified_log_5_1664036441.xdb", '\000' <repeats 479 times>, start_lsn = 1664036441, seq_num = 5}
(gdb) print bitmap_files->files[5]
$9 = {name = "ib_modified_log_6_1668491722.xdb", '\000' <repeats 479 times>, start_lsn = 1668491722, seq_num = 6}
(gdb) print bitmap_files->files[6]
$10 = {name = '\000' <repeats 511 times>, start_lsn = 0, seq_num = 0}

The fix would be to diagnose this as a regular error instead of debug assert.

tags: added: bitmap xtradb
summary: InnoDB: Failing assertion: bitmap_files->files[i].start_lsn >=
- bitmap_files->files[i - 1].start_lsn
+ bitmap_files->files[i - 1].start_lsn on inconsistent bitmap file
+ directory
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

I only need its listing (ls -l) in this case

Revision history for this message
Ramesh Sivaraman (rameshvs02) wrote :
Download full text (10.5 KiB)

root@ramesh-550P5C-550P7C:~/bug/BUNDLE_587/vardir1_587# ls -lrt
total 48
drwxr-xr-x 5 ramesh ramesh 20480 Jul 3 21:35 std_data_ln
drwxr-xr-x 2 ramesh ramesh 4096 Jul 13 15:24 run
drwxr-xr-x 2 ramesh ramesh 4096 Jul 13 15:24 log
drwxr-xr-x 2 ramesh ramesh 4096 Jul 13 15:25 tmp
-rw-r--r-- 1 ramesh ramesh 1880 Jul 13 15:25 command
drwxr-xr-x 7 ramesh ramesh 4096 Jul 15 18:17 master-data
root@ramesh-550P5C-550P7C:~/bug/BUNDLE_587/vardir1_587# ls -l *
-rw-r--r-- 1 ramesh ramesh 1880 Jul 13 15:25 command

log:
total 144
-rw-r--r-- 1 ramesh ramesh 4150 Jul 13 15:24 bootstrap.log
-rw-r--r-- 1 ramesh ramesh 23 Jul 13 15:24 current_test
-rw-r--r-- 1 ramesh ramesh 23 Jul 13 15:24 master1.err
-rw-r--r-- 1 ramesh ramesh 8931 Jul 13 15:24 master.err
-rw-r----- 1 ramesh ramesh 313 Jul 13 15:24 master.log
-rw-r----- 1 ramesh ramesh 313 Jul 13 15:24 master-slow.log
-rw-r--r-- 1 ramesh ramesh 464 Jul 13 15:24 mysql-test-run.log
-rw-r--r-- 1 ramesh ramesh 23 Jul 13 15:24 ndb_testrun.log
-rw-r--r-- 1 ramesh ramesh 23 Jul 13 15:24 slave1.err
-rw-r--r-- 1 ramesh ramesh 23 Jul 13 15:24 slave2.err
-rw-r--r-- 1 ramesh ramesh 23 Jul 13 15:24 slave.err

master-data:
total 113020
-rw-r----- 1 ramesh ramesh 56 Jul 13 15:25 auto.cnf
-rw-rw-r-- 1 ramesh ramesh 3512076 Jul 15 18:16 gdb_587_150714-0546_FULL.txt
-rw-rw-r-- 1 ramesh ramesh 274332 Jul 15 18:16 gdb_587_150714-0546_STD.txt
-rw-r----- 1 ramesh ramesh 79691776 Jul 13 15:25 ibdata1
-rw-r----- 1 ramesh ramesh 10485760 Jul 13 15:25 ib_logfile0
-rw-r----- 1 ramesh ramesh 10485760 Jul 13 15:25 ib_logfile1
-rw-r----- 1 ramesh ramesh 10485760 Jul 13 15:25 ib_logfile2
-rw-r----- 1 ramesh ramesh 81920 Jul 13 15:25 ib_modified_log_1_0.xdb
-rw-r----- 1 ramesh ramesh 40960 Jul 13 15:25 ib_modified_log_2_1627177563.xdb
-rw-r----- 1 ramesh ramesh 36864 Jul 13 15:25 ib_modified_log_3_1649458316.xdb
-rw-r----- 1 ramesh ramesh 20480 Jul 13 15:25 ib_modified_log_3_49941516.xdb
-rw-r----- 1 ramesh ramesh 24576 Jul 13 15:25 ib_modified_log_4_1658108010.xdb
-rw-r----- 1 ramesh ramesh 36864 Jul 13 15:25 ib_modified_log_5_1664036441.xdb
-rw-r----- 1 ramesh ramesh 73728 Jul 13 15:25 ib_modified_log_6_1668491722.xdb
-rw-r----- 1 ramesh ramesh 94314 Jul 13 15:25 innodb_status.8801
drwxr-x--- 2 ramesh ramesh 4096 Jul 13 15:25 literals
-rwx------ 1 ramesh ramesh 1871 Jul 13 15:25 log000000000000.tokulog25
-rw-r--r-- 1 ramesh ramesh 8931 Jul 15 18:16 master_587_150714-0546.err
drwxr-xr-x 2 ramesh ramesh 16384 Jul 13 15:24 mysql
drwxr-x--- 2 ramesh ramesh 12288 Jul 13 15:25 performance_schema
-rw-r----- 1 ramesh ramesh 24576 Jul 13 15:25 tc.log
drwxr-xr-x 2 ramesh ramesh 36864 Jul 13 15:25 test
-rwxr-x--x 1 ramesh ramesh 16384 Jul 13 15:25 tokudb.directory
-rwxr-x--x 1 ramesh ramesh 16384 Jul 13 15:25 tokudb.environment
-rw------- 1 ramesh ramesh 0 Jul 13 15:25 __tokudb_lock_dont_delete_me_data
-rw------- 1 ramesh ramesh 0 Jul 13 15:25 __tokudb_lock_dont_delete_me_environment
-rw------- 1 ramesh ramesh 0 Jul 13 15:25 __tokudb_lock_dont_delete_me_logs
-rw------- 1 ramesh ramesh 0 Jul 13 15:25 __tokudb_lock_dont_delete_me_recovery
-rw-...

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

-rw-r----- 1 ramesh ramesh 81920 Jul 13 15:25 ib_modified_log_1_0.xdb
-rw-r----- 1 ramesh ramesh 40960 Jul 13 15:25 ib_modified_log_2_1627177563.xdb
-rw-r----- 1 ramesh ramesh 36864 Jul 13 15:25 ib_modified_log_3_1649458316.xdb
-rw-r----- 1 ramesh ramesh 20480 Jul 13 15:25 ib_modified_log_3_49941516.xdb
-rw-r----- 1 ramesh ramesh 24576 Jul 13 15:25 ib_modified_log_4_1658108010.xdb
-rw-r----- 1 ramesh ramesh 36864 Jul 13 15:25 ib_modified_log_5_1664036441.xdb
-rw-r----- 1 ramesh ramesh 73728 Jul 13 15:25 ib_modified_log_6_1668491722.xdb

Note the two ib_modified_log_3_ files

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-1527

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

Duplicates of this bug

Other bug subscribers

Remote bug watches

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