Details
-
Bug
-
Status: Confirmed (View Workflow)
-
Major
-
Resolution: Unresolved
-
10.11, 11.4, 11.8, 12.3, 13.1, 13.2, 13.0.2
-
None
Description
Description:
ha_partition::create_handler_file() writes the .par file of a partitioned
table (CREATE TABLE ... PARTITION BY, and every ALTER that changes the
partitioning, where it is written as #sql-shadow-N-<t>.par and renamed over
<t>.par) with create(O_TRUNC) + write + close, and never syncs it. The .frm
is synced (sync_frm, writefile()), the directory is synced, the InnoDB
tablespaces are protected by the redo log, but the 32-byte .par stays in the
page cache until the kernel writes it back (up to vm.dirty_expire_centisecs,
30 s by default). A power loss or kernel crash in that window leaves a 0-byte
.par file (ext4 delayed allocation: the name and the inode are journalled with
the directory sync, the data block is not), and the table cannot be opened:
ERROR 1696 (HY000): Failed to read from the .par file
SELECT, SHOW CREATE TABLE, CHECK TABLE all fail; nothing repairs it on
startup. For ALTER TABLE ... ADD PARTITION this also destroys a table whose
contents were durable long before: the old, synced .par is replaced by the
unsynced new one through rename, so all rows of the table become unreadable
(in the test: 1000 rows committed and durable before the ALTER).
strace of the statements: 0 fsync/fdatasync calls on any .par file (2 on .frm
files), e.g.
openat(AT_FDCWD, "./test/tp.par", O_RDWR|O_CREAT|O_TRUNC|O_CLOEXEC, 0660) = 55
write(55</var/lib/mysql/test/tp.par>, "\10\0\0\0MLON\4\0\0\0\f\f\f\f\f\0\0\0p0\0p1\0p2\0p3\0", 32) = 32
(close; no fsync)
openat(AT_FDCWD, "./test/#sql-shadow-6-tq.par", O_RDWR|O_CREAT|O_TRUNC|O_CLOEXEC, 0660) = 60
write(60</var/lib/mysql/test/#sql-shadow-6-tq.par>, "\10\0\0\0MLON..."..., 32) = 32
rename("./test/#sql-shadow-6-tq.par", "./test/tq.par") = 0
How to repeat (as root; ext4 on a dm-linear device over a loop file):
truncate -s 3G /dev/shm/pcut.img; LOOP=$(losetup -f --show /dev/shm/pcut.img)
dmsetup create pcut --table "0 $((3*1024*2048)) linear $LOOP 0"
mkfs.ext4 -q /dev/mapper/pcut; mkdir -p /mnt/pcut
mount -o noatime,commit=3600 /dev/mapper/pcut /mnt/pcut # commit=3600: no periodic journal commit
docker run -d --name m005 --network host -v /mnt/pcut:/var/lib/mysql -e MARIADB_ALLOW_EMPTY_ROOT_PASSWORD=1 \
-e MARIADB_DATABASE=test quay.io/mariadb-foundation/mariadb-devel:verylatest --port=3312
- (wait until the server is ready)
q() { docker exec m005 mariadb -uroot test -e "$*"; }q "CREATE TABLE tq (id INT PRIMARY KEY, v VARCHAR(100)) PARTITION BY HASH(id) PARTITIONS 2;
INSERT INTO tq SELECT seq, REPEAT('q',100) FROM seq_1_to_1000;"
sync -f /mnt/pcut; sleep 1 # everything up to here is durable
q "CREATE TABLE tp (id INT PRIMARY KEY, k INT, v VARCHAR(100)) PARTITION BY HASH(id) PARTITIONS 4;
INSERT INTO tp SELECT seq, seq, REPEAT('p',100) FROM seq_1_to_1000;
ALTER TABLE tq ADD PARTITION PARTITIONS 2;
INSERT INTO tq SELECT seq, 'after alter' FROM seq_1001_to_1010;" # all acknowledged
sleep 2
ls -l /mnt/pcut/test/ | grep -E "\.par|\.frm" # before the cut - power cut: fail all further I/O without flushing, then kill the server
dmsetup suspend --noflush --nolockfs pcut; dmsetup load pcut --table "0 $((3*1024*2048)) error"; dmsetup resume pcut
docker kill -s KILL m005
umount -l /mnt/pcut; dmsetup remove pcut; losetup -d $LOOP
LOOP=$(losetup -f --show /dev/shm/pcut.img); mount -o noatime $LOOP /mnt/pcut # "reboot"
ls -l /mnt/pcut/test/ | grep -E "\.par|\.frm"
docker start m005 - (wait until the server is ready)
q "SELECT count
FROM tp"; q "SELECT count
FROM tq"; q "CHECK TABLE tq"
Result (identical on 13.2 main and 13.0.2):
files before the cut: tp.par 32 bytes, tq.par 32 bytes
files after the cut: tp.frm 1418, tp.par 0, tp#P#p0..p3.ibd present
tq.frm 1395, tq.par 0, tq#P#p0..p3.ibd present
SELECT count
FROM tp -> ERROR 1696 (HY000): Failed to read from the .par file
SELECT count
FROM tq -> ERROR 1696 (HY000): Failed to read from the .par file
CHECK TABLE tq -> Error: Failed to read from the .par file / error: Corrupt
SHOW CREATE TABLE tq -> ERROR 1696
Expected: a partitioned table whose DDL and rows were acknowledged survives a
power loss like a non-partitioned one. The .par file should be synced before
it is closed (under the same sync_frm switch as the .frm), and the shadow .par
synced before it is renamed into place.
Cause:
https://github.com/MariaDB/server/blob/327437ade1d6dc6e4e57a6f1723b4abe4ac6c4b4/sql/ha_partition.cc#L2961-L2970
(create, write, close; no mysql_file_sync), compared with the .frm:
https://github.com/MariaDB/server/blob/327437ade1d6dc6e4e57a6f1723b4abe4ac6c4b4/sql/discover.cc#L142-L144
The ALTER path renames the unsynced shadow .par over the old one in
mysql_write_frm(WFRM_INSTALL_SHADOW):
https://github.com/MariaDB/server/blob/327437ade1d6dc6e4e57a6f1723b4abe4ac6c4b4/sql/sql_table.cc#L1083-L1091
Related: MDEV-29558 (1696 "Failed to read from the .par file" after kill -9 in
a DDL/DML workload, open), MDEV-39181 (DDL_LOG error 1696 at crash recovery,
draft), MDEV-27180 (fully atomic partitioning DDL, in review). Those are about
the atomicity of partitioning DDL under a process kill; this one is about the
missing fsync, and also hits CREATE TABLE and tables whose DDL completed
seconds before the crash.
Attachments
Issue Links
- relates to
-
MDEV-27180 Fully atomic partitioning DDL operations
-
- In Review
-
-
MDEV-29558 Crash recovery: SHOW KEYS .. harvests 1696: Failed to read from the .par file
-
- Open
-
-
MDEV-39181 [Draft] DDL_LOG: Got error 1696 when trying to execute action upon crash recovery
-
- Open
-