[MDEV-17622] Assertion `block->type == PAGECACHE_EMPTY_PAGE || block->type == type || type == PAGECACHE_LSN_PAGE || type == PAGECACHE_READ_UNKNOWN_PAGE || block->type == PAGECACHE_READ_UNKNOWN_PAGE' failed in pagecache_read or ER_CRASHED_ON_USAGE Created: 2018-11-05  Updated: 2023-07-10  Resolved: 2023-07-10

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - Aria
Affects Version/s: 10.2, 10.3
Fix Version/s: N/A

Type: Bug Priority: Minor
Reporter: Elena Stepanova Assignee: Michael Widenius
Resolution: Won't Fix Votes: 0
Labels: not-10.4, not-10.5, not-10.6

Issue Links:
Relates
relates to MDEV-17636 Assertion `pagecache->block_root[i].s... Closed
relates to MDEV-17659 Error 175 "File too short; Expected m... Closed
relates to MDEV-17665 Assertion `!share || share->page_type... Closed
relates to MDEV-17754 AddressSanitizer: heap-use-after-free... Confirmed
relates to MDEV-17659 Error 175 "File too short; Expected m... Closed
relates to MDEV-17665 Assertion `!share || share->page_type... Closed
relates to MDEV-20467 Multiple "Warning: Enabling keys got ... Open
relates to MDEV-23296 Assertion `block->type == PAGECACHE_E... Closed

 Description   

I'm demoting it to Minor, because after related fixes the failure is reproducible in 10.2-10.3 and doesn't appear to affect non-debug builds

The test case is non-deterministic, run with --repeat=N. It usually fails for me within several attempts on 10.2/10.3 debug, but it can vary on different machines and builds.

--source include/have_sequence.inc
 
 
 
CREATE TABLE t1 (id INT, f INT, KEY (f), PRIMARY KEY (id)) ENGINE=Aria;
 
ALTER TABLE t1 DISABLE KEYS;
 
INSERT INTO t1 SELECT seq, 0 FROM seq_1_to_200;
 
 
 
--connect (con1,localhost,root,,test)
 
--send
 
  CREATE TABLE t2 SELECT f FROM t1;
 
 
 
--connection default
 
--let $run= 100
 
--disable_query_log
 
--disable_result_log
 
while ($run)
 
{
 
  --error ER_BAD_FIELD_ERROR
 
  INSERT INTO t1 (x) SELECT seq FROM seq_1_to_100;
 
  --dec $run
 
}
 
--enable_query_log
 
--enable_result_log
 
 
 
# Cleanup
 
--connection con1
 
--reap
 
--disconnect con1
 
--connection default
 
DROP TABLE t1, t2;

10.2 14a18d7d

 
mysqld: /data/src/10.2/storage/maria/ma_pagecache.c:3416: pagecache_read: Assertion `block->type == PAGECACHE_EMPTY_PAGE || block->type == type || type == PAGECACHE_LSN_PAGE || type == PAGECACHE_READ_UNKNOW
 
N_PAGE || block->type == PAGECACHE_READ_UNKNOWN_PAGE' failed.
 
210426 21:08:34 [ERROR] mysqld got signal 6 ;
 
 
 
#6  0x00007f6bd6ff1729 in __assert_fail_base (fmt=0x7f6bd7187588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5626246a4278 "block->type == PAGECACHE_EMPTY_PAGE || block->type == type || type == PAGECACHE_LSN_PAGE || type == PAGECACHE_READ_UNKNOWN_PAGE || block->type == PAGECACHE_READ_UNKNOWN_PAGE", file=0x5626246a2d78 "/data/src/10.2/storage/maria/ma_pagecache.c", line=3416, function=<optimized out>) at assert.c:92
 
#7  0x00007f6bd7002f36 in __GI___assert_fail (assertion=0x5626246a4278 "block->type == PAGECACHE_EMPTY_PAGE || block->type == type || type == PAGECACHE_LSN_PAGE || type == PAGECACHE_READ_UNKNOWN_PAGE || block->type == PAGECACHE_READ_UNKNOWN_PAGE", file=0x5626246a2d78 "/data/src/10.2/storage/maria/ma_pagecache.c", line=3416, function=0x5626246a4f58 <__PRETTY_FUNCTION__.18793> "pagecache_read") at assert.c:101
 
#8  0x000056262420ecbc in pagecache_read (pagecache=0x562625596960 <maria_pagecache_var>, file=0x7f6bc007e510, pageno=1, level=0, buff=0x7f6bb40b7660 '\245' <repeats 200 times>..., type=PAGECACHE_PLAIN_PAGE, lock=PAGECACHE_LOCK_LEFT_UNLOCKED, page_link=0x7f6bd0fc3110) at /data/src/10.2/storage/maria/ma_pagecache.c:3416
 
#9  0x000056262424f228 in _ma_scan_block_record (info=0x7f6bc007e0d0, record=0x7f6bc018ef50 "\377", record_pos=0, skip_deleted=1 '\001') at /data/src/10.2/storage/maria/ma_blockrec.c:5508
 
#10 0x000056262423c2ce in maria_scan (info=0x7f6bc007e0d0, record=0x7f6bc018ef50 "\377") at /data/src/10.2/storage/maria/ma_scan.c:54
 
#11 0x00005626241e7b74 in ha_maria::rnd_next (this=0x7f6bc009edd8, buf=0x7f6bc018ef50 "\377") at /data/src/10.2/storage/maria/ha_maria.cc:2477
 
#12 0x0000562623c4ce83 in handler::ha_rnd_next (this=0x7f6bc009edd8, buf=0x7f6bc018ef50 "\377") at /data/src/10.2/sql/handler.cc:2669
 
#13 0x0000562623dc1147 in rr_sequential (info=0x7f6bb40141a0) at /data/src/10.2/sql/records.cc:492
 
#14 0x0000562623a36b7b in join_init_read_record (tab=0x7f6bb40140d8) at /data/src/10.2/sql/sql_select.cc:19791
 
#15 0x0000562623a348ba in sub_select (join=0x7f6bb4012600, join_tab=0x7f6bb40140d8, end_of_records=false) at /data/src/10.2/sql/sql_select.cc:18862
 
#16 0x0000562623a33e7e in do_select (join=0x7f6bb4012600, procedure=0x0) at /data/src/10.2/sql/sql_select.cc:18409
 
#17 0x0000562623a0da5f in JOIN::exec_inner (this=0x7f6bb4012600) at /data/src/10.2/sql/sql_select.cc:3642
 
#18 0x0000562623a0cf06 in JOIN::exec (this=0x7f6bb4012600) at /data/src/10.2/sql/sql_select.cc:3437
 
#19 0x0000562623a0e0e0 in mysql_select (thd=0x7f6bb4000d90, tables=0x7f6bb4011cf0, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2416184064, result=0x7f6bb4012510, unit=0x7f6bb4004988, select_lex=0x7f6bb40050c8) at /data/src/10.2/sql/sql_select.cc:3840
 
#20 0x0000562623a02242 in handle_select (thd=0x7f6bb4000d90, lex=0x7f6bb40048c8, result=0x7f6bb4012510, setup_tables_done_option=0) at /data/src/10.2/sql/sql_select.cc:361
 
#21 0x0000562623aa36a7 in Sql_cmd_create_table::execute (this=0x7f6bb4011560, thd=0x7f6bb4000d90) at /data/src/10.2/sql/sql_table.cc:10997
 
#22 0x00005626239cb7bb in mysql_execute_command (thd=0x7f6bb4000d90) at /data/src/10.2/sql/sql_parse.cc:6020
 
#23 0x00005626239d0620 in mysql_parse (thd=0x7f6bb4000d90, rawbuf=0x7f6bb4011480 "CREATE TABLE t2 SELECT f FROM t1", length=32, parser_state=0x7f6bd0fc4570, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7796
 
#24 0x00005626239be84a in dispatch_command (command=COM_QUERY, thd=0x7f6bb4000d90, packet=0x7f6bb4060e81 "CREATE TABLE t2 SELECT f FROM t1", packet_length=32, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1827
 
#25 0x00005626239bd345 in do_command (thd=0x7f6bb4000d90) at /data/src/10.2/sql/sql_parse.cc:1381
 
#26 0x0000562623b1874c in do_handle_one_connection (connect=0x5626262dfb20) at /data/src/10.2/sql/sql_connect.cc:1336
 
#27 0x0000562623b184b1 in handle_one_connection (arg=0x5626262dfb20) at /data/src/10.2/sql/sql_connect.cc:1241
 
#28 0x00005626243433ae in pfs_spawn_thread (arg=0x562626321860) at /data/src/10.2/storage/perfschema/pfs.cc:1869
 
#29 0x00007f6bd7512609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#30 0x00007f6bd70ee293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Reproducible on 10.2, 10.3.
Not reproducible on 10.4, possibly due to patches for MDEV-17665/MDEV-23296 and/or related bugs in 10.4+.
No obvious problem on a non-debug build.

 Comments   
Comment by Alice Sherepa [ 2020-02-11 ]

similar one on 10.5:

10.5 a18639f1a913b446f32d

 
mysqld: /10.5/storage/maria/ma_pagecache.c:3806: pagecache_read: Assertion `block->type == PAGECACHE_EMPTY_PAGE || block->type == type || type == PAGECACHE_LSN_PAGE || type == PAGECACHE_READ_UNKNOWN_PAGE || block->type == PAGECACHE_READ_UNKNOWN_PAGE' failed.
 
200724 13:33:25 [ERROR] mysqld got signal 6 ;
 
 
 
Server version: 10.5.5-MariaDB-debug-log
 
 
 
linux/raise.c:51(__GI_raise)[0x7f0cd9a7b7bb]
 
stdlib/abort.c:81(__GI_abort)[0x7f0cd9a66535]
 
intl/loadmsgcat.c:1177(_nl_load_domain)[0x7f0cd9a6640f]
 
??:0(__assert_fail)[0x7f0cd9a74102]
 
maria/ma_pagecache.c:3807(pagecache_read)[0x5609c034701e]
 
maria/ma_blockrec.c:5524(_ma_scan_block_record)[0x5609c0332a24]
 
maria/ma_scan.c:54(maria_scan)[0x5609c02d2b77]
 
maria/ha_maria.cc:2509(ha_maria::rnd_next(unsigned char*))[0x5609c0047d7d]
 
sql/handler.cc:3060(handler::ha_rnd_next(unsigned char*))[0x5609c01fd93d]
 
sql/records.cc:511(rr_sequential(READ_RECORD*))[0x5609bfc3adb9]
 
sql/records.h:79(READ_RECORD::read_record())[0x5609bfd6ed1c]
 
sql/sql_select.cc:20660(sub_select(JOIN*, st_join_table*, bool))[0x5609bfd42d25]
 
sql/sql_select.cc:20175(do_select(JOIN*, Procedure*))[0x5609bfd41e51]
 
sql/sql_select.cc:4450(JOIN::exec_inner())[0x5609bfd43572]
 
sql/sql_select.cc:4232(JOIN::exec())[0x5609bfd333c8]
 
sql/sql_select.cc:417(handle_select(THD*, LEX*, select_result*, unsigned long))[0x5609bfcf8de3]
 
sql/sql_parse.cc:6209(execute_sqlcom_select(THD*, TABLE_LIST*))[0x5609bfcf010f]
 
sql/sql_parse.cc:3931(mysql_execute_command(THD*))[0x5609bfcfdc25]
 
sql/sql_parse.cc:7993(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x5609bfcea065]
 
sql/sql_parse.cc:1869(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x5609bfce87a5]
 
sql/sql_parse.cc:1347(do_command(THD*))[0x5609bfe8bb49]
 
sql/sql_connect.cc:1410(do_handle_one_connection(CONNECT*, bool))[0x5609bfe8b8b2]
 
sql/sql_connect.cc:1314(handle_one_connection)[0x5609c03c391f]
 
nptl/pthread_create.c:487(start_thread)[0x7f0cda534fa3]
 
x86_64/clone.S:97(clone)[0x7f0cd9b3d4cf]
 
 
 
Query (0x7f0c7c014ff0): SELECT  * FROM `view_E`

Comment by Elena Stepanova [ 2020-07-27 ]

It will probably end up to be a duplicate of MDEV-17665 (this one is older, but MDEV-17665 contains more variations and a better-looking test case). I will keep both open for now since the test cases are non-deterministic, there is no way to know which one will work better when/if it comes to debugging.

Comment by Alice Sherepa [ 2021-02-22 ]

I'm still getting this assertion in tests from time to time, but probably it should be reported separately
(I tried the test case from the description, no failures on 10000 repeats))

mysqld: /10.3/storage/maria/ma_pagecache.c:3420: pagecache_read: Assertion `block->type == PAGECACHE_EMPTY_PAGE || block->type == type || type == PAGECACHE_LSN_PAGE || type == PAGECACHE_READ_UNKNOWN_PAGE || block->type == PAGECACHE_READ_UNKNOWN_PAGE' failed.
 
210217 16:40:20 [ERROR] mysqld got signal 6 ;
 
 
 
Server version: 10.3.28-MariaDB-debug-log
 
 
 
linux/raise.c:51(__GI_raise)[0x7f5792e837bb]
 
stdlib/abort.c:81(__GI_abort)[0x7f5792e6e535]
 
intl/loadmsgcat.c:1177(_nl_load_domain)[0x7f5792e6e40f]
 
/lib/x86_64-linux-gnu/libc.so.6(+0x30102)[0x7f5792e7c102]
 
maria/ma_pagecache.c:3421(pagecache_read)[0x5629bd897553]
 
maria/ma_blockrec.c:5508(_ma_scan_block_record)[0x5629bd9554b2]
 
maria/ma_scan.c:54(maria_scan)[0x5629bd91d6e8]
 
maria/ha_maria.cc:2404(ha_maria::rnd_next(unsigned char*))[0x5629bd82af0b]
 
sql/handler.cc:2847(handler::ha_rnd_next(unsigned char*))[0x5629bc87dd4d]
 
sql/records.cc:485(rr_sequential(READ_RECORD*))[0x5629bcc9f2d1]
 
sql/records.h:70(READ_RECORD::read_record())[0x5629bbf30bde]
 
sql/sql_select.cc:20647(join_init_read_record(st_join_table*))[0x5629bc20e3d2]
 
sql/sql_select.cc:19708(sub_select(JOIN*, st_join_table*, bool))[0x5629bc206a4b]
 
sql/sql_select.cc:19251(do_select(JOIN*, Procedure*))[0x5629bc204935]
 
sql/sql_select.cc:4124(JOIN::exec_inner())[0x5629bc1954d2]
 
sql/sql_select.cc:3919(JOIN::exec())[0x5629bc192eaa]
 
sql/sql_select.cc:4325(mysql_select(THD*, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*))[0x5629bc196773]
 
sql/sql_select.cc:370(handle_select(THD*, LEX*, select_result*, unsigned long))[0x5629bc16d270]
 
sql/sql_parse.cc:6316(execute_sqlcom_select(THD*, TABLE_LIST*))[0x5629bc0d96b0]
 
sql/sql_parse.cc:3847(mysql_execute_command(THD*))[0x5629bc0c71f0]
 
sql/sql_parse.cc:7840(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x5629bc0e37a7]
 
sql/sql_parse.cc:1855(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x5629bc0b9e7c]
 
sql/sql_parse.cc:1398(do_command(THD*))[0x5629bc0b65b7]
 
sql/sql_connect.cc:1403(do_handle_one_connection(CONNECT*))[0x5629bc4a73d0]
 
sql/sql_connect.cc:1309(handle_one_connection)[0x5629bc4a6c88]
 
nptl/pthread_create.c:487(start_thread)[0x7f57935c1fa3]
 
x86_64/clone.S:97(clone)[0x7f5792f454cf]
 
 
 
Query (0x62b00005b290):  SELECT COUNT(*) FROM `D_Aria` WHERE row_start IN (SELECT row_end FROM `BB_Aria`)

Comment by Elena Stepanova [ 2021-04-26 ]

The original test case stopped reproducing the failure after the patch for MDEV-17659. The scenario was very similar in these two bug reports, so it's not surprising.
I have re-written the description entirely with a new test case, which still reproduces the failure on 10.2/10.3, but not on 10.4+, possibly to the fix for MDEV-17665 / MDEV-23296.

For a note, there is still a problem in 10.4 which causes the same assertion failure in pagecache_read, but with otherwise an entirely different stack trace – something coming from ha_maria::repair and going through _ma_flush_pending_blocks. When we get a test case for that, it should probably be filed separately.

Comment by Elena Stepanova [ 2023-07-10 ]

Closing as 10.3 is EOL.
There is a comment about the failure being observed on higher versions, but without a test case.
MDEV-31656 shows a somewhat similar assertion failure, but on a very different use case, ALTER instead of SELECT.

Generated at Thu Feb 08 08:37:52 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.