Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-26674

io_uring related hangs on the Linux 5.14.0 kernel

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Stalled (View Workflow)
    • Priority: Blocker
    • Resolution: Unresolved
    • Affects Version/s: 10.6, 10.7
    • Fix Version/s: 10.6.6, 10.7.2
    • Labels:
    • Environment:

      Description

      After a kernel upgrade, I started to experience random hangs in InnoDB related to io_uring. Yesterday with an older kernel

      Linux version 5.10.0-8-amd64 (debian-kernel@lists.debian.org) (gcc-10 (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2) #1 SMP Debian 5.10.46-4 (2021-08-03)
      

      everything ran fine, but today I got several tests failing or hanging when running the following on a nproc=40 machine:

      nice ./mtr --parallel=60 --big-test --force
      

      Here is an example with the names of hanging tests:

      10.6 d95361107c07b6e8257a7a82c41b18af64ab8d89

      Completed: Failed 7/5108 tests, 99.86% were successful.
       
      Failing test(s): innodb.innodb-64k innodb_zip.innochecksum_2 gcol.innodb_virtual_basic stress.ddl_innodb innodb_gis.kill_server main.index_merge_innodb innodb_gis.rtree_debug
      

      I suspect that the culprit is the newer kernel:

      Linux version 5.14.0-1-amd64 (debian-kernel@lists.debian.org) (gcc-10 (Debian 10.3.0-10) 10.3.0, GNU ld (GNU Binutils for Debian) 2.37) #1 SMP Debian 5.14.6-2 (2021-09-19)
      

      If I disable io_uring for the MariaDB server build, then everything will work just fine using the libaio interface (io_submit, io_getevents).

      Here is one example of a hang:

      10.6 d95361107c07b6e8257a7a82c41b18af64ab8d89

      innodb_zip.innochecksum_2 '4k,innodb'    w40 [ fail ]  Found warnings/errors in server log file!
              Test ended at 2021-09-24 14:43:48
      line
      Attempting backtrace. You can use the following information to find out
      Thread 7 (Thread 0x7eff55043640 (LWP 954970)):
      #0  0x00007eff56cb7bd2 in __GI___sigtimedwait (set=0x7eff55042ca8, info=0x7eff55042c20, timeout=0x0) at ../sysdeps/unix/sysv/linux/sigtimedwait.c:36
      #1  0x000055c55ef1883b in my_sigwait (set=0x7eff55042ca8, sig=0x7eff55042c1c, code=<optimized out>) at /mariadb/10.6/include/my_pthread.h:195
      #2  signal_hand (arg=<optimized out>) at /mariadb/10.6/sql/mysqld.cc:3113
      #3  0x00007eff57075eae in start_thread (arg=0x7eff55043640) at pthread_create.c:463
      #4  0x00007eff56d77a5f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
       
      Thread 6 (LWP 961402):
      #0  0x0000000000000000 in ?? ()
      Backtrace stopped: Cannot access memory at address 0x0
       
      Thread 5 (Thread 0x7eff5638b640 (LWP 954807)):
      #0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
      #1  0x00007eff57721cb0 in ?? () from /usr/lib/x86_64-linux-gnu/liburing.so.1
      #2  0x00007eff57721963 in __io_uring_get_cqe () from /usr/lib/x86_64-linux-gnu/liburing.so.1
      #3  0x000055c55f872361 in io_uring_wait_cqe_nr (ring=0x55c562837c98, cqe_ptr=0x7eff5638ad10, wait_nr=1) at /usr/include/liburing.h:494
      #4  io_uring_wait_cqe (ring=0x55c562837c98, cqe_ptr=0x7eff5638ad10) at /usr/include/liburing.h:514
      #5  (anonymous namespace)::aio_uring::thread_routine (aio=0x55c562837c90) at /mariadb/10.6/tpool/aio_liburing.cc:137
      #6  0x00007eff56f2e8c4 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
      #7  0x00007eff57075eae in start_thread (arg=0x7eff5638b640) at pthread_create.c:463
      #8  0x00007eff56d77a5f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
       
      Thread 4 (LWP 961385):
      #0  0x0000000000000000 in ?? ()
      Backtrace stopped: Cannot access memory at address 0x0
       
      Thread 3 (Thread 0x7eff5781f640 (LWP 954792)):
      #0  futex_abstimed_wait_cancelable (private=0, abstime=0x7eff5781ed10, clockid=1468132416, expected=0, futex_word=0x55c560ae27fc <COND_timer+44>) at ../sysdeps/nptl/futex-internal.h:323
      #1  __pthread_cond_wait_common (abstime=0x7eff5781ed10, clockid=1468132416, mutex=0x55c560ae2748 <LOCK_timer+40>, cond=0x55c560ae27d0 <COND_timer>) at pthread_cond_wait.c:520
      #2  __pthread_cond_timedwait (cond=cond@entry=0x55c560ae27d0 <COND_timer>, mutex=mutex@entry=0x55c560ae2748 <LOCK_timer+40>, abstime=abstime@entry=0x7eff5781ed10) at pthread_cond_wait.c:656
      #3  0x000055c55f8dbacf in safe_cond_timedwait (cond=0x55c560ae27d0 <COND_timer>, mp=0x55c560ae2720 <LOCK_timer>, abstime=abstime@entry=0x7eff5781ed10, file=0x55c55f96aaa9 "/mariadb/10.6/include/mysql/psi/mysql_thread.h", line=line@entry=1088) at /mariadb/10.6/mysys/thr_mutex.c:546
      #4  0x000055c55f8dc26f in inline_mysql_cond_timedwait (that=0x55c560ae27fc <COND_timer+44>, mutex=0x189, abstime=0x7eff5781ed10, src_file=<optimized out>, src_line=<optimized out>) at /mariadb/10.6/include/mysql/psi/mysql_thread.h:1088
      #5  timer_handler (arg=<optimized out>) at /mariadb/10.6/mysys/thr_timer.c:321
      #6  0x00007eff57075eae in start_thread (arg=0x7eff5781f640) at pthread_create.c:463
      #7  0x00007eff56d77a5f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
       
      Thread 2 (Thread 0x7efec9ffb640 (LWP 954925)):
      #0  futex_abstimed_wait_cancelable (private=0, abstime=0x7efec9ffac78, clockid=-905991216, expected=0, futex_word=0x55c5627dc54c) at ../sysdeps/nptl/futex-internal.h:323
      #1  __pthread_cond_wait_common (abstime=0x7efec9ffac78, clockid=-905991216, mutex=0x55c5627cd990, cond=0x55c5627dc520) at pthread_cond_wait.c:520
      #2  __pthread_cond_clockwait (abstime=0x7efec9ffac78, clockid=-905991216, mutex=0x55c5627cd990, cond=0x55c5627dc520) at pthread_cond_wait.c:677
      #3  __pthread_cond_clockwait (cond=0x55c5627dc520, mutex=0x55c5627cd990, clockid=-905991216, abstime=0x7efec9ffac78) at pthread_cond_wait.c:665
      #4  0x000055c55f86efaf in std::__condvar::wait_until (this=0x55c5627dc520, __m=<error reading variable>, __clock=1, __abs_time=@0x7efec9ffac78: {tv_sec = 24713, tv_nsec = 284075513}) at /usr/bin/../lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/std_mutex.h:169
      #5  std::condition_variable::__wait_until_impl<std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (this=0x55c5627dc520, __lock=@0x7efec9ffacc8: {_M_device = 0x55c5627cd990, _M_owns = true}, __atime=<optimized out>) at /usr/bin/../lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/condition_variable:201
      #6  std::condition_variable::wait_until<std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (this=0x55c5627dc520, __lock=@0x7efec9ffacc8: {_M_device = 0x55c5627cd990, _M_owns = true}, __atime=<optimized out>) at /usr/bin/../lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/condition_variable:111
      #7  std::condition_variable::wait_for<long, std::ratio<1l, 1000l> > (this=0x55c5627dc520, __lock=@0x7efec9ffacc8: {_M_device = 0x55c5627cd990, _M_owns = true}, __rtime=@0x55c5627cd9b8: {__r = 60000}) at /usr/bin/../lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/condition_variable:163
      #8  tpool::thread_pool_generic::wait_for_tasks (this=this@entry=0x55c5627cd880, lk=@0x7efec9ffacc8: {_M_device = 0x55c5627cd990, _M_owns = true}, thread_data=thread_data@entry=0x55c5627dc520) at /mariadb/10.6/tpool/tpool_generic.cc:449
      #9  0x000055c55f86f14e in tpool::thread_pool_generic::get_task (this=this@entry=0x55c5627cd880, thread_var=thread_var@entry=0x55c5627dc520, t=t@entry=0x7efec9ffad18) at /mariadb/10.6/tpool/tpool_generic.cc:502
      #10 0x000055c55f86f444 in tpool::thread_pool_generic::worker_main (this=0x55c5627cd880, thread_var=0x55c5627dc520) at /mariadb/10.6/tpool/tpool_generic.cc:547
      #11 0x00007eff56f2e8c4 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
      #12 0x00007eff57075eae in start_thread (arg=0x7efec9ffb640) at pthread_create.c:463
      #13 0x00007eff56d77a5f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
       
      Thread 1 (Thread 0x7eff5699a840 (LWP 954716)):
      #0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:54
      #1  0x000055c55f25a83a in handle_fatal_signal (sig=6) at /mariadb/10.6/sql/signal_handler.cc:345
      #2  <signal handler called>
      #3  0x00007eff57079849 in __pthread_mutex_unlock_usercnt (mutex=mutex@entry=0x55c5601cf528 <buf_pool+40>, decr=decr@entry=0) at pthread_mutex_unlock.c:58
      #4  0x00007eff5707c1a8 in __pthread_cond_wait_common (abstime=0x7fff59490d98, clockid=0, mutex=0x55c5601cf528 <buf_pool+40>, cond=0x55c5601cf5f0 <buf_pool+240>) at pthread_cond_wait.c:421
      #5  __pthread_cond_timedwait (cond=cond@entry=0x55c5601cf5f0 <buf_pool+240>, mutex=mutex@entry=0x55c5601cf528 <buf_pool+40>, abstime=abstime@entry=0x7fff59490d98) at pthread_cond_wait.c:656
      #6  0x000055c55f8dbacf in safe_cond_timedwait (cond=0x55c5601cf5f0 <buf_pool+240>, mp=0x55c5601cf500 <buf_pool>, abstime=0x7fff59490d98, file=0x55c55fbd74a8 "/mariadb/10.6/storage/innobase/buf/buf0flu.cc", line=2435) at /mariadb/10.6/mysys/thr_mutex.c:546
      #7  0x000055c55f796517 in buf_flush_buffer_pool () at /mariadb/10.6/storage/innobase/buf/buf0flu.cc:2434
      #8  0x000055c55f5a1121 in logs_empty_and_mark_files_at_shutdown () at /mariadb/10.6/storage/innobase/log/log0log.cc:1139
      #9  0x000055c55f6d79a0 in innodb_shutdown () at /mariadb/10.6/storage/innobase/srv/srv0start.cc:1970
      #10 0x000055c55f517318 in innobase_end () at /mariadb/10.6/storage/innobase/handler/ha_innodb.cc:4273
      #11 0x000055c55f25b48f in ha_finalize_handlerton (plugin=0x55c5627abcb0) at /mariadb/10.6/sql/handler.cc:595
      #12 0x000055c55f00b6df in plugin_deinitialize (plugin=0x55c5627abcb0, ref_check=true) at /mariadb/10.6/sql/sql_plugin.cc:1266
      #13 0x000055c55f009f9a in reap_plugins () at /mariadb/10.6/sql/sql_plugin.cc:1342
      #14 0x000055c55f00bba3 in plugin_shutdown () at /mariadb/10.6/sql/sql_plugin.cc:2050
      #15 0x000055c55ef179ed in clean_up (print_message=true) at /mariadb/10.6/sql/mysqld.cc:1923
      #16 0x000055c55ef196a2 in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /mariadb/10.6/sql/mysqld.cc:5844
      #17 0x00007eff56ca1e4a in __libc_start_main (main=0x55c55ef16a40 <main(int, char**)>, argc=26, argv=0x7fff59491718, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fff59491708) at ../csu/libc-start.c:314
      #18 0x000055c55ef1697a in _start () at /mariadb/10.6/sql/my_decimal.h:147
      

      This looks like a shutdown hang, and the problem could be the hung Thread 5. There are also 2 suspicious threads with a null address. I do not remember seeing such stack traces earlier.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              danblack Daniel Black
              Reporter:
              marko Marko Mäkelä
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

                Dates

                Created:
                Updated:

                  Git Integration