ib_databases_file and ib_databases tests are unstable
General
Escalation
General
Escalation
Description
Tests ib_databases_file and ib_databases tests are unstable.
Those tests need the table to be present on disk in order to not copy them. If the table has not been checkpointed yet, --prepare phase will create the table even though it has to be excluded via --database filter.
2020-11-11 14:46:59: run.sh: ===> /work/pxb/ins/8.0/xtrabackup-test/test/server/bin/mysql --defaults-file=/work/pxb/ins/8.0/xtrabackup-test/test/var/w4/var1/my.cnf -e USE test1; SELECT * FROM a;
2020-11-11 14:46:59: run.sh: ===> mysql succeeded when it was expected to fail
The issue here is that the test relies on innodb_wait_for_flush_all to wait for all dirty pages to be flushed to disk. However, it seems that doesn't mean MySQL will update checkpoint pointers:
2020-11-11 14:46:44: run.sh: ===> /work/pxb/ins/8.0/xtrabackup-test/test/server/bin/mysql --defaults-file=/work/pxb/ins/8.0/xtrabackup-test/test/var/w4/var1/my.cnf
Dirty pages left 319
Dirty pages left 306
Dirty pages left 293
Dirty pages left 93
Dirty pages left 0
2020-11-11 14:46:48: run.sh: ===> /work/pxb/ins/8.0/xtrabackup-test/test/server/bin/mysql --defaults-file=/work/pxb/ins/8.0/xtrabackup-test/test/var/w4/var1/my.cnf -e SHOW ENGINE INNODB STATUS\G
*************************** 1. row ***************************
. . .
---
LOG
---
Log sequence number 18027176
Log buffer assigned up to 18027176
Log buffer completed up to 18027176
Log written up to 18027176
Log flushed up to 18027176
Added dirty pages up to 18027176
Pages flushed up to 17588921
Last checkpoint at 17588921
158 log i/o's done, 26.00 log i/o's/second
. . .
2020-11-11 14:46:48: run.sh: ===> /work/pxb/ins/8.0/xtrabackup-test/test/../../bin/xtrabackup --defaults-file=/work/pxb/ins/8.0/xtrabackup-test/test/var/w4/var1/my.cnf --no-version-check --backup --databases-file=/work/pxb/ins/8.0/xtrabackup-test/test/var/w4/var1/databases_file --target-dir=/work/pxb/ins/8.0/xtrabackup-test/test/var/w4/var1/backup
...
Starting to parse redo log at lsn = 17588754
xtrabackup: Redo Log Archiving is not set up.
201111 14:46:48 >> log scanned up to (18027176)
Problem: innodb_wait_for_flush_all relies on Innodb_buffer_pool_pages_dirty status to report all dirty pages have been flushed. When using such a function on xtrabackup testing, one expects the backup to not parse redo log entries from before that point. However, the status might report zero dirty pages, but checkpoint has not yet been performed, causing xtrabackup to start parsing undesired entries from redolog.
Fix: Added extra check to make sure checkpoint has been performed.
Tests ib_databases_file and ib_databases tests are unstable.
Those tests need the table to be present on disk in order to not copy them. If the table has not been checkpointed yet, --prepare phase will create the table even though it has to be excluded via --database filter.
2020-11-11 14:46:59: run.sh: ===> /work/pxb/ins/8.0/xtrabackup-test/test/server/bin/mysql --defaults-file=/work/pxb/ins/8.0/xtrabackup-test/test/var/w4/var1/my.cnf -e USE test1; SELECT * FROM a; 2020-11-11 14:46:59: run.sh: ===> mysql succeeded when it was expected to failThe issue here is that the test relies on innodb_wait_for_flush_all to wait for all dirty pages to be flushed to disk. However, it seems that doesn't mean MySQL will update checkpoint pointers:
2020-11-11 14:46:44: run.sh: ===> /work/pxb/ins/8.0/xtrabackup-test/test/server/bin/mysql --defaults-file=/work/pxb/ins/8.0/xtrabackup-test/test/var/w4/var1/my.cnf Dirty pages left 319 Dirty pages left 306 Dirty pages left 293 Dirty pages left 93 Dirty pages left 0 2020-11-11 14:46:48: run.sh: ===> /work/pxb/ins/8.0/xtrabackup-test/test/server/bin/mysql --defaults-file=/work/pxb/ins/8.0/xtrabackup-test/test/var/w4/var1/my.cnf -e SHOW ENGINE INNODB STATUS\G *************************** 1. row *************************** . . . --- LOG --- Log sequence number 18027176 Log buffer assigned up to 18027176 Log buffer completed up to 18027176 Log written up to 18027176 Log flushed up to 18027176 Added dirty pages up to 18027176 Pages flushed up to 17588921 Last checkpoint at 17588921 158 log i/o's done, 26.00 log i/o's/second . . . 2020-11-11 14:46:48: run.sh: ===> /work/pxb/ins/8.0/xtrabackup-test/test/../../bin/xtrabackup --defaults-file=/work/pxb/ins/8.0/xtrabackup-test/test/var/w4/var1/my.cnf --no-version-check --backup --databases-file=/work/pxb/ins/8.0/xtrabackup-test/test/var/w4/var1/databases_file --target-dir=/work/pxb/ins/8.0/xtrabackup-test/test/var/w4/var1/backup ... Starting to parse redo log at lsn = 17588754 xtrabackup: Redo Log Archiving is not set up. 201111 14:46:48 >> log scanned up to (18027176)