Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.5.2
Description
We started to get a new type of failures in a test on 10.5:
10.5 ccc06931c3c7be094f6dcddeb45589f06cf0c8af |
CURRENT_TEST: encryption.innodb_encryption_discard_import
|
mysqltest: At line 154: query 'DROP TABLE t1, t2, t3' failed: 2013: Lost connection to MySQL server during query
|
…
|
Version: '10.5.3-MariaDB-debug-log' socket: '/dev/shm/var/tmp/1/mysqld.1.sock' port: 16000 Source distribution
|
2020-04-08 4:52:36 0 [ERROR] InnoDB: Record 126 is above rec heap top 120
|
2020-04-08 4:52:36 0 [Note] InnoDB: Uncompressed page, stored checksum in field1 1586335936, calculated checksums for field1: crc32 3521116018, innodb 2228745977, page type 17855 == INDEX.none 3735928559, stored checksum in field2 15335816, calculated checksums for field2: crc32 3521116018, innodb 11584688, none 3735928559, page LSN 0 15335816, low 4 bytes of LSN at page end 2171006708, page number (if stored to page already) 6, space id (if created with >= MySQL-4.1.1 and stored already) 8
|
2020-04-08 4:52:36 0 [Note] InnoDB: Page may be an index page where index id is 28
|
2020-04-08 4:52:36 0 [Note] InnoDB: Index 28 is `PRIMARY` in table `test`.`t1`
|
2020-04-08 4:52:36 0 [ERROR] [FATAL] InnoDB: Apparent corruption of an index page [page id: space=8, page number=6] to be written to data file. We intentionally crash the server to prevent corrupt data from ending up in data files.
|
200408 4:52:36 [ERROR] mysqld got signal 6 ;
|
Similar to MDEV-21549, this might be an old bug that became more reproducible in 10.5 thanks to improved write performance.
The first failure of this kind on the cross-reference was for a bb-10.5-release that was based on 10.5 fad47df9957d754bec12d4d327c77ae04f71d903. The first failure directly on 10.5 was on dec14dcffe08c0284daac4f93cd750956b15ca47. All these failures occur on kvm-asan only, so it looks somewhat timing-sensitive.
Attachments
Issue Links
- relates to
-
MDEV-15528 Avoid writing freed InnoDB pages
-
- Closed
-
-
MDEV-21347 innodb_log_optimize_ddl=OFF is not crash safe
-
- Closed
-
Activity
Sorry Marko, wouldn't call success on this just yet.
10.5-d5e8b4d7f97c7a15be5d58b6f088c4c64787a385 |
|
encryption.innodb_encryption_discard_import 'innodb' w3 [ fail ] Found warnings/errors in server log file!
|
Test ended at 2020-06-03 16:33:00
|
line
|
2020-06-03 16:32:45 0 [ERROR] InnoDB: Record 126 is above rec heap top 120
|
2020-06-03 16:32:45 0 [ERROR] [FATAL] InnoDB: Apparent corruption of an index page [page id: space=8, page number=6] to be written to data file. We intentionally crash the server to prevent corrupt data from ending up in data files.
|
Attempting backtrace. You can use the following information to find out
|
2020-06-03 16:32:53 0 [ERROR] InnoDB: Record 126 is above rec heap top 120
|
2020-06-03 16:32:53 0 [ERROR] [FATAL] InnoDB: Apparent corruption of an index page [page id: space=8, page number=6] to be written to data file. We intentionally crash the server to prevent corrupt data from ending up in data files.
|
Attempting backtrace. You can use the following information to find out
|
^ Found warnings in /home/dan/build-mariadb-server-10.5-debug-gccO0/mysql-test/var/3/log/mysqld.1.err
|
ok
|
|
- found 'core' (0/5)
|
|
Trying 'dbx' to get a backtrace
|
|
Trying 'gdb' to get a backtrace from coredump /home/dan/build-mariadb-server-10.5-debug-gccO0/mysql-test/var/3/log/encryption.innodb_encryption_discard_import-innodb/mysqld.1/data/core
|
Core generated by '/home/dan/build-mariadb-server-10.5-debug-gccO0/sql/mariadbd'
|
Output from gdb follows. The first stack trace is from the failing thread.
|
The following stack traces are from all threads (so the failing one is
|
duplicated).
|
--------------------------
|
[New LWP 52334]
|
[New LWP 52331]
|
[New LWP 52332]
|
[New LWP 52336]
|
[New LWP 52338]
|
[New LWP 52333]
|
[New LWP 52337]
|
[New LWP 52344]
|
[New LWP 52348]
|
[Thread debugging using libthread_db enabled]
|
Using host libthread_db library "/lib/powerpc64le-linux-gnu/libthread_db.so.1".
|
Core was generated by `/home/dan/build-mariadb-server-10.5-debug-gccO0/sql/mariadbd --defaults-group-s'.
|
Program terminated with signal SIGABRT, Aborted.
|
#0 0x000074dad8cb4844 in __pthread_kill (threadid=<optimized out>, signo=<optimized out>) at ../sysdeps/unix/sysv/linux/pthread_kill.c:55
|
55 ../sysdeps/unix/sysv/linux/pthread_kill.c: No such file or directory.
|
[Current thread is 1 (Thread 0x74dad168f120 (LWP 52334))]
|
#0 0x000074dad8cb4844 in __pthread_kill (threadid=<optimized out>, signo=<optimized out>) at ../sysdeps/unix/sysv/linux/pthread_kill.c:55
|
#1 0x000007965ec3e9fc in my_write_core (sig=6) at /home/dan/mariadb-server-10.5/mysys/stacktrace.c:518
|
#2 0x000007965df998bc in handle_fatal_signal (sig=6) at /home/dan/mariadb-server-10.5/sql/signal_handler.cc:330
|
#3 <signal handler called>
|
#4 0x000074dad866e98c in __libc_signal_restore_set (set=0x74dad168dd48) at ../sysdeps/unix/sysv/linux/nptl-signals.h:80
|
#5 __GI_raise (sig=<optimized out>) at ../sysdeps/unix/sysv/linux/raise.c:48
|
#6 0x000074dad8670be0 in __GI_abort () at abort.c:79
|
#7 0x000007965e926e44 in ib::fatal::~fatal (this=0x74dad168e0b0, __in_chrg=<optimized out>) at /home/dan/mariadb-server-10.5/storage/innobase/ut/ut0ut.cc:601
|
#8 0x000007965e9de0cc in buf_dblwr_assert_on_corrupt_block (block=0x74dad1aa6260) at /home/dan/mariadb-server-10.5/storage/innobase/buf/buf0dblwr.cc:793
|
#9 0x000007965e9de2a4 in buf_dblwr_check_block (block=0x74dad1aa6260) at /home/dan/mariadb-server-10.5/storage/innobase/buf/buf0dblwr.cc:852
|
#10 0x000007965e9de9e8 in buf_dblwr_flush_buffered_writes () at /home/dan/mariadb-server-10.5/storage/innobase/buf/buf0dblwr.cc:976
|
#11 0x000007965e9f2800 in buf_flush_end (flush_type=BUF_FLUSH_LIST) at /home/dan/mariadb-server-10.5/storage/innobase/buf/buf0flu.cc:1975
|
#12 0x000007965e9f2a98 in buf_flush_do_batch (type=BUF_FLUSH_LIST, min_n=18446744073709551614, lsn_limit=18446744073709551615, n=0x74dad168e438) at /home/dan/mariadb-server-10.5/storage/innobase/buf/buf0flu.cc:2019
|
#13 0x000007965e9f5424 in pc_flush_slot () at /home/dan/mariadb-server-10.5/storage/innobase/buf/buf0flu.cc:2640
|
#14 0x000007965e9f69cc in buf_flush_page_cleaner () at /home/dan/mariadb-server-10.5/storage/innobase/buf/buf0flu.cc:3041
|
#15 0x000074dad8ca885c in start_thread (arg=0x0) at pthread_create.c:463
|
#16 0x000074dad8779028 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:82
|
|
Thread 9 (Thread 0x74dac0f9f120 (LWP 52348)):
|
#0 0x000074dad8cb2b94 in futex_abstimed_wait_cancelable (private=<optimized out>, abstime=0x74dac0f9e300, expected=0, futex_word=0x204) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
|
#1 __pthread_cond_wait_common (abstime=0x74dac0f9e300, mutex=0x7969da044f0, cond=0x7969da41140) at pthread_cond_wait.c:539
|
#2 __pthread_cond_timedwait (cond=0x7969da41140, mutex=0x7969da044f0, abstime=0x74dac0f9e300) at pthread_cond_wait.c:667
|
#3 0x000007965eb6ff34 in __gthread_cond_timedwait (__cond=0x7969da41140, __mutex=0x7969da044f0, __abs_timeout=0x74dac0f9e300) at /usr/include/powerpc64le-linux-gnu/c++/7/bits/gthr-default.h:871
|
#4 0x000007965eb77178 in std::condition_variable::__wait_until_impl<std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (this=0x7969da41140, __lock=@0x74dac0f9e470: {_M_device = 0x7969da044f0, _M_owns = true}, __atime=@0x74dac0f9e3c8: {__d = {__r = 1591166032477822425}}) at /usr/include/c++/7/condition_variable:178
|
#5 0x000007965eb754bc in std::condition_variable::wait_until<std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (this=0x7969da41140, __lock=@0x74dac0f9e470: {_M_device = 0x7969da044f0, _M_owns = true}, __atime=@0x74dac0f9e3c8: {__d = {__r = 1591166032477822425}}) at /usr/include/c++/7/condition_variable:106
|
#6 0x000007965eb74104 in std::condition_variable::wait_for<long, std::ratio<1l, 1000l> > (this=0x7969da41140, __lock=@0x74dac0f9e470: {_M_device = 0x7969da044f0, _M_owns = true}, __rtime=@0x7969da04518: {__r = 60000}) at /usr/include/c++/7/condition_variable:143
|
#7 0x000007965eb70204 in tpool::thread_pool_generic::wait_for_tasks (this=0x7969da043e0, lk=@0x74dac0f9e470: {_M_device = 0x7969da044f0, _M_owns = true}, thread_data=0x7969da41140) at /home/dan/mariadb-server-10.5/tpool/tpool_generic.cc:418
|
#8 0x000007965eb704b0 in tpool::thread_pool_generic::get_task (this=0x7969da043e0, thread_var=0x7969da41140, t=0x74dac0f9e4c8) at /home/dan/mariadb-server-10.5/tpool/tpool_generic.cc:471
|
#9 0x000007965eb70838 in tpool::thread_pool_generic::worker_main (this=0x7969da043e0, thread_var=0x7969da41140) at /home/dan/mariadb-server-10.5/tpool/tpool_generic.cc:516
|
#10 0x000007965eb76024 in std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__f=@0x74dab0001048: (void (tpool::thread_pool_generic::*)(class tpool::thread_pool_generic * const, struct tpool::worker_data *)) 0x7965eb707a4 <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>, __t=@0x74dab0001040: 0x7969da043e0) at /usr/include/c++/7/bits/invoke.h:73
|
#11 0x000007965eb74838 in std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__fn=@0x74dab0001048: (void (tpool::thread_pool_generic::*)(class tpool::thread_pool_generic * const, struct tpool::worker_data *)) 0x7965eb707a4 <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>) at /usr/include/c++/7/bits/invoke.h:95
|
#12 0x000007965eb7bf20 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul> (this=0x74dab0001038) at /usr/include/c++/7/thread:234
|
#13 0x000007965eb7be50 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator() (this=0x74dab0001038) at /usr/include/c++/7/thread:243
|
#14 0x000007965eb7bdfc in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run (this=0x74dab0001030) at /usr/include/c++/7/thread:186
|
#15 0x000074dad8ae3430 in ?? () from /usr/lib/powerpc64le-linux-gnu/libstdc++.so.6
|
#16 0x000074dad8ca885c in start_thread (arg=0x0) at pthread_create.c:463
|
#17 0x000074dad8779028 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:82
|
|
Thread 8 (Thread 0x74dad1888120 (LWP 52344)):
|
#0 0x000074dad8670228 in __GI___sigtimedwait (set=<optimized out>, info=0x74dad1887480, timeout=0x0) at ../sysdeps/unix/sysv/linux/sigtimedwait.c:42
|
#1 0x000074dad86702ec in __GI___sigwaitinfo (set=<optimized out>, info=<optimized out>) at ../sysdeps/unix/sysv/linux/sigwaitinfo.c:25
|
#2 0x000007965d985474 in my_sigwait (set=0x74dad18875c0, sig=0x74dad1887584, code=0x74dad1887588) at /home/dan/mariadb-server-10.5/include/my_pthread.h:196
|
#3 0x000007965d98d79c in signal_hand (arg=0x0) at /home/dan/mariadb-server-10.5/sql/mysqld.cc:2987
|
#4 0x000007965e4607a0 in pfs_spawn_thread (arg=0x7969e1b34a8) at /home/dan/mariadb-server-10.5/storage/perfschema/pfs.cc:2201
|
#5 0x000074dad8ca885c in start_thread (arg=0x0) at pthread_create.c:463
|
#6 0x000074dad8779028 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:82
|
|
Thread 7 (Thread 0x74dac37ef120 (LWP 52337)):
|
#0 0x000074dad8cb2b94 in futex_abstimed_wait_cancelable (private=<optimized out>, abstime=0x74dac37ee300, expected=0, futex_word=0x204) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
|
#1 __pthread_cond_wait_common (abstime=0x74dac37ee300, mutex=0x7969da044f0, cond=0x7969da41240) at pthread_cond_wait.c:539
|
#2 __pthread_cond_timedwait (cond=0x7969da41240, mutex=0x7969da044f0, abstime=0x74dac37ee300) at pthread_cond_wait.c:667
|
#3 0x000007965eb6ff34 in __gthread_cond_timedwait (__cond=0x7969da41240, __mutex=0x7969da044f0, __abs_timeout=0x74dac37ee300) at /usr/include/powerpc64le-linux-gnu/c++/7/bits/gthr-default.h:871
|
#4 0x000007965eb77178 in std::condition_variable::__wait_until_impl<std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (this=0x7969da41240, __lock=@0x74dac37ee470: {_M_device = 0x7969da044f0, _M_owns = true}, __atime=@0x74dac37ee3c8: {__d = {__r = 1591166033100910763}}) at /usr/include/c++/7/condition_variable:178
|
#5 0x000007965eb754bc in std::condition_variable::wait_until<std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (this=0x7969da41240, __lock=@0x74dac37ee470: {_M_device = 0x7969da044f0, _M_owns = true}, __atime=@0x74dac37ee3c8: {__d = {__r = 1591166033100910763}}) at /usr/include/c++/7/condition_variable:106
|
#6 0x000007965eb74104 in std::condition_variable::wait_for<long, std::ratio<1l, 1000l> > (this=0x7969da41240, __lock=@0x74dac37ee470: {_M_device = 0x7969da044f0, _M_owns = true}, __rtime=@0x7969da04518: {__r = 60000}) at /usr/include/c++/7/condition_variable:143
|
#7 0x000007965eb70204 in tpool::thread_pool_generic::wait_for_tasks (this=0x7969da043e0, lk=@0x74dac37ee470: {_M_device = 0x7969da044f0, _M_owns = true}, thread_data=0x7969da41240) at /home/dan/mariadb-server-10.5/tpool/tpool_generic.cc:418
|
#8 0x000007965eb704b0 in tpool::thread_pool_generic::get_task (this=0x7969da043e0, thread_var=0x7969da41240, t=0x74dac37ee4c8) at /home/dan/mariadb-server-10.5/tpool/tpool_generic.cc:471
|
#9 0x000007965eb70838 in tpool::thread_pool_generic::worker_main (this=0x7969da043e0, thread_var=0x7969da41240) at /home/dan/mariadb-server-10.5/tpool/tpool_generic.cc:516
|
#10 0x000007965eb76024 in std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__f=@0x7969de499a8: (void (tpool::thread_pool_generic::*)(class tpool::thread_pool_generic * const, struct tpool::worker_data *)) 0x7965eb707a4 <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>, __t=@0x7969de499a0: 0x7969da043e0) at /usr/include/c++/7/bits/invoke.h:73
|
#11 0x000007965eb74838 in std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__fn=@0x7969de499a8: (void (tpool::thread_pool_generic::*)(class tpool::thread_pool_generic * const, struct tpool::worker_data *)) 0x7965eb707a4 <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>) at /usr/include/c++/7/bits/invoke.h:95
|
#12 0x000007965eb7bf20 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul> (this=0x7969de49998) at /usr/include/c++/7/thread:234
|
#13 0x000007965eb7be50 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator() (this=0x7969de49998) at /usr/include/c++/7/thread:243
|
#14 0x000007965eb7bdfc in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run (this=0x7969de49990) at /usr/include/c++/7/thread:186
|
#15 0x000074dad8ae3430 in ?? () from /usr/lib/powerpc64le-linux-gnu/libstdc++.so.6
|
#16 0x000074dad8ca885c in start_thread (arg=0x0) at pthread_create.c:463
|
#17 0x000074dad8779028 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:82
|
|
Thread 6 (Thread 0x74dad2eaf120 (LWP 52333)):
|
#0 0x000074dad8cb2b94 in futex_abstimed_wait_cancelable (private=<optimized out>, abstime=0x74dad2eae530, expected=0, futex_word=0x204) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
|
#1 __pthread_cond_wait_common (abstime=0x74dad2eae530, mutex=0x7966016a2f0 <LOCK_checkpoint+40>, cond=0x7966016a378 <COND_checkpoint>) at pthread_cond_wait.c:539
|
#2 __pthread_cond_timedwait (cond=0x7966016a378 <COND_checkpoint>, mutex=0x7966016a2f0 <LOCK_checkpoint+40>, abstime=0x74dad2eae530) at pthread_cond_wait.c:667
|
#3 0x000007965ec45e70 in safe_cond_timedwait (cond=0x7966016a378 <COND_checkpoint>, mp=0x7966016a2c8 <LOCK_checkpoint>, abstime=0x74dad2eae530, file=0x7965effd7c8 "/home/dan/mariadb-server-10.5/include/mysql/psi/mysql_thread.h", line=1257) at /home/dan/mariadb-server-10.5/mysys/thr_mutex.c:546
|
#4 0x000007965e38c2f0 in inline_mysql_cond_timedwait (that=0x7966016a378 <COND_checkpoint>, mutex=0x7966016a2c8 <LOCK_checkpoint>, abstime=0x74dad2eae530, src_file=0x7965effd808 "/home/dan/mariadb-server-10.5/storage/maria/ma_servicethread.c", src_line=116) at /home/dan/mariadb-server-10.5/include/mysql/psi/mysql_thread.h:1257
|
#5 0x000007965e38ca20 in my_service_thread_sleep (control=0x7965f75c420 <checkpoint_control>, sleep_time=29000000000) at /home/dan/mariadb-server-10.5/storage/maria/ma_servicethread.c:115
|
#6 0x000007965e37c25c in ma_checkpoint_background (arg=0x1e) at /home/dan/mariadb-server-10.5/storage/maria/ma_checkpoint.c:707
|
#7 0x000007965e4607a0 in pfs_spawn_thread (arg=0x7969d9e6a28) at /home/dan/mariadb-server-10.5/storage/perfschema/pfs.cc:2201
|
#8 0x000074dad8ca885c in start_thread (arg=0x0) at pthread_create.c:463
|
#9 0x000074dad8779028 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:82
|
|
Thread 5 (Thread 0x74dac2fdf120 (LWP 52338)):
|
#0 0x000074dad8cb2b94 in futex_abstimed_wait_cancelable (private=<optimized out>, abstime=0x74dac2fde300, expected=0, futex_word=0x204) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
|
#1 __pthread_cond_wait_common (abstime=0x74dac2fde300, mutex=0x7969da044f0, cond=0x7969da411c0) at pthread_cond_wait.c:539
|
#2 __pthread_cond_timedwait (cond=0x7969da411c0, mutex=0x7969da044f0, abstime=0x74dac2fde300) at pthread_cond_wait.c:667
|
#3 0x000007965eb6ff34 in __gthread_cond_timedwait (__cond=0x7969da411c0, __mutex=0x7969da044f0, __abs_timeout=0x74dac2fde300) at /usr/include/powerpc64le-linux-gnu/c++/7/bits/gthr-default.h:871
|
#4 0x000007965eb77178 in std::condition_variable::__wait_until_impl<std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (this=0x7969da411c0, __lock=@0x74dac2fde470: {_M_device = 0x7969da044f0, _M_owns = true}, __atime=@0x74dac2fde3c8: {__d = {__r = 1591166032488182077}}) at /usr/include/c++/7/condition_variable:178
|
#5 0x000007965eb754bc in std::condition_variable::wait_until<std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (this=0x7969da411c0, __lock=@0x74dac2fde470: {_M_device = 0x7969da044f0, _M_owns = true}, __atime=@0x74dac2fde3c8: {__d = {__r = 1591166032488182077}}) at /usr/include/c++/7/condition_variable:106
|
#6 0x000007965eb74104 in std::condition_variable::wait_for<long, std::ratio<1l, 1000l> > (this=0x7969da411c0, __lock=@0x74dac2fde470: {_M_device = 0x7969da044f0, _M_owns = true}, __rtime=@0x7969da04518: {__r = 60000}) at /usr/include/c++/7/condition_variable:143
|
#7 0x000007965eb70204 in tpool::thread_pool_generic::wait_for_tasks (this=0x7969da043e0, lk=@0x74dac2fde470: {_M_device = 0x7969da044f0, _M_owns = true}, thread_data=0x7969da411c0) at /home/dan/mariadb-server-10.5/tpool/tpool_generic.cc:418
|
#8 0x000007965eb704b0 in tpool::thread_pool_generic::get_task (this=0x7969da043e0, thread_var=0x7969da411c0, t=0x74dac2fde4c8) at /home/dan/mariadb-server-10.5/tpool/tpool_generic.cc:471
|
#9 0x000007965eb70838 in tpool::thread_pool_generic::worker_main (this=0x7969da043e0, thread_var=0x7969da411c0) at /home/dan/mariadb-server-10.5/tpool/tpool_generic.cc:516
|
#10 0x000007965eb76024 in std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__f=@0x7969de49978: (void (tpool::thread_pool_generic::*)(class tpool::thread_pool_generic * const, struct tpool::worker_data *)) 0x7965eb707a4 <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>, __t=@0x7969de49970: 0x7969da043e0) at /usr/include/c++/7/bits/invoke.h:73
|
#11 0x000007965eb74838 in std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__fn=@0x7969de49978: (void (tpool::thread_pool_generic::*)(class tpool::thread_pool_generic * const, struct tpool::worker_data *)) 0x7965eb707a4 <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>) at /usr/include/c++/7/bits/invoke.h:95
|
#12 0x000007965eb7bf20 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul> (this=0x7969de49968) at /usr/include/c++/7/thread:234
|
#13 0x000007965eb7be50 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator() (this=0x7969de49968) at /usr/include/c++/7/thread:243
|
#14 0x000007965eb7bdfc in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run (this=0x7969de49960) at /usr/include/c++/7/thread:186
|
#15 0x000074dad8ae3430 in ?? () from /usr/lib/powerpc64le-linux-gnu/libstdc++.so.6
|
#16 0x000074dad8ca885c in start_thread (arg=0x0) at pthread_create.c:463
|
#17 0x000074dad8779028 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:82
|
|
Thread 4 (Thread 0x74dac3fff120 (LWP 52336)):
|
#0 0x000074dad8cb2b94 in futex_abstimed_wait_cancelable (private=<optimized out>, abstime=0x74dac3ffe300, expected=0, futex_word=0x204) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
|
#1 __pthread_cond_wait_common (abstime=0x74dac3ffe300, mutex=0x7969da044f0, cond=0x7969da412c0) at pthread_cond_wait.c:539
|
#2 __pthread_cond_timedwait (cond=0x7969da412c0, mutex=0x7969da044f0, abstime=0x74dac3ffe300) at pthread_cond_wait.c:667
|
#3 0x000007965eb6ff34 in __gthread_cond_timedwait (__cond=0x7969da412c0, __mutex=0x7969da044f0, __abs_timeout=0x74dac3ffe300) at /usr/include/powerpc64le-linux-gnu/c++/7/bits/gthr-default.h:871
|
#4 0x000007965eb77178 in std::condition_variable::__wait_until_impl<std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (this=0x7969da412c0, __lock=@0x74dac3ffe470: {_M_device = 0x7969da044f0, _M_owns = true}, __atime=@0x74dac3ffe3c8: {__d = {__r = 1591166032475521173}}) at /usr/include/c++/7/condition_variable:178
|
#5 0x000007965eb754bc in std::condition_variable::wait_until<std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (this=0x7969da412c0, __lock=@0x74dac3ffe470: {_M_device = 0x7969da044f0, _M_owns = true}, __atime=@0x74dac3ffe3c8: {__d = {__r = 1591166032475521173}}) at /usr/include/c++/7/condition_variable:106
|
#6 0x000007965eb74104 in std::condition_variable::wait_for<long, std::ratio<1l, 1000l> > (this=0x7969da412c0, __lock=@0x74dac3ffe470: {_M_device = 0x7969da044f0, _M_owns = true}, __rtime=@0x7969da04518: {__r = 60000}) at /usr/include/c++/7/condition_variable:143
|
#7 0x000007965eb70204 in tpool::thread_pool_generic::wait_for_tasks (this=0x7969da043e0, lk=@0x74dac3ffe470: {_M_device = 0x7969da044f0, _M_owns = true}, thread_data=0x7969da412c0) at /home/dan/mariadb-server-10.5/tpool/tpool_generic.cc:418
|
#8 0x000007965eb704b0 in tpool::thread_pool_generic::get_task (this=0x7969da043e0, thread_var=0x7969da412c0, t=0x74dac3ffe4c8) at /home/dan/mariadb-server-10.5/tpool/tpool_generic.cc:471
|
#9 0x000007965eb70838 in tpool::thread_pool_generic::worker_main (this=0x7969da043e0, thread_var=0x7969da412c0) at /home/dan/mariadb-server-10.5/tpool/tpool_generic.cc:516
|
#10 0x000007965eb76024 in std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__f=@0x7969de49a08: (void (tpool::thread_pool_generic::*)(class tpool::thread_pool_generic * const, struct tpool::worker_data *)) 0x7965eb707a4 <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>, __t=@0x7969de49a00: 0x7969da043e0) at /usr/include/c++/7/bits/invoke.h:73
|
#11 0x000007965eb74838 in std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__fn=@0x7969de49a08: (void (tpool::thread_pool_generic::*)(class tpool::thread_pool_generic * const, struct tpool::worker_data *)) 0x7965eb707a4 <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>) at /usr/include/c++/7/bits/invoke.h:95
|
#12 0x000007965eb7bf20 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul> (this=0x7969de499f8) at /usr/include/c++/7/thread:234
|
#13 0x000007965eb7be50 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator() (this=0x7969de499f8) at /usr/include/c++/7/thread:243
|
#14 0x000007965eb7bdfc in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run (this=0x7969de499f0) at /usr/include/c++/7/thread:186
|
#15 0x000074dad8ae3430 in ?? () from /usr/lib/powerpc64le-linux-gnu/libstdc++.so.6
|
#16 0x000074dad8ca885c in start_thread (arg=0x0) at pthread_create.c:463
|
#17 0x000074dad8779028 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:82
|
|
Thread 3 (Thread 0x74dad428f120 (LWP 52332)):
|
#0 0x000074dad8cb2b94 in futex_abstimed_wait_cancelable (private=<optimized out>, abstime=0x74dad428e630, expected=0, futex_word=0x204) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
|
#1 __pthread_cond_wait_common (abstime=0x74dad428e630, mutex=0x7966023b5b8 <LOCK_timer+40>, cond=0x7966023b640 <COND_timer>) at pthread_cond_wait.c:539
|
#2 __pthread_cond_timedwait (cond=0x7966023b640 <COND_timer>, mutex=0x7966023b5b8 <LOCK_timer+40>, abstime=0x74dad428e630) at pthread_cond_wait.c:667
|
#3 0x000007965ec45e70 in safe_cond_timedwait (cond=0x7966023b640 <COND_timer>, mp=0x7966023b590 <LOCK_timer>, abstime=0x74dad428e630, file=0x7965f2075b8 "/home/dan/mariadb-server-10.5/include/mysql/psi/mysql_thread.h", line=1257) at /home/dan/mariadb-server-10.5/mysys/thr_mutex.c:546
|
#4 0x000007965ec47660 in inline_mysql_cond_timedwait (that=0x7966023b640 <COND_timer>, mutex=0x7966023b590 <LOCK_timer>, abstime=0x74dad428e630, src_file=0x7965f2075f8 "/home/dan/mariadb-server-10.5/mysys/thr_timer.c", src_line=321) at /home/dan/mariadb-server-10.5/include/mysql/psi/mysql_thread.h:1257
|
#5 0x000007965ec48818 in timer_handler (arg=0x0) at /home/dan/mariadb-server-10.5/mysys/thr_timer.c:321
|
#6 0x000007965e4607a0 in pfs_spawn_thread (arg=0x7969d932fd8) at /home/dan/mariadb-server-10.5/storage/perfschema/pfs.cc:2201
|
#7 0x000074dad8ca885c in start_thread (arg=0x0) at pthread_create.c:463
|
#8 0x000074dad8779028 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:82
|
|
Thread 2 (Thread 0x74dad9278c70 (LWP 52331)):
|
#0 0x000074dad8cb9768 in __GI___nanosleep (requested_time=0x204, remaining=0x0) at ../sysdeps/unix/sysv/linux/nanosleep.c:28
|
#1 0x000007965e70da38 in os_thread_sleep (tm=100000) at /home/dan/mariadb-server-10.5/storage/innobase/os/os0thread.cc:231
|
#2 0x000007965e6bc40c in logs_empty_and_mark_files_at_shutdown () at /home/dan/mariadb-server-10.5/storage/innobase/log/log0log.cc:1641
|
#3 0x000007965e88d640 in innodb_shutdown () at /home/dan/mariadb-server-10.5/storage/innobase/srv/srv0start.cc:2089
|
#4 0x000007965e59b3f4 in innobase_end () at /home/dan/mariadb-server-10.5/storage/innobase/handler/ha_innodb.cc:4089
|
#5 0x000007965df9e920 in ha_finalize_handlerton (plugin=0x7969d936310) at /home/dan/mariadb-server-10.5/sql/handler.cc:524
|
#6 0x000007965db6c1a4 in plugin_deinitialize (plugin=0x7969d936310, ref_check=true) at /home/dan/mariadb-server-10.5/sql/sql_plugin.cc:1262
|
#7 0x000007965db6c8c0 in reap_plugins () at /home/dan/mariadb-server-10.5/sql/sql_plugin.cc:1338
|
#8 0x000007965db6f4d8 in plugin_shutdown () at /home/dan/mariadb-server-10.5/sql/sql_plugin.cc:2019
|
#9 0x000007965d98aa68 in clean_up (print_message=true) at /home/dan/mariadb-server-10.5/sql/mysqld.cc:1984
|
#10 0x000007965d994c70 in mysqld_main (argc=172, argv=0x7969d7e3b60) at /home/dan/mariadb-server-10.5/sql/mysqld.cc:5647
|
#11 0x000007965d9852d4 in main (argc=31, argv=0x7ffffbfaff08) at /home/dan/mariadb-server-10.5/sql/main.cc:25
|
|
Thread 1 (Thread 0x74dad168f120 (LWP 52334)):
|
#0 0x000074dad8cb4844 in __pthread_kill (threadid=<optimized out>, signo=<optimized out>) at ../sysdeps/unix/sysv/linux/pthread_kill.c:55
|
#1 0x000007965ec3e9fc in my_write_core (sig=6) at /home/dan/mariadb-server-10.5/mysys/stacktrace.c:518
|
#2 0x000007965df998bc in handle_fatal_signal (sig=6) at /home/dan/mariadb-server-10.5/sql/signal_handler.cc:330
|
#3 <signal handler called>
|
#4 0x000074dad866e98c in __libc_signal_restore_set (set=0x74dad168dd48) at ../sysdeps/unix/sysv/linux/nptl-signals.h:80
|
#5 __GI_raise (sig=<optimized out>) at ../sysdeps/unix/sysv/linux/raise.c:48
|
#6 0x000074dad8670be0 in __GI_abort () at abort.c:79
|
#7 0x000007965e926e44 in ib::fatal::~fatal (this=0x74dad168e0b0, __in_chrg=<optimized out>) at /home/dan/mariadb-server-10.5/storage/innobase/ut/ut0ut.cc:601
|
#8 0x000007965e9de0cc in buf_dblwr_assert_on_corrupt_block (block=0x74dad1aa6260) at /home/dan/mariadb-server-10.5/storage/innobase/buf/buf0dblwr.cc:793
|
#9 0x000007965e9de2a4 in buf_dblwr_check_block (block=0x74dad1aa6260) at /home/dan/mariadb-server-10.5/storage/innobase/buf/buf0dblwr.cc:852
|
#10 0x000007965e9de9e8 in buf_dblwr_flush_buffered_writes () at /home/dan/mariadb-server-10.5/storage/innobase/buf/buf0dblwr.cc:976
|
#11 0x000007965e9f2800 in buf_flush_end (flush_type=BUF_FLUSH_LIST) at /home/dan/mariadb-server-10.5/storage/innobase/buf/buf0flu.cc:1975
|
#12 0x000007965e9f2a98 in buf_flush_do_batch (type=BUF_FLUSH_LIST, min_n=18446744073709551614, lsn_limit=18446744073709551615, n=0x74dad168e438) at /home/dan/mariadb-server-10.5/storage/innobase/buf/buf0flu.cc:2019
|
#13 0x000007965e9f5424 in pc_flush_slot () at /home/dan/mariadb-server-10.5/storage/innobase/buf/buf0flu.cc:2640
|
#14 0x000007965e9f69cc in buf_flush_page_cleaner () at /home/dan/mariadb-server-10.5/storage/innobase/buf/buf0flu.cc:3041
|
#15 0x000074dad8ca885c in start_thread (arg=0x0) at pthread_create.c:463
|
#16 0x000074dad8779028 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:82
|
|
- saving '/home/dan/build-mariadb-server-10.5-debug-gccO0/mysql-test/var/3/log/encryption.innodb_encryption_discard_import-innodb/' to '/home/dan/build-mariadb-server-10.5-debug-gccO0/mysql-test/var/log/encryption.innodb_encryption_discard_import-innodb/'
|
seems to be a memory barrier related:
on a 2 node system with 80 threads per node, the linux kernel co-locates the threads such that the following will successfully run:
10.5-036920c7262dfaf1532f3ba77a013b7ec04d5f7c (bb-10.5-MDEV-15053-3) works ok |
build-mariadb-server-10.5-debug-gccO0$ mysql-test/mtr --parallel=80 --force --max-test-fail=30 --repeat=4 --mem encryption.innodb_encryption_discard_import{,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,}
|
|
with frequent, byt non-crashing
|
encryption.innodb_encryption_discard_import 'innodb' w68 [ 2 fail ] Found warnings/errors in server log file!
|
Test ended at 2020-06-05 16:57:26
|
line
|
2020-06-05 16:57:11 3 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-ib27' but there are 1 pending operations on it.
|
^ Found warnings in /home/dan/build-mariadb-server-10.5-debug-gccO0/mysql-test/var/68/log/mysqld.1.err
|
ok
|
Push the --parallel=120 or beyond and quite a few instances of the assertion will almost instantly occur:
parallel=120 |
worker[118] Using MTR_BUILD_THREAD 411, with reserved ports 18220..18239
|
worker[107] Using MTR_BUILD_THREAD 413, with reserved ports 18260..18279
|
worker[120] Using MTR_BUILD_THREAD 415, with reserved ports 18300..18319
|
worker[106] Using MTR_BUILD_THREAD 416, with reserved ports 18320..18339
|
worker[105] Using MTR_BUILD_THREAD 417, with reserved ports 18340..18359
|
worker[114] Using MTR_BUILD_THREAD 414, with reserved ports 18280..18299
|
worker[108] Using MTR_BUILD_THREAD 418, with reserved ports 18360..18379
|
worker[117] Using MTR_BUILD_THREAD 419, with reserved ports 18380..18399
|
encryption.innodb_encryption_discard_import 'innodb' w26 [ pass ] 90701
|
encryption.innodb_encryption_discard_import 'innodb' w3 [ pass ] 91568
|
encryption.innodb_encryption_discard_import 'innodb' w111 [ pass ] 92694
|
encryption.innodb_encryption_discard_import 'innodb' w76 [ pass ] 93182
|
encryption.innodb_encryption_discard_import 'innodb' w21 [ pass ] 93436
|
encryption.innodb_encryption_discard_import 'innodb' w87 [ pass ] 93424
|
encryption.innodb_encryption_discard_import 'innodb' w73 [ pass ] 93722
|
encryption.innodb_encryption_discard_import 'innodb' w114 [ pass ] 93723
|
encryption.innodb_encryption_discard_import 'innodb' w40 [ pass ] 93673
|
encryption.innodb_encryption_discard_import 'innodb' w85 [ pass ] 94168
|
encryption.innodb_encryption_discard_import 'innodb' w31 [ pass ] 93777
|
encryption.innodb_encryption_discard_import 'innodb' w5 [ pass ] 94037
|
encryption.innodb_encryption_discard_import 'innodb' w60 [ pass ] 94459
|
encryption.innodb_encryption_discard_import 'innodb' w24 [ pass ] 94056
|
encryption.innodb_encryption_discard_import 'innodb' w74 [ pass ] 94880
|
encryption.innodb_encryption_discard_import 'innodb' w96 [ pass ] 94790
|
encryption.innodb_encryption_discard_import 'innodb' w81 [ pass ] 94545
|
encryption.innodb_encryption_discard_import 'innodb' w53 [ pass ] 94533
|
encryption.innodb_encryption_discard_import 'innodb' w14 [ pass ] 94979
|
encryption.innodb_encryption_discard_import 'innodb' w22 [ pass ] 95137
|
encryption.innodb_encryption_discard_import 'innodb' w83 [ pass ] 95067
|
encryption.innodb_encryption_discard_import 'innodb' w109 [ pass ] 95219
|
encryption.innodb_encryption_discard_import 'innodb' w99 [ pass ] 95144
|
encryption.innodb_encryption_discard_import 'innodb' w2 [ pass ] 95356
|
encryption.innodb_encryption_discard_import 'innodb' w36 [ pass ] 94990
|
encryption.innodb_encryption_discard_import 'innodb' w9 [ pass ] 95262
|
encryption.innodb_encryption_discard_import 'innodb' w27 [ pass ] 95053
|
encryption.innodb_encryption_discard_import 'innodb' w77 [ pass ] 95483
|
encryption.innodb_encryption_discard_import 'innodb' w102 [ pass ] 95680
|
encryption.innodb_encryption_discard_import 'innodb' w113 [ fail ] Found warnings/errors in server log file!
|
Test ended at 2020-06-05 17:26:09
|
line
|
2020-06-05 17:26:01 0 [ERROR] InnoDB: Record 126 is above rec heap top 120
|
......
|
I am now looking at a rr replay trace of a failed encryption.innodb_encryption_discard_import run. In the page image, PAGE_HEAP_TOP, PAGE_N_HEAP and PAGE_N_RECS correspond to an empty ROW_FORMAT≠REDUNDANT page (120, 0x8002, 0), but the page is not empty. The infimum pseudo-record points to the payload start of the record that was allocated at byte 120:
od -t x1 -Ax -w14 -j 120 page.bin
|
Each record is 14 bytes; that is why I chose this format. Every record is also allocated sequentially; the REC_NEXT bytes are always 00 0e except for the very last one:
000078 00 10 00 11 00 0e 80 00 00 00 00 00 00 04
|
000086 00 00 00 19 00 0e 80 00 00 37 00 00 00 05
|
…
|
000804 00 00 04 61 00 0e 80 00 1d a6 00 00 00 aa
|
000812 00 00 04 69 f8 58 80 00 1d dd 00 00 00 ab
|
000820 00 00 00 00 00 00 00 00 00 00 00 00 00 00
|
*
|
So, the PAGE_HEAP_TOP should actually be 0x820 and the number of records should be 140 = (0x820-120)/14.
As far as I understood, the crash that I am debugging occurred during the execution of the statement
ALTER TABLE t1 ENGINE InnoDB; |
and now I have a call stack for the problematic page 8:6:
#0 PageBulk::finish (this=0x61a000012c98)
|
at /home/mleich/bb-10.5-marko/storage/innobase/btr/btr0bulk.cc:504
|
#1 0x000055ea99985ff0 in BtrBulk::pageCommit (this=0x6070003b56a8,
|
page_bulk=0x61a000012c98, next_page_bulk=0x0, insert_father=false)
|
at /home/mleich/bb-10.5-marko/storage/innobase/btr/btr0bulk.cc:908
|
#2 0x000055ea99987cf2 in BtrBulk::finish (this=0x6070003b56a8, err=DB_SUCCESS)
|
at /home/mleich/bb-10.5-marko/storage/innobase/btr/btr0bulk.cc:1157
|
At this point, the page header looks different: the page payload ends at 0xa6e, which corresponds to the PAGE_HEAP_TOP.
The assertion will fail later for the same page number, but the page has been migrated to a different block address in the buffer pool.
I currently suspect that the page was incorrectly evicted (likely because we failed to keep it in the buf_pool.flush_list) and an earlier version reloaded. I should be able to confirm this shortly.
This is also somewhat related to MDEV-21347, where I would like to remove buf_block_t::skip_flush_check.
We seem to be evicting a dirty page.
Thread 30 hit Breakpoint 1, buf_flush_write_complete (bpage=0x7f457eaaa888, flush_type=IORequest::FLUSH_LIST, dblwr=true) at /home/mleich/bb-10.5-marko/storage/innobase/buf/buf0flu.cc:529
|
529 ut_ad(mutex_own(&buf_pool.mutex));
|
(rr) when
|
Current event: 974555
|
…
|
Thread 34 hit Hardware watchpoint 2: -location $4.frame[16]@8
|
|
Old value = "\000\000\000\000\000ı9"
|
New value = "\000\000\000\000\000ı\251"
|
mach_write_to_4 (b=0x7f457edc4014 "", n=12890537) at /home/mleich/bb-10.5-marko/storage/innobase/include/mach0data.ic:167
|
167 }
|
1: /x $4.frame[16]@8 = {0x0, 0x0, 0x0, 0x0, 0x0, 0xc4, 0xb1, 0xa9}
|
Current event: 1184399
|
(rr)
|
Continuing.
|
|
Thread 34 hit Hardware watchpoint 2: -location $4.frame[16]@8
|
|
Old value = "\000\000\000\000\000ı\251"
|
New value = "\000\000\000\000\000\000\261\251"
|
__memset_avx2_erms () at ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S:141
|
141 ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S: No such file or directory.
|
1: /x $4.frame[16]@8 = {0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xb1, 0xa9}
|
Current event: 1542264
|
(rr) bt
|
#0 __memset_avx2_erms () at ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S:141
|
#1 0x00007f458a8f1cdf in ?? () from /usr/lib/x86_64-linux-gnu/libasan.so.4
|
#2 0x000055ea99a6cb31 in buf_LRU_block_free_non_file_page (block=0x7f457eaaa888) at /home/mleich/bb-10.5-marko/storage/innobase/buf/buf0lru.cc:1352
|
#3 0x000055ea99a651cb in buf_LRU_block_free_hashed_page (block=0x7f457eaaa888) at /home/mleich/bb-10.5-marko/storage/innobase/buf/buf0lru.cc:150
|
#4 0x000055ea99a6c6e9 in buf_LRU_free_page (bpage=0x7f457eaaa888, zip=true) at /home/mleich/bb-10.5-marko/storage/innobase/buf/buf0lru.cc:1327
|
#5 0x000055ea99a67027 in buf_LRU_free_from_common_LRU_list (scan_all=false) at /home/mleich/bb-10.5-marko/storage/innobase/buf/buf0lru.cc:563
|
#6 0x000055ea99a67344 in buf_LRU_scan_and_free_block (scan_all=false) at /home/mleich/bb-10.5-marko/storage/innobase/buf/buf0lru.cc:598
|
#7 0x000055ea99a68872 in buf_LRU_get_free_block (have_mutex=false) at /home/mleich/bb-10.5-marko/storage/innobase/buf/buf0lru.cc:780
|
#8 0x000055ea99a74291 in buf_page_init_for_read (mode=132, page_id=..., zip_size=0, unzip=false) at /home/mleich/bb-10.5-marko/storage/innobase/buf/buf0rea.cc:109
|
The penultimate watchpoint caught an update of FIL_PAGE_LSN to 0xc4b1a9, and the page was not written to the file system after that.
The page was removed from the flush list shortly before it was reused for something else:
…
|
#6 0x000055ea9995dbdb in btr_page_free (index=0x618000021520, block=0x7f457eaaa888, mtr=0x7f45692ac5a0, blob=false) at /home/mleich/bb-10.5-marko/storage/innobase/btr/btr0btr.cc:746
|
#7 0x000055ea9998819e in BtrBulk::finish (this=0x6070003b56a8, err=DB_SUCCESS) at /home/mleich/bb-10.5-marko/storage/innobase/btr/btr0bulk.cc:1195
|
…
|
(rr) when
|
Current event: 1184391
|
Thanks to MDEV-15528, we will skip the write of the freed page to the data file. At this point, the contents of page 8:6 looks rather similar to the contents of page 8:3 (the root page of the primary key). The root page has no siblings at this point, and its PAGE_LEVEL is 1, that is, it is 1 level above the leaf level.
Up until now, all seems well and good. Page 8:6 is a garbage page, and nobody should have any business modifying it. An allowed subsequent course of action would be to allocate the page for something else and invoke buf_page_create() on it.
The actual problem is revealed later, when an encryption thread is about to perform a dummy write on the garbage page. Here it is reading the garbage page into the buffer pool:
(rr) when
|
Current event: 1705403
|
(rr) bt
|
#0 buf_page_get_low (page_id=..., zip_size=0, rw_latch=2, guess=0x0, mode=12, file=0x55ea9b035ba0 "/home/mleich/bb-10.5-marko/storage/innobase/fil/fil0crypt.cc", line=1739, mtr=0x7f4579964740,
|
err=0x7f45799645d0, allow_ibuf_merge=false) at /home/mleich/bb-10.5-marko/storage/innobase/buf/buf0buf.cc:3003
|
#1 0x000055ea99a1ce5c in buf_page_get_gen (page_id=..., zip_size=0, rw_latch=2, guess=0x0, mode=12, file=0x55ea9b035ba0 "/home/mleich/bb-10.5-marko/storage/innobase/fil/fil0crypt.cc", line=1739,
|
mtr=0x7f4579964740, err=0x7f45799645d0, allow_ibuf_merge=false) at /home/mleich/bb-10.5-marko/storage/innobase/buf/buf0buf.cc:3609
|
#2 0x000055ea99b6d510 in fil_crypt_get_page_throttle_func (state=0x7f4579964dc0, offset=6, mtr=0x7f4579964740, sleeptime_ms=0x7f4579964700,
|
file=0x55ea9b035ba0 "/home/mleich/bb-10.5-marko/storage/innobase/fil/fil0crypt.cc", line=1739) at /home/mleich/bb-10.5-marko/storage/innobase/fil/fil0crypt.cc:1660
|
#3 0x000055ea99b6dc29 in fil_crypt_rotate_page (key_state=0x7f4579964d80, state=0x7f4579964dc0) at /home/mleich/bb-10.5-marko/storage/innobase/fil/fil0crypt.cc:1737
|
#4 0x000055ea99b6e779 in fil_crypt_rotate_pages (key_state=0x7f4579964d80, state=0x7f4579964dc0) at /home/mleich/bb-10.5-marko/storage/innobase/fil/fil0crypt.cc:1866
|
#5 0x000055ea99b6fb7b in fil_crypt_thread () at /home/mleich/bb-10.5-marko/storage/innobase/fil/fil0crypt.cc:2060
|
The first such call will return nullptr, but a little later the garbage page does exist in the buffer pool, and we will be able to perform the dummy write, which will trip the check at page flushing time:
(rr) fin
|
Run till exit from #1 0x000055ea99a1ce5c in buf_page_get_gen (page_id=..., zip_size=0, rw_latch=2, guess=0x0, mode=16, file=0x55ea9b035ba0 "/home/mleich/bb-10.5-marko/storage/innobase/fil/fil0crypt.cc",
|
line=1739, mtr=0x7f4579964740, err=0x7f45799645d0, allow_ibuf_merge=false) at /home/mleich/bb-10.5-marko/storage/innobase/buf/buf0buf.cc:3609
|
0x000055ea99b6d640 in fil_crypt_get_page_throttle_func (state=0x7f4579964dc0, offset=6, mtr=0x7f4579964740, sleeptime_ms=0x7f4579964700,
|
file=0x55ea9b035ba0 "/home/mleich/bb-10.5-marko/storage/innobase/fil/fil0crypt.cc", line=1739) at /home/mleich/bb-10.5-marko/storage/innobase/fil/fil0crypt.cc:1674
|
1674 block = buf_page_get_gen(page_id, zip_size,
|
Value returned is $14 = (buf_block_t *) 0x7f457eab8940
|
(rr) bt
|
#0 0x000055ea99b6d640 in fil_crypt_get_page_throttle_func (state=0x7f4579964dc0, offset=6, mtr=0x7f4579964740, sleeptime_ms=0x7f4579964700,
|
file=0x55ea9b035ba0 "/home/mleich/bb-10.5-marko/storage/innobase/fil/fil0crypt.cc", line=1739) at /home/mleich/bb-10.5-marko/storage/innobase/fil/fil0crypt.cc:1674
|
#1 0x000055ea99b6dc29 in fil_crypt_rotate_page (key_state=0x7f4579964d80, state=0x7f4579964dc0) at /home/mleich/bb-10.5-marko/storage/innobase/fil/fil0crypt.cc:1737
|
#2 0x000055ea99b6e779 in fil_crypt_rotate_pages (key_state=0x7f4579964d80, state=0x7f4579964dc0) at /home/mleich/bb-10.5-marko/storage/innobase/fil/fil0crypt.cc:1866
|
#3 0x000055ea99b6fb7b in fil_crypt_thread () at /home/mleich/bb-10.5-marko/storage/innobase/fil/fil0crypt.cc:2060
|
#4 0x00007f458957b6db in start_thread (arg=0x7f4579965700) at pthread_create.c:463
|
#5 0x00007f458876188f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
(rr) when
|
Current event: 1705413
|
(rr) c
|
Continuing.
|
|
Thread 14 received signal SIGABRT, Aborted.
|
[Switching to Thread 75971.76741]
|
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
|
51 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
|
(rr) when
|
Current event: 1753207
|
I think that for now, I will work around this by setting the flag buf_block_t::skip_flush_check in the encryption thread. That flag will ultimately be removed and the BtrBulk code cleaned up in MDEV-21347, which I believe to only affect 10.2, 10.3, 10.4 but not 10.5.
Side note: I am unable to repeat this failure on my system. I tried CMAKE_BUILD_TYPE=Debug compiled both with -O2 and without any optimizations.
Fix confirmed. A couple of (hopefully minor warnings), but most importantly no errors of this bug report. Thank you.
10.5-c9f5cb97af6d3ef853f84a19602efea715016734 fix confirmed |
dan@fstn4-p1:~/build-mariadb-server-10.5-debug-gccO0$ mysql-test/mtr --parallel=160 --force --max-test-fail=30 --repeat=4 --mem encryption.innodb_encryption_discard_import{,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,}
|
...
|
encryption.innodb_encryption_discard_import 'innodb' w54 [ 3 pass ] 92509
|
encryption.innodb_encryption_discard_import 'innodb' w31 [ 4 pass ] 90983
|
encryption.innodb_encryption_discard_import 'innodb' w97 [ 4 pass ] 90242
|
encryption.innodb_encryption_discard_import 'innodb' w130 [ 4 pass ] 89715
|
encryption.innodb_encryption_discard_import 'innodb' w2 [ 4 pass ] 93117
|
encryption.innodb_encryption_discard_import 'innodb' w58 [ 4 pass ] 90451
|
encryption.innodb_encryption_discard_import 'innodb' w124 [ 4 pass ] 89816
|
encryption.innodb_encryption_discard_import 'innodb' w87 [ 4 pass ] 89178
|
encryption.innodb_encryption_discard_import 'innodb' w57 [ 4 pass ] 91261
|
encryption.innodb_encryption_discard_import 'innodb' w12 [ 4 pass ] 90886
|
encryption.innodb_encryption_discard_import 'innodb' w42 [ 4 pass ] 89372
|
encryption.innodb_encryption_discard_import 'innodb' w82 [ 4 pass ] 92053
|
encryption.innodb_encryption_discard_import 'innodb' w75 [ 4 pass ] 91744
|
encryption.innodb_encryption_discard_import 'innodb' w3 [ 4 pass ] 90868
|
encryption.innodb_encryption_discard_import 'innodb' w45 [ 4 pass ] 91657
|
encryption.innodb_encryption_discard_import 'innodb' w96 [ 4 pass ] 88776
|
encryption.innodb_encryption_discard_import 'innodb' w13 [ 4 pass ] 90238
|
encryption.innodb_encryption_discard_import 'innodb' w7 [ 4 pass ] 91961
|
encryption.innodb_encryption_discard_import 'innodb' w114 [ 4 pass ] 92635
|
encryption.innodb_encryption_discard_import 'innodb' w30 [ 4 pass ] 91885
|
encryption.innodb_encryption_discard_import 'innodb' w62 [ 4 pass ] 92384
|
encryption.innodb_encryption_discard_import 'innodb' w160 [ 4 pass ] 92220
|
encryption.innodb_encryption_discard_import 'innodb' w131 [ 4 pass ] 93382
|
encryption.innodb_encryption_discard_import 'innodb' w117 [ 4 pass ] 91168
|
encryption.innodb_encryption_discard_import 'innodb' w71 [ 4 pass ] 91152
|
encryption.innodb_encryption_discard_import 'innodb' w74 [ 4 pass ] 92536
|
encryption.innodb_encryption_discard_import 'innodb' w64 [ 4 pass ] 91634
|
encryption.innodb_encryption_discard_import 'innodb' w123 [ 4 pass ] 89752
|
encryption.innodb_encryption_discard_import 'innodb' w39 [ 4 pass ] 91201
|
encryption.innodb_encryption_discard_import 'innodb' w147 [ 4 pass ] 91203
|
encryption.innodb_encryption_discard_import 'innodb' w135 [ 4 pass ] 91850
|
encryption.innodb_encryption_discard_import 'innodb' w106 [ 4 pass ] 91389
|
encryption.innodb_encryption_discard_import 'innodb' w126 [ 4 pass ] 89969
|
encryption.innodb_encryption_discard_import 'innodb' w99 [ 4 pass ] 90548
|
encryption.innodb_encryption_discard_import 'innodb' w141 [ 4 pass ] 93512
|
encryption.innodb_encryption_discard_import 'innodb' w90 [ 4 pass ] 90921
|
encryption.innodb_encryption_discard_import 'innodb' w1 [ 4 pass ] 90680
|
encryption.innodb_encryption_discard_import 'innodb' w46 [ 4 pass ] 89816
|
encryption.innodb_encryption_discard_import 'innodb' w118 [ 4 pass ] 91283
|
encryption.innodb_encryption_discard_import 'innodb' w134 [ 4 pass ] 90862
|
encryption.innodb_encryption_discard_import 'innodb' w70 [ 4 pass ] 90307
|
encryption.innodb_encryption_discard_import 'innodb' w23 [ 4 pass ] 92586
|
encryption.innodb_encryption_discard_import 'innodb' w102 [ 4 pass ] 92368
|
encryption.innodb_encryption_discard_import 'innodb' w63 [ 4 pass ] 93105
|
encryption.innodb_encryption_discard_import 'innodb' w48 [ 4 pass ] 90333
|
encryption.innodb_encryption_discard_import 'innodb' w36 [ 4 pass ] 89422
|
encryption.innodb_encryption_discard_import 'innodb' w111 [ 4 pass ] 90681
|
encryption.innodb_encryption_discard_import 'innodb' w29 [ 4 pass ] 91288
|
encryption.innodb_encryption_discard_import 'innodb' w43 [ 4 pass ] 91116
|
encryption.innodb_encryption_discard_import 'innodb' w34 [ 4 pass ] 92586
|
encryption.innodb_encryption_discard_import 'innodb' w155 [ 4 pass ] 90528
|
encryption.innodb_encryption_discard_import 'innodb' w133 [ 4 pass ] 91216
|
encryption.innodb_encryption_discard_import 'innodb' w128 [ 4 pass ] 91466
|
encryption.innodb_encryption_discard_import 'innodb' w119 [ 4 pass ] 90827
|
encryption.innodb_encryption_discard_import 'innodb' w136 [ 4 pass ] 90500
|
encryption.innodb_encryption_discard_import 'innodb' w79 [ 4 pass ] 90279
|
encryption.innodb_encryption_discard_import 'innodb' w146 [ 4 pass ] 93473
|
encryption.innodb_encryption_discard_import 'innodb' w101 [ 4 pass ] 93685
|
encryption.innodb_encryption_discard_import 'innodb' w59 [ 4 pass ] 89491
|
encryption.innodb_encryption_discard_import 'innodb' w100 [ 4 pass ] 92208
|
encryption.innodb_encryption_discard_import 'innodb' w121 [ 4 pass ] 91196
|
encryption.innodb_encryption_discard_import 'innodb' w61 [ 4 pass ] 90388
|
encryption.innodb_encryption_discard_import 'innodb' w25 [ 4 pass ] 91218
|
encryption.innodb_encryption_discard_import 'innodb' w14 [ 4 pass ] 89496
|
encryption.innodb_encryption_discard_import 'innodb' w151 [ 4 pass ] 90569
|
encryption.innodb_encryption_discard_import 'innodb' w103 [ 4 pass ] 91180
|
encryption.innodb_encryption_discard_import 'innodb' w44 [ 4 pass ] 89909
|
encryption.innodb_encryption_discard_import 'innodb' w78 [ 4 pass ] 91551
|
encryption.innodb_encryption_discard_import 'innodb' w159 [ 4 pass ] 91890
|
encryption.innodb_encryption_discard_import 'innodb' w113 [ 4 pass ] 90588
|
....
|
encryption.innodb_encryption_discard_import 'innodb' w4 [ 4 fail ] Found warnings/errors in server log file!
|
Test ended at 2020-06-15 19:55:31
|
line
|
2020-06-15 19:55:16 3 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-ib27' but there are 1 pending operations on it.
|
^ Found warnings in /home/dan/build-mariadb-server-10.5-debug-gccO0/mysql-test/var/4/log/mysqld.1.err
|
ok
|
|
encryption.innodb_encryption_discard_import 'innodb' w87 [ 3 fail ]
|
Test ended at 2020-06-15 19:53:51
|
|
CURRENT_TEST: encryption.innodb_encryption_discard_import
|
--- /home/dan/mariadb-server-10.5/mysql-test/suite/encryption/r/innodb_encryption_discard_import.result 2020-05-07 20:26:02.552751540 +1000
|
+++ /home/dan/mariadb-server-10.5/mysql-test/suite/encryption/r/innodb_encryption_discard_import.reject 2020-06-15 19:53:50.826222226 +1000
|
@@ -115,7 +115,7 @@
|
# t1 yes on expecting NOT FOUND
|
NOT FOUND /foobar/ in t1.ibd
|
# t2 ... on expecting NOT FOUND
|
-NOT FOUND /temp/ in t2.ibd
|
+FOUND 1 /temp/ in t2.ibd
|
# t3 ... on expecting NOT FOUND
|
NOT FOUND /barfoo/ in t3.ibd
|
# restart
|
|
|
Completed: Failed 28/1756 tests, 98.41% were successful.
|
|
Failing test(s): encryption.innodb_encryption_discard_import
|
|
The log files in var/log may give you some hint of what went wrong.
|
|
If you want to report this error, please read first the documentation
|
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html
|
|
Errors/warnings were found in logfiles during server shutdown after running the
|
following sequence(s) of tests:
|
encryption.innodb_encryption_discard_import
|
mysql-test-run: *** ERROR: there were failing test cases
|
The above warning about pending operations only occured after the first 1292 tests succeeded.
danblack, thank you! I have observed both of those occasional failures myself. The warnings about pending operations on #sql-ib files could have been introduced by MDEV-15053.
I believe that
MDEV-22027could cause this. I do not remember seeing this failure after finishingMDEV-21724.