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

InnoDB: Failing assertion: UT_LIST_GET_LEN(buf_pool->flush_list) == 0 during shutdown

    XMLWordPrintable

    Details

      Description

      origin/10.4 2b66cd249384221e2a892f655fe84bb58ddc31bd 2021-08-23T10:44:06+03:00
      

      Workflow:

      1. DB server start
      2. Generate some initial data
      3. 33 sessions run a DDL/DML mix concurrent. They disconnect after 300s.
      4. Shutdown attempt which ends with

        # 2021-08-23T03:52:21 [3465505] | [rr 3469573 1955505]2021-08-23  3:51:27 0 [Note] /data/Server_bin/10.4_asan/bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown
        # 2021-08-23T03:52:21 [3465505] | [rr 3469573 1956164]2021-08-23  3:51:27 83 [Warning] Aborted connection 83 to db: 'mysql' user: 'root' host: 'localhost' (This connection closed normally)
        # 2021-08-23T03:52:21 [3465505] | [rr 3469573 1957093]2021-08-23  3:51:27 0 [Note] InnoDB: FTS optimize thread exiting.
        # 2021-08-23T03:52:21 [3465505] | [rr 3469573 1957281]2021-08-23  3:51:27 0 [Note] Event Scheduler: Purging the queue. 0 events
        # 2021-08-23T03:52:21 [3465505] | [rr 3469573 1957790]2021-08-23  3:51:29 0 [Note] InnoDB: Starting shutdown...
        # 2021-08-23T03:52:21 [3465505] | [rr 3469573 1957905]2021-08-23  3:51:29 0 [Note] InnoDB: Dumping buffer pool(s) to /dev/shm/vardir/1629713923/217/1/data/ib_buffer_pool
        # 2021-08-23T03:52:21 [3465505] | [rr 3469573 1957917]2021-08-23  3:51:29 0 [Note] InnoDB: Instance 0, restricted to 95 pages due to innodb_buf_pool_dump_pct=25
        # 2021-08-23T03:52:21 [3465505] | [rr 3469573 1957929]2021-08-23  3:51:29 0 [Note] InnoDB: Buffer pool(s) dump completed at 210823  3:51:29
        # 2021-08-23T03:52:21 [3465505] | [rr 3469573 1958065]2021-08-23 03:51:29 0x66b427d20700[rr 3469573 1958068]  InnoDB: Assertion failure in file /data/Server/10.4/storage/innobase/buf/buf0flu.cc line 3348
        # 2021-08-23T03:52:21 [3465505] | [rr 3469573 1958070]InnoDB: Failing assertion: UT_LIST_GET_LEN(buf_pool->flush_list) == 0
        # 2021-08-23T03:52:21 [3465505] | [rr 3469573 1958072]InnoDB: We intentionally generate a memory trap.
        

      Per Marko Mäkelä:
      ----------------
      1. A page was read before the shutdown

      #3  0x0000560a62536e21 in buf_read_ibuf_merge_pages (sync=false, 
          space_ids=0x7e8e3789f710, page_nos=0x7e8e3789f6b0, n_stored=1)
          at /data/Server/10.4/storage/innobase/buf/buf0rea.cc:805
      #4  0x0000560a620290ba in ibuf_merge_pages (n_pages=0x7e8e3789fd90, sync=false)
          at /data/Server/10.4/storage/innobase/ibuf/ibuf0ibuf.cc:2462
      #5  0x0000560a62029e41 in ibuf_merge (n_pages=0x7e8e3789fd90, sync=false)
          at /data/Server/10.4/storage/innobase/ibuf/ibuf0ibuf.cc:2567
      #6  0x0000560a6202a407 in ibuf_merge_in_background (full=false)
          at /data/Server/10.4/storage/innobase/ibuf/ibuf0ibuf.cc:2638
      #7  0x0000560a62316a0b in srv_master_do_active_tasks ()
          at /data/Server/10.4/storage/innobase/srv/srv0srv.cc:2147
      

      2. There happens a change buffer merge after the begin of the shutdown process

      #7  0x0000560a620d2562 in mtr_t::commit (this=0x2f2d612b0830)
          at /data/Server/10.4/storage/innobase/mtr/mtr0mtr.cc:452
      #8  0x0000560a6201eecd in btr_pcur_commit_specify_mtr (pcur=0x2f2d612b04c0, 
          mtr=0x2f2d612b0830)
          at /data/Server/10.4/storage/innobase/include/btr0pcur.ic:345
      #9  0x0000560a6201feb1 in ibuf_btr_pcur_commit_specify_mtr (
          pcur=0x2f2d612b04c0, mtr=0x2f2d612b0830)
          at /data/Server/10.4/storage/innobase/ibuf/ibuf0ibuf.cc:322
      #10 0x0000560a62035092 in ibuf_merge_or_delete_for_page (block=0x5ac0422418b8, 
          page_id=..., zip_size=0)
          at /data/Server/10.4/storage/innobase/ibuf/ibuf0ibuf.cc:4572
      #11 0x0000560a624df00d in buf_page_io_complete (bpage=0x5ac0422418b8, 
          dblwr=true, evict=false)
          at /data/Server/10.4/storage/innobase/buf/buf0buf.cc:6201
      #12 0x0000560a62610488 in fil_aio_wait (segment=2)
          at /data/Server/10.4/storage/innobase/fil/fil0fil.cc:4375
      

      3. The bug does not seem to be a duplicate of MDEV-12630.
      4. MDEV-19514 Resolved: 2019-10-11 16:57 , Fix Version/s: 10.5.0 should have fixed that trouble.

      RQG
      ------

      git clone https://github.com/mleich1/rqg --branch experimental RQG
       
      perl rqg.pl \
      --grammar=conf/mariadb/innodb_compression_encryption.yy \
      --gendata=conf/mariadb/innodb_compression_encryption.zz \
      --max_gd_duration=1800 \
      --mysqld=--loose-innodb-encryption-threads=7 \
      --mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \
      --mysqld=--loose-idle_write_transaction_timeout=0 \
      --mysqld=--loose-idle_transaction_timeout=0 \
      --mysqld=--loose-idle_readonly_transaction_timeout=0 \
      --mysqld=--connect_timeout=60 \
      --mysqld=--interactive_timeout=28800 \
      --mysqld=--slave_net_timeout=60 \
      --mysqld=--net_read_timeout=30 \
      --mysqld=--net_write_timeout=60 \
      --mysqld=--loose-table_lock_wait_timeout=50 \
      --mysqld=--wait_timeout=28800 \
      --mysqld=--lock-wait-timeout=86400 \
      --mysqld=--innodb-lock-wait-timeout=50 \
      --no-mask \
      --queries=10000000 \
      --seed=random \
      --reporters=Backtrace \
      --reporters=ErrorLog \
      --reporters=Deadlock1 \
      --validators=None \
      --mysqld=--log_output=none \
      --mysqld=--log_bin_trust_function_creators=1 \
      --mysqld=--loose-debug_assert_on_not_freed_memory=0 \
      --engine=InnoDB \
      --restart_timeout=240 \
      --mysqld=--plugin-load-add=file_key_management.so \
      --mysqld=--loose-file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
      --duration=300 \
      --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
      --mysqld=--loose-innodb-sync-debug \
      --mysqld=--innodb_stats_persistent=on \
      --mysqld=--innodb_adaptive_hash_index=on \
      --mysqld=--loose-innodb_evict_tables_on_commit_debug=off \
      --mysqld=--loose-max-statement-time=30 \
      --threads=33 \
      --mysqld=--innodb-use-native-aio=0 \
      --rr=Extended \
      --rr_options=--chaos --wait \
      --mysqld=--innodb_page_size=64K \
      --mysqld=--innodb-buffer-pool-size=24M \
      --no_mask \
      --workdir=<local settings> \
      --vardir=<local settings> \
      --mtr-build-thread=<local settings> \
      --basedir1=<local settings> \
      --script_debug=_nix_
      

      sdp:/data/Results/1629713923/TBR-1163/dev/shm/vardir/1629713923/217/1/rr

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              marko Marko Mäkelä
              Reporter:
              mleich Matthias Leich
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

                Dates

                Created:
                Updated:

                  Git Integration