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

SIGABRT in ib_counter_t from buf_inc_get

Details

    • Bug
    • Status: Closed (View Workflow)
    • Critical
    • Resolution: Cannot Reproduce
    • 11.8
    • N/A
    • Storage Engine - InnoDB
    • Ubuntu 24.04.02 LTS running kernel 6.8.0-55-generic

    Description

      CS 11.8.1 6f1161aa34cbb178b00fc24cbc46e2e0e2af767a (Optimized) Build 05/03/2025

      		 
      Core was generated by `/test/MD050325-mariadb-11.8.1-linux-x86_64-opt/bin/mariadbd --no-defaults --max'.
      		 
      Program terminated with signal SIGABRT, Aborted.
      		 
      #0  ib_counter_t<unsigned long, ib_counter_element_t, 128>::add (this=<optimized out>, index=2070842638, n=1) at include/ut0counter.h:75
      		 
       
      		 
      [Current thread is 1 (Thread 0x270a1a0d16c0 (LWP 1213190))]
      		 
      (gdb) bt
      		 
      #0  ib_counter_t<unsigned long, ib_counter_element_t, 128>::add (this=<optimized out>, index=2070842638, n=1) at include/ut0counter.h:75
      		 
      #1  ib_counter_t<unsigned long, ib_counter_element_t, 128>::add (this=<optimized out>, n=1) at include/ut0counter.h:69
      		 
      #2  ib_counter_t<unsigned long, ib_counter_element_t, 128>::inc (this=<optimized out>) at include/ut0counter.h:60
      		 
      #3  ib_counter_t<unsigned long, ib_counter_element_t, 128>::operator++ (this=<optimized out>) at include/ut0counter.h:61
      		 
      #4  buf_inc_get (stats=0x0)at /test/11.8_opt/storage/innobase/buf/buf0buf.cc:2367
      		 
      #5  buf_page_get_gen (page_id={m_id = 21474836483}, zip_size=0, rw_latch=rw_latch@entry=RW_S_LATCH, guess=guess@entry=0x342d35012560, mode=mode@entry=10, mtr=mtr@entry=0x270a1a0cfe10, err=0x270a1a0cf594)at /test/11.8_opt/storage/innobase/buf/buf0buf.cc:2790
      		 
      #6  0x0000559db878642b in btr_cur_t::search_leaf (this=0x18152c0079c0, tuple=0x18152c005f78, mode=PAGE_CUR_LE, latch_mode=BTR_MODIFY_LEAF, mtr=0x270a1a0cfe10) at /test/11.8_opt/storage/innobase/btr/btr0cur.cc:1230
      		 
      #7  0x0000559db802b33e in btr_pcur_open_with_no_init (tuple=0x18152c005f78, mode=40777631, latch_mode=BTR_MODIFY_LEAF, cursor=0x18152c0079c0, mtr=0x270a1a0cfe10) at include/btr0pcur.inl:322
      		 
      #8  btr_pcur_t::restore_position (this=0x18152c0079c0, restore_latch_mode=BTR_MODIFY_LEAF, mtr=0x270a1a0cfe10)at /test/11.8_opt/storage/innobase/btr/btr0pcur.cc:424
      		 
      #9  0x0000559db8749a35 in row_upd_clust_step (node=0x18152c006d98, thr=0x18152c0086a8) at /test/11.8_opt/storage/innobase/row/row0upd.cc:2609
      		 
      #10 row_upd (node=0x18152c006d98, thr=0x18152c0086a8)at /test/11.8_opt/storage/innobase/row/row0upd.cc:2756
      		 
      #11 row_upd_step (thr=thr@entry=0x18152c0086a8)at /test/11.8_opt/storage/innobase/row/row0upd.cc:2898
      		 
      #12 0x0000559db86f8597 in que_thr_step (thr=0x18152c0086a8)at /test/11.8_opt/storage/innobase/que/que0que.cc:535
      		 
      #13 que_run_threads_low (thr=0x18152c0086a8)at /test/11.8_opt/storage/innobase/que/que0que.cc:609
      		 
      #14 que_run_threads (thr=0x18152c0086a8)at /test/11.8_opt/storage/innobase/que/que0que.cc:629
      		 
      #15 0x0000559db86f884a in que_eval_sql (info=info@entry=0x18152c001478, sql=<optimized out>, trx=0x14c84ddf3c80)at /test/11.8_opt/storage/innobase/que/que0que.cc:668
      		 
      #16 0x0000559db87c65ab in dict_stats_exec_sql (pinfo=0x18152c001478, trx=0x26e379f, sql=<optimized out>)at /test/11.8_opt/storage/innobase/dict/dict0stats.cc:556
      		 
      #17 dict_stats_save_index_stat (index=index@entry=0x8a2282028f8, last_update=last_update@entry=1741208087, stat_name=0x559db8b40ccc "size", stat_value=1, sample_size=sample_size@entry=0x0, stat_description=0x559db8b44201 "Number of pages in the index", trx=0x14c84ddf3c80)at /test/11.8_opt/storage/innobase/dict/dict0stats.cc:2773
      		 
      #18 0x0000559db87c8b1e in dict_stats_save (table=<optimized out>, only_for_index=0x0)at /test/11.8_opt/storage/innobase/dict/dict0stats.cc:3062
      		 
      #19 0x0000559db87cfc49 in dict_stats_process_entry_from_recalc_pool (thd=0x628748000d48)at /test/11.8_opt/storage/innobase/dict/dict0stats_bg.cc:342
      		 
      #20 dict_stats_func ()at /test/11.8_opt/storage/innobase/dict/dict0stats_bg.cc:387
      		 
      #21 0x0000559db882414d in tpool::thread_pool_generic::timer_generic::run (this=0x559dd4791500) at /test/11.8_opt/tpool/tpool_generic.cc:336
      		 
      #22 0x0000559db88249f7 in tpool::task::execute (this=0x559dd4791540)at /test/11.8_opt/tpool/task.cc:37
      		 
      #23 0x0000559db88224d6 in tpool::thread_pool_generic::worker_main (this=0x559dd43e8cb0, thread_var=0x559dd43e9020)at /test/11.8_opt/tpool/tpool_generic.cc:574
      		 
      #24 0x0000073b696a1db4 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
      		 
      #25 0x0000320363d2baa4 in start_thread (arg=<optimized out>)at ./nptl/pthread_create.c:447
      		 
      #26 0x0000320363db8a34 in clone ()at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100

      rr trace:

      rr:/data/MDEV-36231/rr$ rr replay ./latest-trace

      Attachments

        Activity

          Ascending order - Click to sort in descending order
          marko Marko Mäkelä added a comment -

          Roel, it seems to me that an external process must have invoked kill -ABRT on the mariadbd process. The crash occurs in the last statement of the following function:

          static void buf_inc_get(ha_handler_stats *stats)
          		 
          {
          		 
            mariadb_increment_pages_accessed(stats);
          		 
            ++buf_pool.stat.n_page_gets;
          		 
          }

          The current instruction in this thread is not dereferencing any memory:

             0x0000559db802c3dd <+61>:	incq   (%rax)
          		 
             0x0000559db802c3e0 <+64>:	mov    %rax,-0x60(%rbp)
          		 
             0x0000559db802c3e4 <+68>:	rdtsc
          		 
          => 0x0000559db802c3e6 <+70>:	and    $0x7f,%eax
          		 
             0x0000559db802c3e9 <+73>:	shl    $0x6,%eax
          		 
             0x0000559db802c3ec <+76>:	lea    0x137ebcd(%rip),%rcx        # 0x559db93aafc0 <buf_pool>
          		 
             0x0000559db802c3f3 <+83>:	incq   (%rax,%rcx,1)

          This code is inlined in buf_page_get_gen().

          The process seems to be mostly idle. I see nothing being blocked inside InnoDB.
          Please double check the test invocation and explain what causes the SIGABRT to be sent to the mariadbd process.

          marko Marko Mäkelä added a comment - Roel , it seems to me that an external process must have invoked kill -ABRT on the mariadbd process. The crash occurs in the last statement of the following function: static void buf_inc_get(ha_handler_stats *stats) { mariadb_increment_pages_accessed(stats); ++buf_pool.stat.n_page_gets; } The current instruction in this thread is not dereferencing any memory: 0x0000559db802c3dd <+61>: incq (%rax) 0x0000559db802c3e0 <+64>: mov %rax,-0x60(%rbp) 0x0000559db802c3e4 <+68>: rdtsc => 0x0000559db802c3e6 <+70>: and $0x7f,%eax 0x0000559db802c3e9 <+73>: shl $0x6,%eax 0x0000559db802c3ec <+76>: lea 0x137ebcd(%rip),%rcx # 0x559db93aafc0 <buf_pool> 0x0000559db802c3f3 <+83>: incq (%rax,%rcx,1) This code is inlined in buf_page_get_gen() . The process seems to be mostly idle. I see nothing being blocked inside InnoDB. Please double check the test invocation and explain what causes the SIGABRT to be sent to the mariadbd process.
          Roel Roel Van de Paar added a comment - - edited

          marko] Thank you for the analysis!
          I looked through the the test code and logs. Firstly, the test was terminated due to a mariadb-admin shutdown hang. Relevant parts of the log:

          [07:54:45] Cleaning up & saving results if needed...
          		 
          [07:54:47] mariadbd failed to shutdown within 90 seconds...
          		 
          [07:54:47] RR Tracing is active, sending SIGABRT to tracee mariadbd and providing time for RR trace to finish correctly 
          [07:54:50] RR completed successfully and the trace was saved in the rr/mariadbd-0 directory inside the trial directory
          		 
          [07:54:51] Saving Trial: Moving rundir from /dev/shm/892293/394 to /data/892293/394

          However, there is one issue here: while the following command was used:

          timeout --signal=9 90s ${BASEDIR}/bin/mysqladmin -uroot -S${SOCKET} shutdown > /dev/null 2>&1  # mysqladmin is symlinked to mariadb-admin

          We can see in the log that only two seconds passed (rather than 90). From files analysis, it is sure that the timeout command exited with status code 137, which is normally the case when the set timeout (i.e. 90 seconds) has elapsed.
          However, if something external killed the timeout (like the OOM killer or one of our watchdogs) then the status is also 137. It is unclear what killed the timeout command itself.
          Just in case it was one of our watchdogs, I added 'timeout' to the process filter list to be sure any timeout's won't be affected in the future.
          As for the issue itself, looking further, I see that the query on which ERROR 2013 was triggered was this one:

          create TABLE t1 (a int, b int, primary key(a) using hash) ENGINE=InnoDB;#ERROR: 2013 - Lost connection to server during query

          However the various file/log timestamps do not render a conclusive picture.
          Now what is interesting is that MDEV-36228 has exactly the same scenario:

          [03:30:10] Cleaning up & saving results if needed...
          		 
          [03:31:42] mariadbd failed to shutdown within 90 seconds for this trial, saving it (pquery-results.sh will show these trials seperately)...
          		 
          [03:31:42] RR Tracing is active, sending SIGABRT to tracee mariadbd and providing time for RR trace to finish correctly
          		 
          [03:31:45] RR completed successfully and the trace was saved in the rr/mariadbd-0 directory inside the trial directory
          		 
          [03:31:46] Saving Trial: Moving rundir from /dev/shm/221267/26 to /data/221267/26

          However in this case the 90 second timeout matches the log timestamps.
          Thus, at least in the case of MDEV-36228 we can be quite sure that there was an issue that prevented mariadb-admin shutting down the sever for 90 seconds.
          At that point, a SIGABRT was sent to ensure the RR trace would be valid (and after this the test code waits for the file mariadb-0/incomplete to be removed by RR).
          So while the trace may have been finally closed down by the SIGABRT, the issue causing the shutdown hang happened earlier. As such, the final stack itself may not be valid and just a point-in-time capture.
          As (for MDEV-36228) you mentioned a rollback was happening - potentially that is what caused the mariadb-admin to hang?
          As for this bug (MDEV-36231), I will remove the stack from the filter list, and see what happens now that we filter 'timeout' from the watchdog processes.

          Roel Roel Van de Paar added a comment - - edited marko ] Thank you for the analysis! I looked through the the test code and logs. Firstly, the test was terminated due to a mariadb-admin shutdown hang. Relevant parts of the log: [07:54:45] Cleaning up & saving results if needed... [07:54:47] mariadbd failed to shutdown within 90 seconds... [07:54:47] RR Tracing is active, sending SIGABRT to tracee mariadbd and providing time for RR trace to finish correctly [07:54:50] RR completed successfully and the trace was saved in the rr/mariadbd-0 directory inside the trial directory [07:54:51] Saving Trial: Moving rundir from /dev/shm/892293/394 to /data/892293/394 However, there is one issue here: while the following command was used: timeout --signal=9 90s ${BASEDIR} /bin/mysqladmin -uroot -S${SOCKET} shutdown > /dev/null 2>&1 # mysqladmin is symlinked to mariadb-admin We can see in the log that only two seconds passed (rather than 90). From files analysis, it is sure that the timeout command exited with status code 137, which is normally the case when the set timeout (i.e. 90 seconds) has elapsed. However, if something external killed the timeout (like the OOM killer or one of our watchdogs) then the status is also 137. It is unclear what killed the timeout command itself. Just in case it was one of our watchdogs, I added 'timeout' to the process filter list to be sure any timeout's won't be affected in the future. As for the issue itself, looking further, I see that the query on which ERROR 2013 was triggered was this one: create TABLE t1 (a int , b int , primary key (a) using hash) ENGINE=InnoDB;#ERROR: 2013 - Lost connection to server during query However the various file/log timestamps do not render a conclusive picture. Now what is interesting is that MDEV-36228 has exactly the same scenario: [03:30:10] Cleaning up & saving results if needed... [03:31:42] mariadbd failed to shutdown within 90 seconds for this trial, saving it (pquery-results.sh will show these trials seperately)... [03:31:42] RR Tracing is active, sending SIGABRT to tracee mariadbd and providing time for RR trace to finish correctly [03:31:45] RR completed successfully and the trace was saved in the rr/mariadbd-0 directory inside the trial directory [03:31:46] Saving Trial: Moving rundir from /dev/shm/221267/26 to /data/221267/26 However in this case the 90 second timeout matches the log timestamps. Thus, at least in the case of MDEV-36228 we can be quite sure that there was an issue that prevented mariadb-admin shutting down the sever for 90 seconds. At that point, a SIGABRT was sent to ensure the RR trace would be valid (and after this the test code waits for the file mariadb-0/incomplete to be removed by RR). So while the trace may have been finally closed down by the SIGABRT, the issue causing the shutdown hang happened earlier. As such, the final stack itself may not be valid and just a point-in-time capture. As (for MDEV-36228 ) you mentioned a rollback was happening - potentially that is what caused the mariadb-admin to hang? As for this bug ( MDEV-36231 ), I will remove the stack from the filter list, and see what happens now that we filter 'timeout' from the watchdog processes.
          marko Marko Mäkelä added a comment -

          I think that 90 seconds may be an unreasonably short shutdown timeout when running under rr record. When there is excessive context switching going on, it is possible that a run with rr record will be thousands of times slower than without it. A larger innodb_buffer_pool_size and innodb_log_file_size should help reduce some context switching. So would a lower number of concurrent client connections. I think that 1 to 3 of them should be sufficient for reproducing most bugs.

          marko Marko Mäkelä added a comment - I think that 90 seconds may be an unreasonably short shutdown timeout when running under rr record . When there is excessive context switching going on, it is possible that a run with rr record will be thousands of times slower than without it. A larger innodb_buffer_pool_size and innodb_log_file_size should help reduce some context switching. So would a lower number of concurrent client connections. I think that 1 to 3 of them should be sufficient for reproducing most bugs.
          Roel Roel Van de Paar added a comment -

          Thank you. In summary, I've removed the stacks of both MDEV-36228 and MDEV-36231 from the filter list, ensured the timeout will not be killed, and updated the shutdown timeout to 240s when rr record is being used. If either issue resurfaces, I will reanalyze and if needed re-open the ticket.

          Roel Roel Van de Paar added a comment - Thank you. In summary, I've removed the stacks of both MDEV-36228 and MDEV-36231 from the filter list, ensured the timeout will not be killed, and updated the shutdown timeout to 240s when rr record is being used. If either issue resurfaces, I will reanalyze and if needed re-open the ticket.

          People

            Roel Roel Van de Paar
            Roel Roel Van de Paar
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Git Integration

                Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.