Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.11.2
Description
origin/bb-10.11-new-innodb-defaults be6a3d9a01c4357fbb52b4eefcb91bf84a8d0d4c 2022-12-09T13:51:55+02:00
|
Marko assumes that the trouble is linked to MDEV-29986.
|
|
Scenario:
|
1. The server is under concurrent DDL/DML load.
|
2. During 1. is ongoing runs a mariabackup --backup to some other directory.
|
|
Snip of the error log:
|
```# 2022-12-09T03:58:05 [234171] | [rr 332149 3776][00] 2022-12-09 03:58:04 >> log scanned up to (315140211)
|
# 2022-12-09T03:58:05 [234171] | [rr 332149 3801][00] 2022-12-09 03:58:05 >> log scanned up to (315141264)
|
# 2022-12-09T03:58:05 [234171] | [rr 332149 3808]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying.
|
# 2022-12-09T03:58:05 [234171] | [rr 332149 3814]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying.
|
# 2022-12-09T03:58:05 [234171] | [rr 332149 3820]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying.
|
# 2022-12-09T03:58:05 [234171] | [rr 332149 3826]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying.
|
# 2022-12-09T03:58:05 [234171] | [rr 332149 3832]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying.
|
# 2022-12-09T03:58:05 [234171] | [rr 332149 3838]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying.
|
# 2022-12-09T03:58:05 [234171] | [rr 332149 3846]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying.
|
# 2022-12-09T03:58:05 [234171] | [rr 332149 3856]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying.
|
# 2022-12-09T03:58:05 [234171] | [rr 332149 3864][00] 2022-12-09 03:58:05 >> log scanned up to (315165453)
|
# 2022-12-09T03:58:05 [234171] | [rr 332149 3871]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying.
|
# 2022-12-09T03:58:05 [234171] | [rr 332149 3877]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying.
|
# 2022-12-09T03:58:05 [234171] | [rr 332149 3881]2022-12-09 3:58:05 0 [Warning] InnoDB: Retry attempts for reading partial data failed.
|
# 2022-12-09T03:58:05 [234171] | [rr 332149 3890][01] 2022-12-09 03:58:05 mariabackup: xtrabackup_copy_datafile() failed.
|
# 2022-12-09T03:58:05 [234171] | [rr 332149 3898][00] FATAL ERROR: 2022-12-09 03:58:05 failed to copy datafile.```
|
Hitting this bug is very rare.
RQG:
===
- git clone https://github.com/mleich1/rqg --branch <pick the right branch> RQG
# - GIT_SHOW: HEAD -> master, origin/master, origin/HEAD 1abbb033ff1d798d9d0a9bacdf072fe8fd4f5deb 2022-12-09T12:56:59+01:00
- rqg.pl : Version 4.2.1 (2022-12)
# - $RQG_HOME/rqg.pl \
- --grammar=conf/engines/many_indexes.yy \
- --gendata=conf/engines/many_indexes.zz \
- --reporters=Mariabackup_linux \
- --redefine=conf/mariadb/redefine_file_buffering_write_through.yy \
- -
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=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 \ - --duration=300 \
- -
mysqld=-loose-innodb_fatal_semaphore_wait_threshold=300 \ - -
mysqld=-innodb_file_per_table=0 \ - -
mysqld=-loose-innodb_read_only_compressed=OFF \ - -
mysqld=-innodb_stats_persistent=on \ - -
mysqld=-innodb_adaptive_hash_index=off \ - -
mysqld=-log-bin \ - -
mysqld=-sync-binlog=1 \ - -
mysqld=-loose-innodb_evict_tables_on_commit_debug=on \ - -
mysqld=-loose-max-statement-time=30 \ - --threads=33 \
- -
mysqld=-innodb_use_native_aio=1 \ - -
mysqld=-loose_innodb_change_buffering=changes \ - -
mysqld=-innodb_rollback_on_timeout=OFF \ - -
mysqld=-innodb_page_size=16K \ - -
mysqld=-innodb-buffer-pool-size=8M \ - --vardir_type=slow \
- <local settings>
sdp:/data/results/1670586562/Backup$ _RR_TRACE_DIR=./1_clone/rr rr replay --mark-stdio
Attachments
Issue Links
- relates to
-
MDEV-29986 Set innodb_undo_tablespaces=3 by default
-
- Closed
-
Activity
Field | Original Value | New Value |
---|---|---|
Link |
This issue relates to |
Assignee | Matthias Leich [ mleich ] | Thirunarayanan Balathandayuthapani [ thiru ] |
Description |
{noformat} origin/bb-10.11-new-innodb-defaults be6a3d9a01c4357fbb52b4eefcb91bf84a8d0d4c 2022-12-09T13:51:55+02:00 Marko assumes that the trouble is linked to Scenario: 1. The server is under concurrent DDL/DML load. 2. During 1. is ongoing runs a mariabackup --backup to some other directory. Snip of the error log: ```# 2022-12-09T03:58:05 [234171] | [rr 332149 3776][00] 2022-12-09 03:58:04 >> log scanned up to (315140211) # 2022-12-09T03:58:05 [234171] | [rr 332149 3801][00] 2022-12-09 03:58:05 >> log scanned up to (315141264) # 2022-12-09T03:58:05 [234171] | [rr 332149 3808]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3814]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3820]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3826]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3832]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3838]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3846]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3856]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3864][00] 2022-12-09 03:58:05 >> log scanned up to (315165453) # 2022-12-09T03:58:05 [234171] | [rr 332149 3871]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3877]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3881]2022-12-09 3:58:05 0 [Warning] InnoDB: Retry attempts for reading partial data failed. # 2022-12-09T03:58:05 [234171] | [rr 332149 3890][01] 2022-12-09 03:58:05 mariabackup: xtrabackup_copy_datafile() failed. # 2022-12-09T03:58:05 [234171] | [rr 332149 3898][00] FATAL ERROR: 2022-12-09 03:58:05 failed to copy datafile.``` {noformat} Hitting this bug is very rare. RQG: === # git clone https://github.com/mleich1/rqg --branch <pick the right branch> RQG # # GIT_SHOW: HEAD -> master, origin/master, origin/HEAD 1abbb033ff1d798d9d0a9bacdf072fe8fd4f5deb 2022-12-09T12:56:59+01:00 # rqg.pl : Version 4.2.1 (2022-12) # # $RQG_HOME/rqg.pl \ # --grammar=conf/engines/many_indexes.yy \ # --gendata=conf/engines/many_indexes.zz \ # --reporters=Mariabackup_linux \ # --redefine=conf/mariadb/redefine_file_buffering_write_through.yy \ # --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=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 \ # --duration=300 \ # --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \ # --mysqld=--innodb_file_per_table=0 \ # --mysqld=--loose-innodb_read_only_compressed=OFF \ # --mysqld=--innodb_stats_persistent=on \ # --mysqld=--innodb_adaptive_hash_index=off \ # --mysqld=--log-bin \ # --mysqld=--sync-binlog=1 \ # --mysqld=--loose-innodb_evict_tables_on_commit_debug=on \ # --mysqld=--loose-max-statement-time=30 \ # --threads=33 \ # --mysqld=--innodb_use_native_aio=1 \ # --mysqld=--loose_innodb_change_buffering=changes \ # --mysqld=--innodb_rollback_on_timeout=OFF \ # --mysqld=--innodb_page_size=16K \ # --mysqld=--innodb-buffer-pool-size=8M \ # --vardir_type=slow \ # <local settings> sdp:/data/results/1670586562/Backup$ _RR_TRACE_DIR=./1_clone/rr rr replay --mark-stdio |
{noformat}
origin/bb-10.11-new-innodb-defaults be6a3d9a01c4357fbb52b4eefcb91bf84a8d0d4c 2022-12-09T13:51:55+02:00 Marko assumes that the trouble is linked to Scenario: 1. The server is under concurrent DDL/DML load. 2. During 1. is ongoing runs a mariabackup --backup to some other directory. Snip of the error log: ```# 2022-12-09T03:58:05 [234171] | [rr 332149 3776][00] 2022-12-09 03:58:04 >> log scanned up to (315140211) # 2022-12-09T03:58:05 [234171] | [rr 332149 3801][00] 2022-12-09 03:58:05 >> log scanned up to (315141264) # 2022-12-09T03:58:05 [234171] | [rr 332149 3808]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3814]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3820]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3826]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3832]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3838]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3846]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3856]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3864][00] 2022-12-09 03:58:05 >> log scanned up to (315165453) # 2022-12-09T03:58:05 [234171] | [rr 332149 3871]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3877]2022-12-09 3:58:05 0 [Warning] InnoDB: 6291456 bytes should have been read at 10485760 from (unknown file), but got only 0. Retrying. # 2022-12-09T03:58:05 [234171] | [rr 332149 3881]2022-12-09 3:58:05 0 [Warning] InnoDB: Retry attempts for reading partial data failed. # 2022-12-09T03:58:05 [234171] | [rr 332149 3890][01] 2022-12-09 03:58:05 mariabackup: xtrabackup_copy_datafile() failed. # 2022-12-09T03:58:05 [234171] | [rr 332149 3898][00] FATAL ERROR: 2022-12-09 03:58:05 failed to copy datafile.``` {noformat} Hitting this bug is very rare. RQG: === # git clone https://github.com/mleich1/rqg --branch <pick the right branch> RQG # # GIT_SHOW: HEAD -> master, origin/master, origin/HEAD 1abbb033ff1d798d9d0a9bacdf072fe8fd4f5deb 2022-12-09T12:56:59+01:00 # rqg.pl : Version 4.2.1 (2022-12) # # $RQG_HOME/rqg.pl \ # --grammar=conf/engines/many_indexes.yy \ # --gendata=conf/engines/many_indexes.zz \ # --reporters=Mariabackup_linux \ # --redefine=conf/mariadb/redefine_file_buffering_write_through.yy \ # --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=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 \ # --duration=300 \ # --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \ # --mysqld=--innodb_file_per_table=0 \ # --mysqld=--loose-innodb_read_only_compressed=OFF \ # --mysqld=--innodb_stats_persistent=on \ # --mysqld=--innodb_adaptive_hash_index=off \ # --mysqld=--log-bin \ # --mysqld=--sync-binlog=1 \ # --mysqld=--loose-innodb_evict_tables_on_commit_debug=on \ # --mysqld=--loose-max-statement-time=30 \ # --threads=33 \ # --mysqld=--innodb_use_native_aio=1 \ # --mysqld=--loose_innodb_change_buffering=changes \ # --mysqld=--innodb_rollback_on_timeout=OFF \ # --mysqld=--innodb_page_size=16K \ # --mysqld=--innodb-buffer-pool-size=8M \ # --vardir_type=slow \ # <local settings> sdp:/data/results/1670586562/Backup$ _RR_TRACE_DIR=./1_clone/rr rr replay --mark-stdio |
Status | Open [ 1 ] | In Progress [ 3 ] |
Assignee | Thirunarayanan Balathandayuthapani [ thiru ] | Marko Mäkelä [ marko ] |
Status | In Progress [ 3 ] | In Review [ 10002 ] |
Assignee | Marko Mäkelä [ marko ] | Thirunarayanan Balathandayuthapani [ thiru ] |
Status | In Review [ 10002 ] | Stalled [ 10000 ] |
Assignee | Thirunarayanan Balathandayuthapani [ thiru ] | Marko Mäkelä [ marko ] |
Status | Stalled [ 10000 ] | In Review [ 10002 ] |
Assignee | Marko Mäkelä [ marko ] | Thirunarayanan Balathandayuthapani [ thiru ] |
Status | In Review [ 10002 ] | Stalled [ 10000 ] |
Status | Stalled [ 10000 ] | In Progress [ 3 ] |
Fix Version/s | 10.5.20 [ 28512 ] | |
Fix Version/s | 10.6.13 [ 28514 ] | |
Fix Version/s | 10.7.9 [ 28516 ] | |
Fix Version/s | 10.8.8 [ 28518 ] | |
Fix Version/s | 10.9.6 [ 28520 ] | |
Fix Version/s | 10.10.4 [ 28522 ] | |
Fix Version/s | 10.11.3 [ 28524 ] | |
Fix Version/s | 10.11 [ 27614 ] | |
Resolution | Fixed [ 1 ] | |
Status | In Progress [ 3 ] | Closed [ 6 ] |
Fix Version/s | 10.7.9 [ 28516 ] |
Fix Version/s | 10.10.3 [ 28521 ] | |
Fix Version/s | 10.9.5 [ 28519 ] | |
Fix Version/s | 10.8.7 [ 28517 ] | |
Fix Version/s | 10.7.8 [ 28515 ] | |
Fix Version/s | 10.6.12 [ 28513 ] | |
Fix Version/s | 10.5.19 [ 28511 ] | |
Fix Version/s | 11.0.1 [ 28548 ] | |
Fix Version/s | 10.11.2 [ 28523 ] | |
Fix Version/s | 10.5.20 [ 28512 ] | |
Fix Version/s | 10.6.13 [ 28514 ] | |
Fix Version/s | 10.8.8 [ 28518 ] | |
Fix Version/s | 10.9.6 [ 28520 ] | |
Fix Version/s | 10.10.4 [ 28522 ] | |
Fix Version/s | 10.11.3 [ 28524 ] |
I see two problems here. First, the error message fails to mention the file name (undo002) even though it would be readily available a couple stack frames earlier.
Second, it may be that mariadb-backup assumes that files will not shrink while they are being copied, that is, it is not compatible with innodb_undo_log_truncate=ON.