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

safe_mutex: Trying to lock mutex ... fil0fil.cc ... when the mutex was already locked log0recv.cc

    XMLWordPrintable

    Details

      Description

      Scenario:
      1. Start the server and generate some initial data
      2. Two sessions run their usual DDL/DML battle
      3. SIGKILL server during 2. is ongoing
      4. Restart attempt which fails with
      [rr 1831586 9423]safe_mutex: Trying to lock mutex at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/fil/fil0fil.cc, line 1924, when the mutex was already locked at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/log/log0recv.cc, line 3701 in thread T@1
       
      (rr) bt
      #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
      #1  0x00007fe806534859 in __GI_abort () at abort.c:79
      #2  0x00005625690e81f0 in safe_mutex_lock (mp=mp@entry=0x56256b063300 <fil_system+32>, my_flags=my_flags@entry=0, file=file@entry=0x562569ae9be0 "/data/Server/bb-10.6-monty-innodb_C/storage/innobase/fil/fil0fil.cc", line=line@entry=1924)
          at /data/Server/bb-10.6-monty-innodb_C/mysys/thr_mutex.c:262
      #3  0x0000562568e36168 in inline_mysql_mutex_lock (src_line=1924, src_file=0x562569ae9be0 "/data/Server/bb-10.6-monty-innodb_C/storage/innobase/fil/fil0fil.cc", that=0x56256b063300 <fil_system+32>)
          at /data/Server/bb-10.6-monty-innodb_C/include/mysql/psi/mysql_thread.h:750
      #4  fil_rename_tablespace (id=225, old_path=0x6020000004f0 "./test/t2.ibd", new_path_in=0x603000005a40 "./test/#sql-ib251.ibd") at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/fil/fil0fil.cc:1924
      #5  0x0000562568e3a0d5 in fil_space_t::rename (this=this@entry=0x6120000016c0, path=path@entry=0x603000005a40 "./test/#sql-ib251.ibd", log=log@entry=false, replace=replace@entry=false)
          at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/fil/fil0fil.cc:1904
      #6  0x00005625687b686f in recv_rename_files () at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/log/log0recv.cc:3730
      #7  0x00005625687e07f4 in recv_recovery_from_checkpoint_start (flush_lsn=<optimized out>) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/log/log0recv.cc:4049
      #8  0x0000562568ae209a in srv_start (create_new_db=<optimized out>) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/srv/srv0start.cc:1425
      #9  0x00005625685e9d47 in innodb_init (p=<optimized out>) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/handler/ha_innodb.cc:3824
      #10 0x0000562567ba6ba3 in ha_initialize_handlerton (plugin=0x621000030810) at /data/Server/bb-10.6-monty-innodb_C/sql/handler.cc:660
      #11 0x000056256739c624 in plugin_initialize (tmp_root=tmp_root@entry=0x7ffe145d5600, plugin=plugin@entry=0x621000030810, argc=argc@entry=0x56256a7b3620 <remaining_argc>, argv=argv@entry=0x615000001278, options_only=<optimized out>)
          at /data/Server/bb-10.6-monty-innodb_C/sql/sql_plugin.cc:1463
      #12 0x000056256739f7a3 in plugin_init (argc=argc@entry=0x56256a7b3620 <remaining_argc>, argv=<optimized out>, flags=0) at /data/Server/bb-10.6-monty-innodb_C/sql/sql_plugin.cc:1756
      #13 0x000056256707c4bb in init_server_components () at /data/Server/bb-10.6-monty-innodb_C/sql/mysqld.cc:5041
      #14 0x0000562567085642 in mysqld_main (argc=47, argv=<optimized out>) at /data/Server/bb-10.6-monty-innodb_C/sql/mysqld.cc:5649
      #15 0x000056256706cf06 in main (argc=<optimized out>, argv=<optimized out>) at /data/Server/bb-10.6-monty-innodb_C/sql/main.cc:34
      (rr)
      sdp:/data/Results/1620824721/TBR-1082/dev/shm/vardir/1620824721/133/1/rr
      _RR_TRACE_DIR="." rr replay --mark-stdio mysqld-0   # Fate of the server till SIGKILL
      _RR_TRACE_DIR="." rr replay --mark-stdio mysqld-1   # Fate of the server during restart
       
      GIT_SHOW: HEAD, origin/bb-10.6-monty-innodb 98ff3177096311914ce10d72df04ad3b7106d0be 2021-05-12T15:11:07+03:00
       
      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=--innodb-encrypt-log \
      --mysqld=--innodb-encrypt-tables \
      --reporters=CrashRecovery1 \
      --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 \
      --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=/home/mleich/RQG_O/conf/mariadb/encryption_keys.txt \
      --duration=100 \
      --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=600 \
      --mysqld=--loose-innodb-sync-debug \
      --mysqld=--innodb_stats_persistent=on \
      --mysqld=--innodb_adaptive_hash_index=off \
      --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=--wait \
      --mysqld=--innodb_page_size=64K \
      --mysqld=--innodb-buffer-pool-size=24M \
      --duration=300 \
      --no_mask \
      --workdir=<local settings> \
      --vardir=<local settings> \
      --mtr-build-thread=<local settings> \
      --basedir1=<local settings> \
      --script_debug=_nix_
       
      Error pattern for RQG
      [ 'TBR-1082', 'INFO: Reporter \'CrashRecovery1\': Attempting database recovery using the server.+\[Note\] InnoDB: Starting crash recovery from checkpoint LSN.+safe_mutex: Trying to lock mutex at .{1,200}fil0fil.cc, line .{1,6}, when the mutex was already locked at .{1,200}log0recv.cc.+RESULT: The RQG run ended with status STATUS_RECOVERY_FAILURE' ],
      
      

        Attachments

          Issue Links

            Activity

              People

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

                Dates

                Created:
                Updated:
                Resolved:

                  Git Integration