[MDEV-32118] Warning Can't open table' upon CHECK TABLE t3 EXTENDED Created: 2023-09-07  Updated: 2024-01-29

Status: Open
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 11.3.0
Fix Version/s: 11.3

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Matthias Leich
Resolution: Unresolved Votes: 0
Labels: rr-profile-analyzed


 Description   

origin/11.3, 11.3 8ad1e26b1bafa4ed9928306efc10c047f2274108 2023-09-04T09:36:44+04:00
Scenario:
1. Start the server and generate some initial data
2. 33 sessions run concurrent some DDL/DML mix
    During that phase a CHECK TABLE t3 EXTENDED  /* E_R Thread5 QNO 156 CON_ID 16 */ ' 
    passed but has a result set line 'test.t3 check Warning Can't open table'
    RQG reacts with stopping the server.
    t3 is ENGINE = InnoDB ROW_FORMAT = Compact
    sdp:/data1/results/1694027773/TBR-2045$ _RR_TRACE_DIR=./1/rr rr replay --mark-stdio
 
RQG
===
# git clone https://github.com/mleich1/rqg --branch <pick the right branch> RQG
#
# GIT_SHOW: HEAD -> master, origin/master, origin/HEAD d24e1493fb180e50a6aa37006bfb613ef8e35861 2023-09-06T15:46:05+02:00
# rqg.pl  : Version 4.4.0 (2023-08)
#
# $RQG_HOME/rqg.pl \
# --gendata=conf/mariadb/table_stress.zz \
# --gendata_sql=conf/mariadb/table_stress.sql \
# --grammar=conf/mariadb/table_stress_innodb.yy \
# --mysqld=--transaction-isolation=REPEATABLE-READ \
# --validator=SelectStability \
# --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 \
# --no_mask \
# --queries=10000000 \
# --seed=random \
# --reporters=None \
# --reporters=ErrorLog \
# --reporters=Deadlock \
# --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 \
# --mysqld=--plugin-load-add=provider_lzo.so \
# --mysqld=--plugin-load-add=provider_bzip2.so \
# --mysqld=--plugin-load-add=provider_lzma.so \
# --mysqld=--plugin-load-add=provider_snappy.so \
# --mysqld=--plugin-load-add=provider_lz4.so \
# --mysqld=--loose-innodb_compression_level=1 \
# --duration=300 \
# --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
# --mysqld=--lock-wait-timeout=86400 \
# --mysqld=--innodb-lock-wait-timeout=50 \
# --mysqld=--loose-innodb_fast_shutdown=0 \
# --mysqld=--sql_mode=STRICT_TRANS_TABLES,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION \
# --mysqld=--innodb_file_per_table=1 \
# --mysqld=--loose-innodb_read_only_compressed=OFF \
# --mysqld=--innodb_stats_persistent=on \
# --mysqld=--innodb_adaptive_hash_index=on \
# --mysqld=--innodb_sort_buffer_size=65536 \
# --mysqld=--innodb_random_read_ahead=OFF \
# --mysqld=--loose-innodb_evict_tables_on_commit_debug=off \
# --mysqld=--loose-max-statement-time=30 \
# --threads=33 \
# --mysqld=--innodb-use-native-aio=0 \
# --mysqld=--loose-gdb \
# --mysqld=--loose-debug-gdb \
# --rr=Extended \
# --rr_options=--chaos --wait \
# --mysqld=--innodb_undo_log_truncate=OFF \
# --mysqld=--loose_innodb_change_buffering=all \
# --mysqld=--innodb_rollback_on_timeout=ON \
# --mysqld=--innodb_page_size=32K \
# --mysqld=--innodb-buffer-pool-size=256M \
# <local settings>



 Comments   
Comment by Marko Mäkelä [ 2023-12-19 ]

In the rr replay trace of the server, I do not see anything wrong. I have no idea why the RQG client thinks that the last executed statement CHECK TABLE t3 returned an error. I see that the following statement returned control to the thread pool:

CHECK TABLE t3 EXTENDED  /* E_R Thread27 QNO 172 CON_ID 41 */;

There was one more CHECK TABLE statement before the server received the SIGKILL:

CHECK TABLE t4 EXTENDED  /* E_R Thread4 QNO 179 CON_ID 18 */;

Also that statement completed well before the server was killed. There was no call to ha_innobase::open() at the end of the trace.

mleich, I think that this needs some more analysis on your side. Could it be some kind of a false alarm due to an error on the client side?

Comment by Matthias Leich [ 2024-01-24 ]

The problem was replayed

  • first time on origin/bb-11.3-MDEV-28699 57eddac4c85a0f63f4cb2e5d1f51fb82ca4c06f6 2023-08-24T23:20:26+05:30
  • last time on origin/bb-11.2-MDEV-32452 0ee7e9ebb5cfe7d3627c0b644012c83c5a63542d 2023-11-08T16:37:46+05:30

I will try to replay the problem and check my version of RQG.

Generated at Thu Feb 08 10:28:58 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.