Bug #58815 btr_estimate_n_rows_in_range_on_level() can read a freed page
Submitted: 8 Dec 2010 13:12 Modified: 14 Jan 2012 11:21
Reporter: Marko Mäkelä Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:5.5, 5.6.3 OS:Any
Assigned to: Vasil Dimov CPU Architecture:Any

[8 Dec 2010 13:12] Marko Mäkelä
Description:
This came up when testing Bug #55284.

InnoDB: Failing assertion: !block->page.file_page_was_freed

 #6  0x00000000009076fb in buf_page_get_gen (space=5, zip_size=0, offset=41,
     rw_latch=1, guess=0x0, mode=10,
     file=0xbada78 "/spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/btr/btr0cur.c", line=3257, mtr=0x40117350)
     at /spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/buf/buf0buf.c:3066
 #7  0x00000000008ee2b0 in btr_estimate_n_rows_in_range_on_level (
     index=0x11d748e8, slot1=0x40119d80, slot2=0x40117e40,
     n_rows_on_prev_level=5, is_n_rows_exact=0x40117d88)
     at /spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/btr/btr0cur.c:3256
 #8  0x00000000008ee928 in btr_estimate_n_rows_in_range (index=0x11d748e8,
     tuple1=0x2aabe0161c68, mode1=2, tuple2=0x2aabe0161cd0, mode2=1)
     at /spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/btr/btr0cur.c:3475
 #9  0x0000000000856579 in ha_innobase::records_in_range (this=0x11e8d320,
     keynr=3, min_key=0x4011bea0, max_key=0x4011be80)
     at /spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/handler/ha_innodb.cc:7500
#10 0x00000000007d46b7 in check_quick_keys (param=0x4011c100, idx=0,
     key_tree=0x2aabe0028c20, min_key=0x4011c258 "", min_key_flag=0,
     min_keypart=-1, max_key=0x4011d156 "", max_key_flag=0, max_keypart=-1)
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/opt_range.cc:7789
 #11 0x00000000007d494d in check_quick_select (param=0x4011c100, idx=0,
     tree=0x2aabe0028c20, update_tbl_stats=true)
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/opt_range.cc:7560
 #12 0x00000000007d4bd8 in get_key_scans_params (param=0x4011c100,
     tree=0x2aabe00287c8, index_read_must_be_used=false, update_tbl_stats=true,
     read_time=1236.0999999999999)
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/opt_range.cc:4959
 #13 0x00000000007dd3de in SQL_SELECT::test_quick_select (this=0x11fabde8,
     thd=0x2aabd41071e0, keys_to_use=..., prev_tables=0,
     limit=18446744073709551615, force_quick_range=false)
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/opt_range.cc:2321
 #14 0x00000000005f76cc in get_quick_record_count (thd=0x2aabd41071e0,
     select=0x11fabde8, table=0x11dd0d00, keys=0x11faba58,
     limit=18446744073709551615)
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/sql_select.cc:2605
 #15 0x00000000005fc2ad in make_join_statistics (join=0x2aabe007fa30,
     tables_arg=0x11faaa28, conds=0x11fab178, keyuse_array=0x2aabe0080fe8)
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/sql_select.cc:3039
 #16 0x00000000005fe25c in JOIN::optimize (this=0x2aabe007fa30)
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/sql_select.cc:1050
 #17 0x00000000006022e0 in mysql_select (thd=0x2aabd41071e0,
     rref_pointer_array=0x2aabd41093a8, tables=0x11faaa28, wild_num=1,
     fields=..., conds=0x11fab178, og_num=0, order=0x0, group=0x0, having=0x0,
     proc_param=0x0, select_options=2148272640, result=0x11fab3a8,
     unit=0x2aabd4108bb8, select_lex=0x2aabd41091d8)
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/sql_select.cc:2556
 #18 0x000000000060723b in handle_select (thd=0x2aabd41071e0,
     lex=0x2aabd4108b08, result=0x11fab3a8, setup_tables_done_option=0)
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/sql_select.cc:297
 #19 0x00000000005b9557 in execute_sqlcom_select (thd=0x2aabd41071e0,
     all_tables=0x11faaa28)
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/sql_parse.cc:4452
 #20 0x00000000005ba2a8 in mysql_execute_command (thd=0x2aabd41071e0)
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/sql_parse.cc:2046
 #21 0x00000000005c0529 in mysql_parse (thd=0x2aabd41071e0,
     rawbuf=0x11faa830 "select * from ibstd_5 where c like 'khd%'", length=41,
     parser_state=0x401209b0)
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/sql_parse.cc:5496

How to repeat:
Compile with UNIV_DEBUG_FILE_ACCESSES. Use a buffer pool that is larger than the workload.

Suggested fix:
Prove that the code works correctly, even though it is accessing garbage pages, or fix it.

At the very least, add a source code comment that explains why this is OK and why the assertion failure is nothing to worry about.

Some background: In tablespace 0, garbage pages may be anything. In other tablespaces, the choice of pages is smaller: bitmap pages (pages n*page_size+m where m=0 or 1), B-tree pages (belonging to any index of the table, on any level), BLOB pages, empty (all-zero) pages and freed pages. Note that testing FIL_PAGE_TYPE is not sufficient, because older versions of InnoDB wrote garbage to FIL_PAGE_TYPE. That garbage could by coincidence be equal to FIL_PAGE_INDEX. Note that the FIL_PAGE_TYPE is not (in present versions of InnoDB) reset when a page is freed.
[28 Feb 2011 16:08] Vasil Dimov
A patch to make this more reproducable:

-- cut ---
--- storage/innobase/btr/btr0cur.c	revid:vasil.dimov@oracle.com-20110228090722-0hsg605yvm2ypl9c
+++ storage/innobase/btr/btr0cur.c	2011-02-28 16:01:24 +0000
@@ -3293,12 +3293,13 @@ btr_estimate_n_rows_in_range_on_level(
 			n_rows += page_get_n_recs(page);
 		}
 
 		page_no = btr_page_get_next(page, &mtr);
 
 		mtr_commit(&mtr);
+		sleep(1);
 
 		if (n_pages_read == N_PAGES_READ_LIMIT
 		    || page_no == FIL_NULL) {
 			/* Either we read too many pages or
 			we reached the end of the level without passing
 			through slot2->page_no, the tree must have changed
--- cut ---

./ibtest3 &
./ibtest3a &
./ibtest3a &
./ibtest3b &
./ibtest3b &
[27 Mar 2011 6:04] MySQL Verification Team
i got this on mysql-trunk when running zlibdml.php in 3 threads. attached stack/gdb output.

Attachment: bug58815_mysql-trunk_gdb_output.txt (text/plain), 12.45 KiB.

[12 May 2011 9:38] MySQL Verification Team
this prevents use of a debug build to try find other bugs. upgrading severity.

Version: '5.5.12-debug'  socket: ''  port: 3306  MySQL Community Server - Debug (GPL)
110512 11:24:01  InnoDB: Assertion failure in thread 1588 in file buf0buf.c line 3079
InnoDB: Failing assertion: !block->page.file_page_was_freed
InnoDB: We intentionally generate a memory trap.
mysqld-debug.exe!buf_page_get_gen()[buf0buf.c:3079]
mysqld-debug.exe!btr_estimate_n_rows_in_range_on_level()[btr0cur.c:3269]
mysqld-debug.exe!btr_estimate_n_rows_in_range()[btr0cur.c:3489]
mysqld-debug.exe!ha_innobase::records_in_range()[ha_innodb.cc:7543]
mysqld-debug.exe!check_quick_keys()[opt_range.cc:7789]
mysqld-debug.exe!check_quick_select()[opt_range.cc:7560]
mysqld-debug.exe!get_key_scans_params()[opt_range.cc:4959]
mysqld-debug.exe!SQL_SELECT::test_quick_select()[opt_range.cc:2322]
mysqld-debug.exe!get_quick_record_count()[sql_select.cc:2611]
mysqld-debug.exe!make_join_statistics()[sql_select.cc:3044]
mysqld-debug.exe!JOIN::optimize()[sql_select.cc:1056]
mysqld-debug.exe!mysql_select()[sql_select.cc:2561]
mysqld-debug.exe!handle_select()[sql_select.cc:297]
mysqld-debug.exe!execute_sqlcom_select()[sql_parse.cc:4466]
mysqld-debug.exe!mysql_execute_command()[sql_parse.cc:2052]
mysqld-debug.exe!mysql_parse()[sql_parse.cc:5503]
mysqld-debug.exe!dispatch_command()[sql_parse.cc:1034]
mysqld-debug.exe!do_command()[sql_parse.cc:771]
mysqld-debug.exe!do_handle_one_connection()[sql_connect.cc:771]
mysqld-debug.exe!handle_one_connection()[sql_connect.cc:707]
mysqld-debug.exe!pthread_start()[my_winthread.c:61]
mysqld-debug.exe!_callthreadstartex()[threadex.c:348]
mysqld-debug.exe!_threadstartex()[threadex.c:331]
kernel32.dll!GetModuleFileNameA()

t some variables.
s may be invalid and cause the dump to abort.
0A0): select * from `blobtest_2` where `id`<=2558 limit 1
D (thread ID): 2
KILLED
[14 Jan 2012 11:21] Sveta Smirnova
Synchronizing records in this and internal bug databases. Bug is not repeatable anymore.
[1 Dec 2016 8:21] jony wang
we may encounter the same bug in production enviroment 

the stack is as follow

(gdb) bt
#0  0x00007f6c1f12f621 in pthread_kill () from /home/opt/gcc-4.8.2.bpkg-r2/gcc-4.8.2.bpkg-r2/lib64/libpthread-2.18.so
#1  0x0000000000664a83 in handle_fatal_signal (sig=6) at /home/mysql/opbin/output/mysql-5623-trunk/sql/signal_handler.cc:230
#2  <signal handler called>
#3  0x00007f6c1df523f7 in raise () from /home/opt/gcc-4.8.2.bpkg-r2/gcc-4.8.2.bpkg-r2/lib64/libc-2.18.so
#4  0x00007f6c1df537d8 in abort () from /home/opt/gcc-4.8.2.bpkg-r2/gcc-4.8.2.bpkg-r2/lib64/libc-2.18.so
#5  0x00007f6c1df90554 in __libc_message () from /home/opt/gcc-4.8.2.bpkg-r2/gcc-4.8.2.bpkg-r2/lib64/libc-2.18.so
#6  0x00007f6c1df95dbe in malloc_printerr () from /home/opt/gcc-4.8.2.bpkg-r2/gcc-4.8.2.bpkg-r2/lib64/libc-2.18.so
#7  0x00007f6c1df96a97 in _int_free () from /home/opt/gcc-4.8.2.bpkg-r2/gcc-4.8.2.bpkg-r2/lib64/libc-2.18.so
#8  0x0000000000a4718c in buf_page_free_descriptor (bpage=0x7f6680e28d80)
    at /home/mysql/opbin/output/mysql-5623-trunk/storage/innobase/include/buf0buf.ic:876
#9  buf_page_get_gen (space=space@entry=2432, zip_size=zip_size@entry=8192, offset=offset@entry=449929, rw_latch=rw_latch@entry=1, 
    guess=<optimized out>, guess@entry=0x0, mode=mode@entry=16, 
    file=file@entry=0xd098a8 "/home/mysql/opbin/output/mysql-5623-trunk/storage/innobase/btr/btr0cur.cc", line=line@entry=3613, 
    mtr=mtr@entry=0x7f5f14ece890) at /home/mysql/opbin/output/mysql-5623-trunk/storage/innobase/buf/buf0buf.cc:2830
#10 0x0000000000a33ded in btr_estimate_n_rows_in_range_on_level (slot2=0x7f5f14ed0cd0, slot2=0x7f5f14ed0cd0, is_n_rows_exact=<synthetic pointer>, 
    n_rows_on_prev_level=41, slot1=0x7f5f14eced90, index=0x7f5edc39c608)
    at /home/mysql/opbin/output/mysql-5623-trunk/storage/innobase/btr/btr0cur.cc:3613
#11 btr_estimate_n_rows_in_range (index=index@entry=0x7f5edc39c608, tuple1=tuple1@entry=0x7f5e625b81d8, mode1=<optimized out>, 
    tuple2=tuple2@entry=0x7f5e625b8280, mode2=<optimized out>) at /home/mysql/opbin/output/mysql-5623-trunk/storage/innobase/btr/btr0cur.cc:3844
#12 0x00000000009460af in ha_innobase::records_in_range (this=0x7f5d66d6af70, keynr=<optimized out>, min_key=<optimized out>, 
    max_key=0x7f5f14ed2c90) at /home/mysql/opbin/output/mysql-5623-trunk/storage/innobase/handler/ha_innodb.cc:10452
#13 0x00000000005a70b0 in handler::multi_range_read_info_const (this=0x7f5d66d6af70, keyno=keyno@entry=2, seq=0x7f5f14ed2da0, 
    seq_init_param=<optimized out>, n_ranges_arg=<optimized out>, bufsz=bufsz@entry=0x7f5f14ed2d20, flags=flags@entry=0x7f5f14ed2d10, 
    cost=cost@entry=0x7f5f14ed32f0) at /home/mysql/opbin/output/mysql-5623-trunk/sql/handler.cc:5673
#14 0x00000000005af1fa in DsMrr_impl::dsmrr_info_const (this=0x7f5d66d6b1f8, keyno=2, seq=<optimized out>, seq_init_param=<optimized out>, 
    n_ranges=<optimized out>, bufsz=0x7f5f14ed3250, flags=0x7f5f14ed3230, cost=0x7f5f14ed32f0)
    at /home/mysql/opbin/output/mysql-5623-trunk/sql/handler.cc:6315
#15 0x00000000007ed462 in check_quick_select (param=param@entry=0x7f5f14ed3370, idx=idx@entry=2, index_only=index_only@entry=false, 
    tree=<optimized out>, update_tbl_stats=update_tbl_stats@entry=true, mrr_flags=mrr_flags@entry=0x7f5f14ed3230, 
    bufsize=bufsize@entry=0x7f5f14ed3250, cost=cost@entry=0x7f5f14ed32f0) at /home/mysql/opbin/output/mysql-5623-trunk/sql/opt_range.cc:9503
#16 0x00000000007fb1b4 in get_key_scans_params (read_time=1.21, update_tbl_stats=true, index_read_must_be_used=false, tree=0x7f5d56f9d838, 
    param=0x7f5f14ed3370) at /home/mysql/opbin/output/mysql-5623-trunk/sql/opt_range.cc:5600
#17 SQL_SELECT::test_quick_select (this=this@entry=0x7f5d7570bcc0, thd=thd@entry=0x539e7410, keys_to_use=..., keys_to_use@entry=..., 
    prev_tables=prev_tables@entry=0, limit=limit@entry=18446744073709551615, force_quick_range=force_quick_range@entry=false, 
    interesting_order=interesting_order@entry=st_order::ORDER_NOT_RELEVANT) at /home/mysql/opbin/output/mysql-5623-trunk/sql/opt_range.cc:2900
#18 0x000000000074feb4 in check_quick (limit=18446744073709551615, force_quick_range=false, thd=0x539e7410, this=0x7f5d7570bcc0)
    at /home/mysql/opbin/output/mysql-5623-trunk/sql/opt_range.h:938
#19 mysql_update (thd=thd@entry=0x539e7410, table_list=0x7f5d6f6f2f40, fields=..., values=..., conds=0x7f5d6f6f3da8, order_num=<optimized out>, 
    order=0x0, limit=18446744073709551615, handle_duplicates=DUP_ERROR, ignore=false, found_return=found_return@entry=0x7f5f14ed5ae0, 
    updated_return=updated_return@entry=0x7f5f14ed6040) at /home/mysql/opbin/output/mysql-5623-trunk/sql/sql_update.cc:463
#20 0x00000000006e63dc in mysql_execute_command (thd=thd@entry=0x539e7410) at /home/mysql/opbin/output/mysql-5623-trunk/sql/sql_parse.cc:3323
---Type <return> to continue, or q <return> to quit---
#21 0x00000000006e9f58 in mysql_parse (thd=thd@entry=0x539e7410, rawbuf=<optimized out>, length=<optimized out>, 
    parser_state=parser_state@entry=0x7f5f14ed6770) at /home/mysql/opbin/output/mysql-5623-trunk/sql/sql_parse.cc:6373
#22 0x00000000006eb4a1 in dispatch_command (command=COM_QUERY, thd=0x539e7410, packet=<optimized out>, packet_length=<optimized out>)
    at /home/mysql/opbin/output/mysql-5623-trunk/sql/sql_parse.cc:1332
#23 0x00000000006ed205 in do_command (thd=<optimized out>) at /home/mysql/opbin/output/mysql-5623-trunk/sql/sql_parse.cc:1034
#24 0x00000000006b4b8d in do_handle_one_connection (thd_arg=thd_arg@entry=0x53deeec0)
    at /home/mysql/opbin/output/mysql-5623-trunk/sql/sql_connect.cc:982
#25 0x00000000006b4bd8 in handle_one_connection (arg=arg@entry=0x53deeec0) at /home/mysql/opbin/output/mysql-5623-trunk/sql/sql_connect.cc:898
#26 0x0000000000923c93 in pfs_spawn_thread (arg=0x550b6f80) at /home/mysql/opbin/output/mysql-5623-trunk/storage/perfschema/pfs.cc:1860
#27 0x00007f6c1f12a1c3 in start_thread () from /home/opt/gcc-4.8.2.bpkg-r2/gcc-4.8.2.bpkg-r2/lib64/libpthread-2.18.so
#28 0x00007f6c1e00412d in clone () from /home/opt/gcc-4.8.2.bpkg-r2/gcc-4.8.2.bpkg-r2/lib64/libc-2.18.so