Bug #73555 Tablespace free space info corrupted - freeing page already marked free
Submitted: 13 Aug 2014 4:18 Modified: 27 Aug 2014 4:39
Reporter: Annamalai Gurusami Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:5.7.5-m15-debug OS:Any
Assigned to: CPU Architecture:Any

[13 Aug 2014 4:18] Annamalai Gurusami
Description:
The server hit the following FATAL error in function fseg_free_page_low():

3254                 ib_logf(IB_LOG_LEVEL_ERROR,
3255                         "InnoDB is trying to free page " UINT32PF
3256                         " though it is already marked as free in the"
3257                         " tablespace! The tablespace free space info is"
3258                         " corrupt. You may need to dump your tables and"
3259                         " recreate the whole database!", page_id.page_no());
3260 crash:
3261                 ib_logf(IB_LOG_LEVEL_FATAL, "%s", FORCE_RECOVERY_MSG);
3262         }

The call stack is as follows:

(gdb) where
#0  0x0000003a1f40c63c in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000ddcbd5 in my_write_core (sig=6) at /export/home/ima/nroot/mysql_src_cmtb/mysys/stacktrace.c:246
#2  0x00000000008000dc in handle_fatal_signal (sig=6) at /export/home/ima/nroot/mysql_src_cmtb/sql/signal_handler.cc:219
#3  <signal handler called>
#4  0x0000003a1f032885 in raise () from /lib64/libc.so.6
#5  0x0000003a1f034065 in abort () from /lib64/libc.so.6
#6  0x000000000101c38f in ut_dbg_assertion_failed (expr=0x0, file=0x1418a38 "/export/home/ima/nroot/mysql_src_cmtb/storage/innobase/handler/ha_innodb.cc", line=17653) at /export/home/ima/nroot/mysql_src_cmtb/storage/innobase/ut/ut0dbg.cc:68
#7  0x0000000000e7e09c in ib_logf (level=IB_LOG_LEVEL_FATAL, format=0x14acaa5 "%s") at /export/home/ima/nroot/mysql_src_cmtb/storage/innobase/handler/ha_innodb.cc:17653
#8  0x00000000010f6cb9 in fseg_free_page_low (seg_inode=0x7f2e8c8d9272 "", page_id=..., page_size=..., ahi=true, mtr=0x7fff0773b850) at /export/home/ima/nroot/mysql_src_cmtb/storage/innobase/fsp/fsp0fsp.cc:3261
#9  0x00000000010f7aa9 in fseg_free_step (header=0x7f2e8c8db04a "", ahi=true, mtr=0x7fff0773b850) at /export/home/ima/nroot/mysql_src_cmtb/storage/innobase/fsp/fsp0fsp.cc:3570
#10 0x00000000010313f6 in btr_free_but_not_root (root_page_id=..., page_size=..., logging_mode=MTR_LOG_ALL) at /export/home/ima/nroot/mysql_src_cmtb/storage/innobase/btr/btr0btr.cc:1108
#11 0x00000000010a85f4 in dict_drop_index_tree (rec=0x7f2ebc3bded3 "", pcur=0x18decd50, is_drop=true, mtr=0x7fff0773be20) at /export/home/ima/nroot/mysql_src_cmtb/storage/innobase/dict/dict0crea.cc:937
#12 0x0000000000fc3a84 in row_upd_clust_step (node=0x18dee470, thr=0x18dee928) at /export/home/ima/nroot/mysql_src_cmtb/storage/innobase/row/row0upd.cc:2375
#13 0x0000000000fc4160 in row_upd (node=0x18dee470, thr=0x18dee928) at /export/home/ima/nroot/mysql_src_cmtb/storage/innobase/row/row0upd.cc:2534
#14 0x0000000000fc4641 in row_upd_step (thr=0x18dee928) at /export/home/ima/nroot/mysql_src_cmtb/storage/innobase/row/row0upd.cc:2681
#15 0x0000000000f29384 in que_thr_step (thr=0x18dee928) at /export/home/ima/nroot/mysql_src_cmtb/storage/innobase/que/que0que.cc:1035
#16 0x0000000000f29661 in que_run_threads_low (thr=0x18dee928) at /export/home/ima/nroot/mysql_src_cmtb/storage/innobase/que/que0que.cc:1115
#17 0x0000000000f29820 in que_run_threads (thr=0x18dee928) at /export/home/ima/nroot/mysql_src_cmtb/storage/innobase/que/que0que.cc:1156
#18 0x0000000000f29ad2 in que_eval_sql (info=0x0, sql=0x1450fa0 "PROCEDURE DROP_TEMP_INDEXES_PROC () IS\nixid CHAR;\nfound INT;\nDECLARE CURSOR index_cur IS\n SELECT ID FROM SYS_INDEXES\n WHERE SUBSTR(NAME,0,1)='\377'\nFOR UPDATE;\nBEGIN\nfound := 1;\nOPEN index_cur;\nWHILE fou"..., reserve_dict_mutex=0, trx=0x7f2ee5d2c018) at /export/home/ima/nroot/mysql_src_cmtb/storage/innobase/que/que0que.cc:1234
#19 0x0000000000f652bf in row_merge_drop_temp_indexes () at /export/home/ima/nroot/mysql_src_cmtb/storage/innobase/row/row0merge.cc:3304
#20 0x0000000000ee7516 in recv_recovery_rollback_active () at /export/home/ima/nroot/mysql_src_cmtb/storage/innobase/log/log0recv.cc:3511
#21 0x0000000000fd852a in innobase_start_or_create_for_mysql () at /export/home/ima/nroot/mysql_src_cmtb/storage/innobase/srv/srv0start.cc:2171
#22 0x0000000000e663a2 in innobase_init (p=0x3b76d90) at /export/home/ima/nroot/mysql_src_cmtb/storage/innobase/handler/ha_innodb.cc:3340
#23 0x000000000085c379 in ha_initialize_handlerton (plugin=0x3b5e8e8) at /export/home/ima/nroot/mysql_src_cmtb/sql/handler.cc:672
#24 0x0000000000b28cf3 in plugin_initialize (plugin=0x3b5e8e8) at /export/home/ima/nroot/mysql_src_cmtb/sql/sql_plugin.cc:1142
#25 0x0000000000b298cb in plugin_init (argc=0x1d3bc98, argv=0x3a6a700, flags=0) at /export/home/ima/nroot/mysql_src_cmtb/sql/sql_plugin.cc:1449
#26 0x00000000007f0021 in init_server_components () at /export/home/ima/nroot/mysql_src_cmtb/sql/mysqld.cc:3941
#27 0x00000000007f1047 in mysqld_main (argc=92, argv=0x3a6a700) at /export/home/ima/nroot/mysql_src_cmtb/sql/mysqld.cc:4481
#28 0x00000000007e9294 in main (argc=80, argv=0x7fff077414f8) at /export/home/ima/nroot/mysql_src_cmtb/sql/main.cc:25
(gdb) 

How to repeat:
ima reported this during n testing.  refer to rb#5559 problem #1.  Though rb#5559 was initially suspected to cause this, we were able to reproduce this problem in plain mysql-trunk.

The n test command line is as follows:

ibtest_ctd.pl: running with --k1 cmtb --run --mstart ima --mend innodb --mss --remote --slaves 5,20 --name msr_debug_sync_npar_k4 --nomanual --times 22 --max_failures 2 --kbs 4 --noupar --rmp 100:skip-log-bin --tcnf smallds
[27 Aug 2014 14:34] Paul Dubois
Bug affects no released version. No changelog entry needed.