[MDEV-14218] rem0rec.cc:566: Assertion `!leaf' failed, innodb_gis.kill_server failed, sporadic, Created: 2017-10-30  Updated: 2018-01-04  Resolved: 2018-01-04

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Tests
Affects Version/s: 10.2
Fix Version/s: 10.3.4, 10.2.13

Type: Bug Priority: Major
Reporter: Alice Sherepa Assignee: Marko Mäkelä
Resolution: Duplicate Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-14058 InnoDB Assertion failure !leaf on rem... Closed
relates to MDEV-13626 Merge InnoDB test cases from MySQL 5.7 Closed
relates to MDEV-14207 innodb_gis.rtree_compress, innodb_gis... Closed
relates to MDEV-14227 innodb_gis.rtree_compress2 '4k,16k,in... Closed

 Description   

innodb_gis.kill_server 'innodb' w3 [ fail ]
https://github.com/MariaDB/server/blob/mdev-13626/mysql-test/suite/innodb_gis/t/kill_server.test

2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Highest supported file format is Barracuda.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Starting crash recovery from checkpoint LSN=7700243
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=50] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=8] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=7] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=10] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=12] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=13] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=15] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=17] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=18] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=20] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=22] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=23] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=25] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=27] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=28] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=30] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=32] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=33] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=35] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Recovered page [page id: space=4, page number=37] from the doublewrite buffer.
2017-10-30 11:44:25 139746469066560 [Note] InnoDB: Starting a batch to recover 74 pages from redo log.
mysqld: /home/alice/aliska/10.2/storage/innobase/rem/rem0rec.cc:566: ulint* rec_get_offsets_func(const rec_t*, const dict_index_t*, ulint*, bool, ulint, const char*, unsigned int, mem_heap_t**): Assertion `!leaf' failed.
171030 11:44:25 [ERROR] mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
Server version: 10.2.10-MariaDB-debug-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=0
max_threads=153
thread_count=0
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63152 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x0 thread_stack 0x49000
/home/alice/aliska/10.2/sql/mysqld(my_print_stacktrace+0x38)[0x555b3755b4df]
/home/alice/aliska/10.2/sql/mysqld(handle_fatal_signal+0x3a3)[0x555b36decd62]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7f1941753390]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7f1940b0c428]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f1940b0e02a]
/lib/x86_64-linux-gnu/libc.so.6(+0x2dbd7)[0x7f1940b04bd7]
/lib/x86_64-linux-gnu/libc.so.6(+0x2dc82)[0x7f1940b04c82]
/home/alice/aliska/10.2/sql/mysqld(+0xb6a796)[0x555b3713c796]
/home/alice/aliska/10.2/sql/mysqld(+0xcb64c2)[0x555b372884c2]
/home/alice/aliska/10.2/sql/mysqld(+0xb0c046)[0x555b370de046]
/home/alice/aliska/10.2/sql/mysqld(+0xb0d8bb)[0x555b370df8bb]
/home/alice/aliska/10.2/sql/mysqld(+0xced529)[0x555b372bf529]
/home/alice/aliska/10.2/sql/mysqld(+0xd7a70f)[0x555b3734c70f]
mysys/stacktrace.c:267(my_print_stacktrace)[0x555b371f3dca]
rem/rem0rec.cc:567(rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned long*, bool, unsigned long, char const*, unsigned int, mem_block_info_t**))[0x7f19417496ba]
log/log0recv.cc:1265(recv_parse_or_apply_log_rec_body(mlog_id_t, unsigned char*, unsigned char*, unsigned long, unsigned long, bool, buf_block_t*, mtr_t*))[0x7f1940bde3dd]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
Writing a core file
----------SERVER LOG END-------------
mysqltest failed but provided no output
The result from queries just before the failure was:
< snip >
count(*)
10000
drop index c2 on t1;
create spatial index idx on t1(c2);
show create table t1;
Table	Create Table
t1	CREATE TABLE `t1` (
  `c1` int(11) DEFAULT NULL,
  `c2` geometry NOT NULL,
  SPATIAL KEY `idx` (`c2`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
check table t1;
Table	Op	Msg_type	Msg_text
test.t1	check	status	OK
truncate table t1;
call mtr.add_suppression("InnoDB: A copy of page \[page id: space=[0-9]+, page number=[0-9]+\] in the doublewrite buffer slot [0-9]+ is not within space bounds");
START TRANSACTION;
CALL insert_t1(5000);
COMMIT;
# Kill and restart

 
Thread 1 (Thread 0x7f1935207700 (LWP 29922)):
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
#1  0x0000555b3755b5d1 in my_write_core (sig=6) at /home/alice/aliska/10.2/mysys/stacktrace.c:477
#2  0x0000555b36ded10e in handle_fatal_signal (sig=6) at /home/alice/aliska/10.2/sql/signal_handler.cc:303
#3  <signal handler called>
#4  0x00007f1940b0c428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
#5  0x00007f1940b0e02a in __GI_abort () at abort.c:89
#6  0x00007f1940b04bd7 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x555b37795f10 "!leaf", file=file@entry=0x555b37795df0 "/home/alice/aliska/10.2/storage/innobase/rem/rem0rec.cc", line=line@entry=566, function=function@entry=0x555b37797200 <rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned long*, bool, unsigned long, char const*, unsigned int, mem_block_info_t**)::__PRETTY_FUNCTION__> "ulint* rec_get_offsets_func(const rec_t*, const dict_index_t*, ulint*, bool, ulint, const char*, unsigned int, mem_heap_t**)") at assert.c:92
#7  0x00007f1940b04c82 in __GI___assert_fail (assertion=0x555b37795f10 "!leaf", file=0x555b37795df0 "/home/alice/aliska/10.2/storage/innobase/rem/rem0rec.cc", line=566, function=0x555b37797200 <rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned long*, bool, unsigned long, char const*, unsigned int, mem_block_info_t**)::__PRETTY_FUNCTION__> "ulint* rec_get_offsets_func(const rec_t*, const dict_index_t*, ulint*, bool, ulint, const char*, unsigned int, mem_heap_t**)") at assert.c:101
#8  0x0000555b3713c796 in rec_get_offsets_func (rec=0x7f193669c07e "", index=0x7f1924001668, offsets=0x0, leaf=true, n_fields=18446744073709551615, file=0x555b3780e9c0 "/home/alice/aliska/10.2/storage/innobase/btr/btr0cur.cc", line=3489, heap=0x7f1935205ff8) at /home/alice/aliska/10.2/storage/innobase/rem/rem0rec.cc:566
#9  0x0000555b372884c2 in btr_cur_parse_update_in_place (ptr=0x7f19364f418a "", end_ptr=0x7f19364f418a "", page=0x7f193669c000 "", page_zip=0x0, index=0x7f1924001668) at /home/alice/aliska/10.2/storage/innobase/btr/btr0cur.cc:3489
#10 0x0000555b370de046 in recv_parse_or_apply_log_rec_body (type=MLOG_COMP_REC_UPDATE_IN_PLACE, ptr=0x7f19364f4156 "\a", end_ptr=0x7f19364f418a "", space_id=4, page_no=4, apply=true, block=0x7f193623f310, mtr=0x7f1935206550) at /home/alice/aliska/10.2/storage/innobase/log/log0recv.cc:1265
#11 0x0000555b370df8bb in recv_recover_page (just_read_in=true, block=0x7f193623f310) at /home/alice/aliska/10.2/storage/innobase/log/log0recv.cc:1771
#12 0x0000555b372bf529 in buf_page_io_complete (bpage=0x7f193623f310, evict=false) at /home/alice/aliska/10.2/storage/innobase/buf/buf0buf.cc:6015
#13 0x0000555b3734c70f in fil_aio_wait (segment=2) at /home/alice/aliska/10.2/storage/innobase/fil/fil0fil.cc:5341
#14 0x0000555b371f3dca in io_handler_thread (arg=0x555b3816ac70 <n+16>) at /home/alice/aliska/10.2/storage/innobase/srv/srv0start.cc:343
#15 0x00007f19417496ba in start_thread (arg=0x7f1935207700) at pthread_create.c:333
#16 0x00007f1940bde3dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
 
Compressed file /home/alice/aliska/10.2/mysql-test/var/log/innodb_gis.kill_server-innodb/mysqld.1/data/core
 
 
innodb_gis.alter_spatial_index 'innodb'  w1 [ pass ]   1346
***Warnings generated in error logs during shutdown after running tests: innodb_gis.kill_server
 
mysqld: /home/alice/aliska/10.2/storage/innobase/rem/rem0rec.cc:566: ulint* rec_get_offsets_func(const rec_t*, const dict_index_t*, ulint*, bool, ulint, const char*, unsigned int, mem_heap_t**): Assertion `!leaf' failed.



 Comments   
Comment by Alice Sherepa [ 2017-10-31 ]

also with test innodb_gis.rtree_compress2 https://github.com/MariaDB/server/blob/mdev-13626/mysql-test/suite/innodb_gis/t/rtree_compress2.test

innodb_gis.rtree_compress2 '4k,innodb'   [ fail ]
        Test ended at 2017-10-31 16:39:56
 
CURRENT_TEST: innodb_gis.rtree_compress2
017-10-31 16:39:52 139642380277568 [Note] InnoDB: Starting final batch to recover 207 pages from redo log.
mysqld: /home/alice/aliska/10.2/storage/innobase/rem/rem0rec.cc:566: ulint* rec_get_offsets_func(const rec_t*, const dict_index_t*, ulint*, bool, ulint, const char*, unsigned int, mem_heap_t**): Assertion `!leaf' failed.
171031 16:39:52 [ERROR] mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
Server version: 10.2.10-MariaDB-debug-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=0
max_threads=153
thread_count=0
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63152 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x0 thread_stack 0x49000
/home/alice/aliska/10.2/sql/mysqld(my_print_stacktrace+0x38)[0x55f94b5444df]
/home/alice/aliska/10.2/sql/mysqld(handle_fatal_signal+0x3a3)[0x55f94add5d62]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7f0105485390]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7f010483e428]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f010484002a]
/lib/x86_64-linux-gnu/libc.so.6(+0x2dbd7)[0x7f0104836bd7]
/lib/x86_64-linux-gnu/libc.so.6(+0x2dc82)[0x7f0104836c82]
/home/alice/aliska/10.2/sql/mysqld(+0xb6a796)[0x55f94b125796]
/home/alice/aliska/10.2/sql/mysqld(+0xcb64c2)[0x55f94b2714c2]
/home/alice/aliska/10.2/sql/mysqld(+0xb0c046)[0x55f94b0c7046]
/home/alice/aliska/10.2/sql/mysqld(+0xb0d8bb)[0x55f94b0c88bb]
/home/alice/aliska/10.2/sql/mysqld(+0xced529)[0x55f94b2a8529]
/home/alice/aliska/10.2/sql/mysqld(+0xd7a70f)[0x55f94b33570f]
/home/alice/aliska/10.2/sql/mysqld(+0xc21dca)[0x55f94b1dcdca]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7f010547b6ba]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f01049103dd]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
Writing a core file
----------SERVER LOG END-------------
mysqltest failed but provided no output
The result from queries just before the failure was:
< snip >
begin
declare i int default 1;
while (i <= total) DO
insert into t1 values (i, Point(i, i));
set i = i + 1;
end while;
end|
CALL insert_t1(70000);
select count(*) from t1;
count(*)
70000
check table t1;
Table	Op	Msg_type	Msg_text
test.t1	check	status	OK
truncate table t1;
call mtr.add_suppression("InnoDB: A copy of page \[page id: space=[0-9]+, page number=[0-9]+\] in the doublewrite buffer slot [0-9]+ is not within space bounds");
START TRANSACTION;
CALL insert_t1(5000);
COMMIT;
# Kill and restart

#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
#1  0x000055f94b5445d1 in my_write_core (sig=6) at /home/alice/aliska/10.2/mysys/stacktrace.c:477
#2  0x000055f94add610e in handle_fatal_signal (sig=6) at /home/alice/aliska/10.2/sql/signal_handler.cc:303
#3  <signal handler called>
#4  0x00007f010483e428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
#5  0x00007f010484002a in __GI_abort () at abort.c:89
#6  0x00007f0104836bd7 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x55f94b77ef10 "!leaf", file=file@entry=0x55f94b77edf0 "/home/alice/aliska/10.2/storage/innobase/rem/rem0rec.cc", line=line@entry=566, function=function@entry=0x55f94b780200 <rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned long*, bool, unsigned long, char const*, unsigned int, mem_block_info_t**)::__PRETTY_FUNCTION__> "ulint* rec_get_offsets_func(const rec_t*, const dict_index_t*, ulint*, bool, ulint, const char*, unsigned int, mem_heap_t**)") at assert.c:92
#7  0x00007f0104836c82 in __GI___assert_fail (assertion=0x55f94b77ef10 "!leaf", file=0x55f94b77edf0 "/home/alice/aliska/10.2/storage/innobase/rem/rem0rec.cc", line=566, function=0x55f94b780200 <rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned long*, bool, unsigned long, char const*, unsigned int, mem_block_info_t**)::__PRETTY_FUNCTION__> "ulint* rec_get_offsets_func(const rec_t*, const dict_index_t*, ulint*, bool, ulint, const char*, unsigned int, mem_heap_t**)") at assert.c:101
#8  0x000055f94b125796 in rec_get_offsets_func (rec=0x7f00fe53007e "", index=0x7f00dc001968, offsets=0x0, leaf=true, n_fields=18446744073709551615, file=0x55f94b7f79c0 "/home/alice/aliska/10.2/storage/innobase/btr/btr0cur.cc", line=3489, heap=0x7f00fce08ff8) at /home/alice/aliska/10.2/storage/innobase/rem/rem0rec.cc:566
#9  0x000055f94b2714c2 in btr_cur_parse_update_in_place (ptr=0x7f00fe2f9cf2 "", end_ptr=0x7f00fe2f9cf2 "", page=0x7f00fe530000 "\251\250\361\061", page_zip=0x7f00fdf27b38, index=0x7f00dc001968) at /home/alice/aliska/10.2/storage/innobase/btr/btr0cur.cc:3489
#10 0x000055f94b0c7046 in recv_parse_or_apply_log_rec_body (type=MLOG_COMP_REC_UPDATE_IN_PLACE, ptr=0x7f00fe2f9cbe "\a", end_ptr=0x7f00fe2f9cf2 "", space_id=4, page_no=4, apply=true, block=0x7f00fdf27b10, mtr=0x7f00fce09550) at /home/alice/aliska/10.2/storage/innobase/log/log0recv.cc:1265
#11 0x000055f94b0c88bb in recv_recover_page (just_read_in=true, block=0x7f00fdf27b10) at /home/alice/aliska/10.2/storage/innobase/log/log0recv.cc:1771
#12 0x000055f94b2a8529 in buf_page_io_complete (bpage=0x7f00fdf27b10, evict=false) at /home/alice/aliska/10.2/storage/innobase/buf/buf0buf.cc:6015
#13 0x000055f94b33570f in fil_aio_wait (segment=2) at /home/alice/aliska/10.2/storage/innobase/fil/fil0fil.cc:5341
#14 0x000055f94b1dcdca in io_handler_thread (arg=0x55f94c153c70 <n+16>) at /home/alice/aliska/10.2/storage/innobase/srv/srv0start.cc:343
#15 0x00007f010547b6ba in start_thread (arg=0x7f00fce0a700) at pthread_create.c:333
#16 0x00007f01049103dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Comment by Marko Mäkelä [ 2018-01-04 ]

This is a duplicate of MDEV-14058.

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