Uploaded image for project: 'Percona Server'
  1. Percona Server
  2. PS-5510

Intermittent shutdown crashes if threadpool is enabled

    Details

    • Type: Bug
    • Status: Done
    • Priority: Medium
    • Resolution: Fixed
    • Affects Version/s: 8.0, Not 5.6, Not 5.7
    • Fix Version/s: 8.0.15-6
    • Component/s: None

      Description

      Server started with threadpool crashes at the very end of shutdown, intermittently. An example:

      [  5%] main.percona_signal_handling_threadpool  w2  [ fail ]  Found warnings/errors in server log file!
              Test ended at 2019-03-21 02:38:11
      line
      Attempting backtrace. You can use the following information to find out
      ^ Found warnings in /home/laurynas/percona/obj-percona-8.0-release/mysql-test/var/2/log/mysqld.1.err
      ok
      

      with example following core dump stacktraces:

      Thread 3 (Thread 0x7f11b00b5700 (LWP 22330)):
      #0  0x00007f11c51e73ab in _Unwind_IteratePhdrCallback (info=info@entry=0x7f11b00b3d40, size=size@entry=64, ptr=ptr@entry=0x7f11b00b3dd0) at ../../../src/libgcc/unwind-dw2-fde-dip.c:398
      #1  0x00007f11c5146417 in __GI___dl_iterate_phdr (callback=callback@entry=0x7f11c51e6ff0 <_Unwind_IteratePhdrCallback>, data=data@entry=0x7f11b00b3dd0) at dl-iteratephdr.c:75
      #2  0x00007f11c51e8281 in _Unwind_Find_FDE (pc=0x7f11c5114ca1 <__GI___backtrace+97>, bases=bases@entry=0x7f11b00b3f58) at ../../../src/libgcc/unwind-dw2-fde-dip.c:469
      #3  0x00007f11c51e4983 in uw_frame_state_for (context=context@entry=0x7f11b00b3eb0, fs=fs@entry=0x7f11b00b3fa0) at ../../../src/libgcc/unwind-dw2.c:1257
      #4  0x00007f11c51e6898 in _Unwind_Backtrace (trace=0x7f11c5114b40 <backtrace_helper>, trace_argument=0x7f11b00b4160) at ../../../src/libgcc/unwind.inc:302
      #5  0x00007f11c5114ca2 in __GI___backtrace (array=array@entry=0x7f11b00b41c0, size=size@entry=128) at backtrace.c:111
      #6  0x0000558c8936bffd in my_print_stacktrace (stack_bottom=0x0, thread_stack=286720) at ../../percona-8.0/mysys/stacktrace.cc:258
      #7  0x0000558c886641a3 in handle_fatal_signal (sig=11) at ../../percona-8.0/sql/signal_handler.cc:178
      #8  <signal handler called>
      #9  std::__atomic_base<bool>::store (__m=std::memory_order_seq_cst, __i=true, this=0x7f11bc4ce878) at /usr/include/c++/7/bits/atomic_base.h:374
      #10 std::__atomic_base<bool>::operator= (__i=true, this=0x7f11bc4ce878) at /usr/include/c++/7/bits/atomic_base.h:267
      #11 std::atomic<bool>::operator= (__i=true, this=0x7f11bc4ce878) at /usr/include/c++/7/atomic:79
      #12 memory_full_aggregate<PFS_memory_safe_stat, PFS_memory_shared_stat> (stat=0x7f11bc4ce878, from=0x7f11bf16c088) at ../../../percona-8.0/storage/perfschema/pfs_stat.h:1029
      #13 aggregate_all_memory (alive=false, from_array=0x7f11bf169850, to_array=0x7f11bc4cc040) at ../../../percona-8.0/storage/perfschema/pfs_instr.cc:1617
      #14 0x0000558c893a40b3 in aggregate_thread (thread=thread@entry=0x7f11c2c67d80, safe_account=0x558c8b9acc80, safe_user=0x0, safe_host=0x0)
          at ../../../percona-8.0/storage/perfschema/pfs_instr.cc:1761
      #15 0x0000558c89388e8f in pfs_delete_current_thread_v1 () at ../../../percona-8.0/storage/perfschema/pfs.cc:3385
      #16 0x0000558c88646237 in worker_main (param=param@entry=0x558c8ac0e600 <all_groups+1536>) at ../../percona-8.0/sql/threadpool_unix.cc:1451
      #17 0x0000558c89388a3f in pfs_spawn_thread (arg=0x7f115c035980) at ../../../percona-8.0/storage/perfschema/pfs.cc:2836
      #18 0x00007f11c6bc1164 in start_thread (arg=<optimized out>) at pthread_create.c:486
      #19 0x00007f11c5105def in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      
      Thread 2 (Thread 0x7f11c343b840 (LWP 21817)):
      #0  0x00007f11c50ff497 in munmap () at ../sysdeps/unix/syscall-template.S:78
      #1  0x0000558c893997ae in pfs_free (klass=klass@entry=0x558c8ac76640 <builtin_memory_user_errors>, size=140768, ptr=<optimized out>)
          at ../../../percona-8.0/storage/perfschema/pfs_global.cc:113
      #2  0x0000558c89399856 in pfs_free_array (klass=klass@entry=0x558c8ac76640 <builtin_memory_user_errors>, n=<optimized out>, size=size@entry=32, ptr=<optimized out>)
      --Type <RET> for more, q to quit, c to continue without paging--
          at ../../../percona-8.0/storage/perfschema/pfs_global.cc:177
      #3  0x0000558c89394475 in PFS_error_stat::cleanup (memory_class=<optimized out>, this=0x558c8b9eb2b0) at ../../../percona-8.0/storage/perfschema/pfs_stat.h:604
      #4  PFS_user_allocator::free_array (this=<optimized out>, array=array@entry=0x558c8b9cfdf0) at ../../../percona-8.0/storage/perfschema/pfs_buffer_container.cc:1036
      #5  0x0000558c893af80c in PFS_buffer_scalable_container<PFS_user, 128, 128, PFS_user_array, PFS_user_allocator>::cleanup (this=<optimized out>)
          at ../../../percona-8.0/storage/perfschema/pfs_buffer_container.h:452
      #6  cleanup_user () at ../../../percona-8.0/storage/perfschema/pfs_user.cc:64
      #7  0x0000558c893ac688 in cleanup_performance_schema () at ../../../percona-8.0/storage/perfschema/pfs_server.cc:284
      #8  0x0000558c893acd6c in shutdown_performance_schema () at ../../../percona-8.0/storage/perfschema/pfs_server.cc:337
      #9  0x0000558c8840a97c in mysqld_exit (exit_code=0) at ../../percona-8.0/sql/mysqld.cc:2060
      #10 0x0000558c8841caad in mysqld_main (argc=<optimized out>, argv=<optimized out>) at ../../percona-8.0/sql/mysqld.cc:7094
      #11 0x00007f11c500f09b in __libc_start_main (main=0x558c8829ca00 <main(int, char**)>, argc=7, argv=0x7fff564fb148, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, 
          stack_end=0x7fff564fb138) at ../csu/libc-start.c:308
      #12 0x0000558c882cb1ea in _start ()
      
      Thread 1 (Thread 0x7f11b00fd700 (LWP 22300)):
      #0  memcpy (__len=176, __src=0x7f11c2c63d20, __dest=<optimized out>) at /usr/include/x86_64-linux-gnu/bits/string_fortified.h:34
      #1  copy_events_waits (source=0x7f11c2c63d20, dest=<optimized out>) at ../../../percona-8.0/storage/perfschema/pfs_events_waits.cc:93
      #2  insert_events_waits_history_long (wait=wait@entry=0x7f11c2c63d20) at ../../../percona-8.0/storage/perfschema/pfs_events_waits.cc:143
      #3  0x0000558c8938aad8 in pfs_end_cond_wait_v1 (locker=locker@entry=0x7f11b00fcce0) at ../../../percona-8.0/storage/perfschema/pfs.cc:4918
      #4  0x0000558c88645ee0 in inline_mysql_cond_timedwait (src_file=0x558c8a0b4220 "../../percona-8.0/sql/threadpool_unix.cc", src_line=1083, abstime=0x7f11b00fccd0, 
          mutex=0x558c8ac0e600 <all_groups+1536>, that=0x7f11b00fcd40) at ../../percona-8.0/include/mysql/psi/mysql_cond.h:226
      #5  get_event (abstime=0x7f11b00fccd0, thread_group=0x558c8ac0e600 <all_groups+1536>, current_thread=0x7f11b00fcd20) at ../../percona-8.0/sql/threadpool_unix.cc:1082
      #6  worker_main (param=param@entry=0x558c8ac0e600 <all_groups+1536>) at ../../percona-8.0/sql/threadpool_unix.cc:1432
      #7  0x0000558c89388a3f in pfs_spawn_thread (arg=0x558c8be3f400) at ../../../percona-8.0/storage/perfschema/pfs.cc:2836
      #8  0x00007f11c6bc1164 in start_thread (arg=<optimized out>) at pthread_create.c:486
      #9  0x00007f11c5105def in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      

      Many other stacktraces are possible. What they have in common is one threadpool worker thread which just woke up from its event wait, and the rest of the server far advanced in the shutdown (as far as in libc cleanup routines after main()).

      This is caused by worker thread shutdown being asynchronuous, i.e. tp_end() calls thread_group_close() which wakes the threads to shut them down and then their shutdown proceeds asynchronuously.

        Smart Checklist

          Attachments

            Activity

              People

              • Assignee:
                laurynas.biveinis Laurynas Biveinis (Inactive)
                Reporter:
                laurynas.biveinis Laurynas Biveinis (Inactive)
              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - Not Specified
                  Not Specified
                  Logged:
                  Time Spent - 2 hours, 36 minutes
                  2h 36m