XtraBackup Causes xtrabackup_logfile Size to Increase on every failed Prepare Attempt

[Jervin R]

While applying an incremental backup with where a page was detected as corrupt, every attempt to apply the same incremental set increases its xtrabackup_logfile size:

[root@xxxxxxxxxx /shared/backup_20131221_bad2/prepare_logs] # for f in $(cat t); do echo $f; cat $f|grep 'xtrabackup_logfile detected'; done
./log_20131226_030114_prepare.log
xtrabackup: xtrabackup_logfile detected: size=246153216, start_lsn=(12726759490889)
./log_20131226_030345_prepare.log
xtrabackup: xtrabackup_logfile detected: size=276922368, start_lsn=(12726759490889)
./log_20131226_030459_prepare.log
xtrabackup: xtrabackup_logfile detected: size=311525376, start_lsn=(12726759490889)
./log_20131226_030610_prepare.log
xtrabackup: xtrabackup_logfile detected: size=350453760, start_lsn=(12726759490889)
./log_20131226_030715_prepare.log
xtrabackup: xtrabackup_logfile detected: size=394248192, start_lsn=(12726759490889)
./log_20131226_030823_prepare.log
xtrabackup: xtrabackup_logfile detected: size=443514880, start_lsn=(12726759490889)
./log_20131226_030928_prepare.log
xtrabackup: xtrabackup_logfile detected: size=498941952, start_lsn=(12726759490889)
./log_20131226_031036_prepare.log
xtrabackup: xtrabackup_logfile detected: size=561299456, start_lsn=(12726759490889)
./log_20131226_031146_prepare.log
xtrabackup: xtrabackup_logfile detected: size=631455744, start_lsn=(12726759490889)
./log_20131226_031256_prepare.log
xtrabackup: xtrabackup_logfile detected: size=710377472, start_lsn=(12726759490889)
./log_20131226_031402_prepare.log
xtrabackup: xtrabackup_logfile detected: size=799162368, start_lsn=(12726759490889)
./log_20131226_032003_prepare.log
xtrabackup: xtrabackup_logfile detected: size=899055616, start_lsn=(12726759490889)
./log_20131226_032135_prepare.log
xtrabackup: xtrabackup_logfile detected: size=1011433472, start_lsn=(12726759490889)
./log_20131226_032230_prepare.log
xtrabackup: xtrabackup_logfile detected: size=1137852416, start_lsn=(12726759490889)
./log_20131226_032326_prepare.log
xtrabackup: xtrabackup_logfile detected: size=1280081920, start_lsn=(12726759490889)
./log_20131226_032421_prepare.log
xtrabackup: xtrabackup_logfile detected: size=1440088064, start_lsn=(12726759490889)
./log_20131226_032515_prepare.log
xtrabackup: xtrabackup_logfile detected: size=1620099072, start_lsn=(12726759490889)
./log_20131226_032612_prepare.log
xtrabackup: xtrabackup_logfile detected: size=1822605312, start_lsn=(12726759490889)
./log_20131226_032706_prepare.log
xtrabackup: xtrabackup_logfile detected: size=2050424832, start_lsn=(12726759490889)
./log_20131226_032801_prepare.log
xtrabackup: xtrabackup_logfile detected: size=2306719744, start_lsn=(12726759490889)
./log_20131226_033237_prepare.log
xtrabackup: xtrabackup_logfile detected: size=2595045376, start_lsn=(12726759490889)
./log_20131226_033333_prepare.log
xtrabackup: xtrabackup_logfile detected: size=2919415808, start_lsn=(12726759490889)
./log_20131226_033428_prepare.log
xtrabackup: xtrabackup_logfile detected: size=3284336640, start_lsn=(12726759490889)
./log_20131226_033526_prepare.log
xtrabackup: xtrabackup_logfile detected: size=3694870528, start_lsn=(12726759490889)
./log_20131226_033622_prepare.log
xtrabackup: xtrabackup_logfile detected: size=4156719104, start_lsn=(12726759490889)
./log_20131226_033721_prepare.log
xtrabackup: xtrabackup_logfile detected: size=4676304896, start_lsn=(12726759490889)
./log_20131226_033817_prepare.log
xtrabackup: xtrabackup_logfile detected: size=5260836864, start_lsn=(12726759490889)
./log_20131226_033916_prepare.log
xtrabackup: xtrabackup_logfile detected: size=5918441472, start_lsn=(12726759490889)
./log_20131226_034013_prepare.log
xtrabackup: xtrabackup_logfile detected: size=6658244608, start_lsn=(12726759490889)
./log_20131226_034703_prepare.log
xtrabackup: xtrabackup_logfile detected: size=7490519040, start_lsn=(12726759490889)
./log_20131226_034801_prepare.log
xtrabackup: xtrabackup_logfile detected: size=8426831872, start_lsn=(12726759490889)
./log_20131226_034901_prepare.log
xtrabackup: xtrabackup_logfile detected: size=9480175616, start_lsn=(12726759490889)
./log_20131226_035001_prepare.log
xtrabackup: xtrabackup_logfile detected: size=10665197568, start_lsn=(12726759490889)
./log_20131226_035103_prepare.log
xtrabackup: xtrabackup_logfile detected: size=11998347264, start_lsn=(12726759490889)
./log_20131226_035206_prepare.log
xtrabackup: xtrabackup_logfile detected: size=13498138624, start_lsn=(12726759490889)
./log_20131226_035308_prepare.log
xtrabackup: xtrabackup_logfile detected: size=15185395712, start_lsn=(12726759490889)
./log_20131226_035413_prepare.log
xtrabackup: xtrabackup_logfile detected: size=17083564032, start_lsn=(12726759490889)
./log_20131226_035523_prepare.log
xtrabackup: xtrabackup_logfile detected: size=19219005440, start_lsn=(12726759490889)
./log_20131226_040200_prepare.log
xtrabackup: xtrabackup_logfile detected: size=21621374976, start_lsn=(12726759490889)
./log_20131226_040343_prepare.log
xtrabackup: xtrabackup_logfile detected: size=24324046848, start_lsn=(12726759490889)
./log_20131226_040454_prepare.log
xtrabackup: xtrabackup_logfile detected: size=27364540416, start_lsn=(12726759490889)
./log_20131226_040606_prepare.log
xtrabackup: xtrabackup_logfile detected: size=30785093632, start_lsn=(12726759490889)
./log_20131226_040721_prepare.log
xtrabackup: xtrabackup_logfile detected: size=34633220096, start_lsn=(12726759490889)
./log_20131226_040838_prepare.log
xtrabackup: xtrabackup_logfile detected: size=38962364416, start_lsn=(12726759490889)
./log_20131226_040959_prepare.log
xtrabackup: xtrabackup_logfile detected: size=43832655872, start_lsn=(12726759490889)
./log_20131226_041127_prepare.log
xtrabackup: xtrabackup_logfile detected: size=49311727616, start_lsn=(12726759490889)
./log_20131226_041259_prepare.log
xtrabackup: xtrabackup_logfile detected: size=55475683328, start_lsn=(12726759490889)
./log_20131226_041430_prepare.log
xtrabackup: xtrabackup_logfile detected: size=62410129408, start_lsn=(12726759490889)
./log_20131226_041607_prepare.log
xtrabackup: xtrabackup_logfile detected: size=70211387392, start_lsn=(12726759490889)
./log_20131226_041748_prepare.log
xtrabackup: xtrabackup_logfile detected: size=78987804672, start_lsn=(12726759490889)
./log_20131226_041947_prepare.log
xtrabackup: xtrabackup_logfile detected: size=88861278208, start_lsn=(12726759490889)
./log_20131226_042135_prepare.log
xtrabackup: xtrabackup_logfile detected: size=99968925696, start_lsn=(12726759490889)
./log_20131226_042343_prepare.log
xtrabackup: xtrabackup_logfile detected: size=112465035264, start_lsn=(12726759490889)
./log_20131226_042548_prepare.log
xtrabackup: xtrabackup_logfile detected: size=126523162624, start_lsn=(12726759490889)
./log_20131226_042810_prepare.log
xtrabackup: xtrabackup_logfile detected: size=142338555904, start_lsn=(12726759490889)
./log_20131226_043043_prepare.log
xtrabackup: xtrabackup_logfile detected: size=160130875392, start_lsn=(12726759490889)
./log_20131226_043315_prepare.log
xtrabackup: xtrabackup_logfile detected: size=180147224576, start_lsn=(12726759490889)
./log_20131226_043600_prepare.log
xtrabackup: xtrabackup_logfile detected: size=202665623552, start_lsn=(12726759490889)
./log_20131226_043857_prepare.log
xtrabackup: xtrabackup_logfile detected: size=227998826496, start_lsn=(12726759490889)
./log_20131226_044206_prepare.log
xtrabackup: xtrabackup_logfile detected: size=256498679808, start_lsn=(12726759490889)
./log_20131226_044551_prepare.log
xtrabackup: xtrabackup_logfile detected: size=288561004544, start_lsn=(12726759490889)
./log_20131226_045007_prepare.log
xtrabackup: xtrabackup_logfile detected: size=324631117824, start_lsn=(12726759490889)
./log_20131226_045433_prepare.log
xtrabackup: xtrabackup_logfile detected: size=365209993216, start_lsn=(12726759490889)
./log_20131226_045916_prepare.log
xtrabackup: xtrabackup_logfile detected: size=410861240320, start_lsn=(12726759490889)
./log_20131226_050444_prepare.log
xtrabackup: xtrabackup_logfile detected: size=462218887168, start_lsn=(12726759490889)
./log_20131226_051041_prepare.log
xtrabackup: xtrabackup_logfile detected: size=519996243968, start_lsn=(12726759490889)
./log_20131226_051721_prepare.log
xtrabackup: xtrabackup_logfile detected: size=584995766272, start_lsn=(12726759490889)
./log_20131226_052823_prepare.log
xtrabackup: xtrabackup_logfile detected: size=658120228864, start_lsn=(12726759490889)
./log_20131226_054013_prepare.log
xtrabackup: xtrabackup_logfile detected: size=740385243136, start_lsn=(12726759490889)
./log_20131226_055211_prepare.log
xtrabackup: xtrabackup_logfile detected: size=832933396480, start_lsn=(12726759490889)
./log_20131226_060516_prepare.log
xtrabackup: xtrabackup_logfile detected: size=937050062848, start_lsn=(12726759490889)
./log_20131226_061852_prepare.log
xtrabackup: xtrabackup_logfile detected: size=1054181310464, start_lsn=(12726759490889)
./log_20131226_063527_prepare.log

The increase is not monotonic:

[root@xxxxxxxxxx /shared/backup_20131221_bad2/prepare_logs] # cat x|awk '{print $1-X; X=$1}'
246153216
30769152
34603008
38928384
43794432
49266688
55427072
62357504
70156288
78921728
88784896
99893248
112377856
126418944
142229504
160006144
180011008
202506240
227819520
256294912
288325632
324370432
364920832
410533888
461848576
519585792
584531968
657604608
739803136
832274432
936312832
1053343744
1185021952
1333149696
1499791360
1687257088
1898168320
2135441408
2402369536
2702671872
3040493568
3420553216
3848126464
4329144320
4870291456
5479071744
6163955712
6934446080
7801257984
8776417280
9873473536
11107647488
12496109568
14058127360
15815393280
17792319488
20016349184
22518398976
25333202944
28499853312
32062324736
36070113280
40578875392
45651247104
51357646848
57777356800
64999522304
73124462592
82265014272
92548153344
104116666368
117131247616

This leads to https://bugs.launchpad.net/percona-xtrabackup/+bug/1264412

[Jervin R (revin)]

OS is Solaris on Joyent, source of backup is Percona Server 5.6.14 custom built, XtraBackup 2.1.6. Sample log of one of the failed apply is available on internal issue #37934.

[Alexey Kopytov (akopytov)]

The size of xtrabackup_logfile is increased by 1/8 on prepare. Which is a heuristic constant to leave room for redo log writes generated by recovery (e.g. when merging change buffer entries). A better way to handle this would be to disable redo log writes on recovery.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXB-1008