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
-
-
- Closed
-
-
-
- Closed
-
Activity
| Field | Original Value | New Value |
|---|---|---|
| Link |
This issue relates to |
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/'
|
| Link |
This issue relates to |
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
|
......
|
| Attachment | MDEV-22190-gdb-bt.txt [ 52096 ] |
| Attachment | MDEV-22190-gdb-bt-full-page_simple_validate_new.txt [ 52097 ] |
| Labels | need_rr | rr-profile |
| Labels | rr-profile | need_rr |
| Labels | need_rr | rr-profile |
| Status | Open [ 1 ] | In Progress [ 3 ] |
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.
| Link |
This issue relates to |
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.
| Link |
This issue relates to |
| issue.field.resolutiondate | 2020-06-13 09:12:46.0 | 2020-06-13 09:12:46.701 |
| Fix Version/s | 10.5.4 [ 24264 ] | |
| Fix Version/s | 10.5 [ 23123 ] | |
| Resolution | Fixed [ 1 ] | |
| Status | In Progress [ 3 ] | Closed [ 6 ] |
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.
| Workflow | MariaDB v3 [ 106877 ] | MariaDB v4 [ 157576 ] |
I believe that
MDEV-22027could cause this. I do not remember seeing this failure after finishingMDEV-21724.