innobackupex/xtrabackup_51 (1.6.5) filling ./ibdata1 until disk full
132 views
Skip to first unread message
W. Koot
Mar 22, 2012, 4:02:35 PM3/22/12
to Percona Discussion
I've recently upgraded xtrabackup from 1.6.4 to 1.6.5, because I was
having trouble applying incrementals.
To check the backups, I currently run a daily restore on an other
(similar) machine. Upon prepping this morning's backup, I got a
'corrupt log record' error followed by some strange behavior.
It appeared that for some reason ibdata1 was written until the disk
was full and innobackupex crashed:
# du -sh 2012-03-22_02-15-01/
719G 2012-03-22_02-15-01/
# ls -la 2012-03-22_02-15-01/ | grep ibdata1
-rw-r----- 1 root root 547919757312 Mar 22 18:05 ibdata1
In the corrupt record, there is notion of a table called "#sql-
b59a_a447df". This table is apparently listed in the InnoDB data
dictionary, but not to be found.
I suspect that the files were removed from the mysql folder, instead
of a proper drop table. I know for sure however that this table has
not existed the past month; whatever happened with it, happened a
while ago.
The backup script has always been noticing that the table doesn't
exist and therefor skipped, all .ibd files pass innochecksum though.
Only now this temporary table appears to be causing trouble?
I'm considering downgrading to xtrabackup version 1.6.4, which seemed
to do the backing up correctly (data in restored version ok). For
restoring I would need to continue using 1.6.5, so I'm wondering if
anyone can shed some light on this situation? :-)
Version stuff:
# xtrabackup -v
xtrabackup version 1.6.5 for Percona Server 5.1.59 unknown-linux-gnu
(x86_64) (revision id: 328)
# mysql -V
mysql Ver 14.14 Distrib 5.1.61, for unknown-linux-gnu (x86_64) using
readline 5.1
# cat /proc/version
Linux version 2.6.18-194.17.4.el5 (gcc version 4.1.2 20080704 (Red Hat
4.1.2-48))
Log of prepping the full:
# innobackupex --apply-log --ibbackup=xtrabackup_51 --redo-only /home/
backup/2012-03-22_02-15-01
InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase
Oy
and Percona Inc 2009-2012. All Rights Reserved.
This software is published under
the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.
IMPORTANT: Please check that the apply-log run completes successfully.
At the end of a successful apply-log run innobackupex
prints "completed OK!".
120322 17:29:21 innobackupex: Starting ibbackup with command:
xtrabackup_51 --prepare --target-dir=/home/backup/2012-03-22_02-15-01
--apply-log-only
xtrabackup: cd to /home/backup/2012-03-22_02-15-01
xtrabackup: This target seems to be not prepared yet.
120322 17:29:21 InnoDB: Operating system error number 2 in a file
operation.
InnoDB: The error means the system cannot find the path specified.
xtrabackup: Warning: cannot open ./xtrabackup_logfile. will try to
find.
xtrabackup: 'ib_logfile0' seems to be 'xtrabackup_logfile'. will
retry.
xtrabackup: Temporary instance for recovery is set as followings.
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 1462206464
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory
parameter)
InnoDB: The InnoDB memory heap is disabled
120322 17:29:21 InnoDB: Initializing buffer pool, size = 100.0M
120322 17:29:21 InnoDB: Completed initialization of buffer pool
InnoDB: Log scan progressed past the checkpoint lsn 1552 4005809231
120322 17:29:21 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Doing recovery: scanned up to log sequence number 1552
4011052032 (0 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4016294912 (0 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4021537792 (1 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4026780672 (1 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4032023552 (2 %)
120322 17:29:23 InnoDB: Starting an apply batch of log records to the
database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16
17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39
40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62
63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85
86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
[snip]
120322 17:30:06 InnoDB: Starting an apply batch of log records to the
database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16
17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39
40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62
63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85
86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 1552
4215524352 (16 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4220767232 (16 %)
InnoDB: ############### CORRUPT LOG RECORD FOUND
InnoDB: Log record type 47, space id 5032, page number 0
InnoDB: Log parsing proceeded successfully up to 1552 4225394403
InnoDB: Previous log record type 4, is multi 0
InnoDB: Recv offset 166502, prev 166495
InnoDB: Hex dump of corrupt log starting 100 bytes before the start
InnoDB: of the previous log rec,
InnoDB: and ending 100 bytes after the start of the corrupt rec:
len 207; hex
e6554be6ad482dc6622b6ddbed76e4aa1be072c26c001900018004800680078008ffffffffffffffff8004800480047fff800480048004800400047fff0004800480017fff8010801080082d5682003d002a811082003d003802880007002e00000013e8840007003e93a8af93a80000000021001d62757a7a636170747572652f2373716c2d623539615f613434376466001d93a8011b93a8011f1d93a8000293a8000018080493a800002693a80493a800002a000493a800002e040493a8000032000493a8000036210493a80000;
asc UK H- b+m v r
l -V = * =
8 . > ! db/#sql-
b59a_a447df & * . 2
6! ;
InnoDB: WARNING: the log file may have been corrupt and it
InnoDB: is possible that the log scan did not proceed
InnoDB: far enough in recovery! Please run CHECK TABLE
InnoDB: on your InnoDB tables to check that they are ok!
InnoDB: If mysqld crashes after this recovery, look at
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
InnoDB: Doing recovery: scanned up to log sequence number 1552
4226010112 (16 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4231252992 (17 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4236495872 (17 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4241738752 (18 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4246981632 (18 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4252224512 (18 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4257467392 (19 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4262710272 (19 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4267953152 (20 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4273196032 (20 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4278438912 (20 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4283681792 (21 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4288924672 (21 %)
[snip]
InnoDB: Doing recovery: scanned up to log sequence number 1553
866167654 (88 %)
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 2 row operations to undo
InnoDB: Trx id counter is 2 1084739072
120322 17:30:16 InnoDB: Error: table 'db/#sql-405d_44ee4'
InnoDB: in InnoDB data dictionary has tablespace id 7,
InnoDB: but tablespace with that id or name does not exist. It will be
removed from data dictionary.
120322 18:05:35 InnoDB: Error: Write to file ./ibdata1 failed at
offset 127 2458910720.
InnoDB: 1048576 bytes should have been written, only -1 were written.
InnoDB: Operating system error number 28.
InnoDB: Check that your OS and file system support files of this size.
InnoDB: Check also that the disk is not full or a disk quota exceeded.
InnoDB: Error number 28 means 'No space left on device'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/operating-system-error-codes.html
InnoDB: Error: trying to access page number 1298932917 in space 0,
InnoDB: space name ./ibdata1,
InnoDB: which is outside the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check that
InnoDB: your my.cnf matches the ibdata files that you have in the
InnoDB: MySQL server.
120322 18:05:35 InnoDB: Assertion failure in thread 47967927478528 in
file fil/fil0fil.c line 4328
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
xtrabackup_51 version 1.6.5 for MySQL server 5.1.59 unknown-linux-gnu
(x86_64) (revision id: 328)
xtrabackup: xtrabackup_logfile detected: size=1462206464,
start_lsn=(1552 4005809231)
innobackupex: Error:
innobackupex: ibbackup failed at /usr/bin/innobackupex line 349.
having trouble applying incrementals.
To check the backups, I currently run a daily restore on an other
(similar) machine. Upon prepping this morning's backup, I got a
'corrupt log record' error followed by some strange behavior.
It appeared that for some reason ibdata1 was written until the disk
was full and innobackupex crashed:
# du -sh 2012-03-22_02-15-01/
719G 2012-03-22_02-15-01/
# ls -la 2012-03-22_02-15-01/ | grep ibdata1
-rw-r----- 1 root root 547919757312 Mar 22 18:05 ibdata1
In the corrupt record, there is notion of a table called "#sql-
b59a_a447df". This table is apparently listed in the InnoDB data
dictionary, but not to be found.
I suspect that the files were removed from the mysql folder, instead
of a proper drop table. I know for sure however that this table has
not existed the past month; whatever happened with it, happened a
while ago.
The backup script has always been noticing that the table doesn't
exist and therefor skipped, all .ibd files pass innochecksum though.
Only now this temporary table appears to be causing trouble?
I'm considering downgrading to xtrabackup version 1.6.4, which seemed
to do the backing up correctly (data in restored version ok). For
restoring I would need to continue using 1.6.5, so I'm wondering if
anyone can shed some light on this situation? :-)
Version stuff:
# xtrabackup -v
xtrabackup version 1.6.5 for Percona Server 5.1.59 unknown-linux-gnu
(x86_64) (revision id: 328)
# mysql -V
mysql Ver 14.14 Distrib 5.1.61, for unknown-linux-gnu (x86_64) using
readline 5.1
# cat /proc/version
Linux version 2.6.18-194.17.4.el5 (gcc version 4.1.2 20080704 (Red Hat
4.1.2-48))
Log of prepping the full:
# innobackupex --apply-log --ibbackup=xtrabackup_51 --redo-only /home/
backup/2012-03-22_02-15-01
InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase
Oy
and Percona Inc 2009-2012. All Rights Reserved.
This software is published under
the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.
IMPORTANT: Please check that the apply-log run completes successfully.
At the end of a successful apply-log run innobackupex
prints "completed OK!".
120322 17:29:21 innobackupex: Starting ibbackup with command:
xtrabackup_51 --prepare --target-dir=/home/backup/2012-03-22_02-15-01
--apply-log-only
xtrabackup: cd to /home/backup/2012-03-22_02-15-01
xtrabackup: This target seems to be not prepared yet.
120322 17:29:21 InnoDB: Operating system error number 2 in a file
operation.
InnoDB: The error means the system cannot find the path specified.
xtrabackup: Warning: cannot open ./xtrabackup_logfile. will try to
find.
xtrabackup: 'ib_logfile0' seems to be 'xtrabackup_logfile'. will
retry.
xtrabackup: Temporary instance for recovery is set as followings.
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 1462206464
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory
parameter)
InnoDB: The InnoDB memory heap is disabled
120322 17:29:21 InnoDB: Initializing buffer pool, size = 100.0M
120322 17:29:21 InnoDB: Completed initialization of buffer pool
InnoDB: Log scan progressed past the checkpoint lsn 1552 4005809231
120322 17:29:21 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Doing recovery: scanned up to log sequence number 1552
4011052032 (0 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4016294912 (0 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4021537792 (1 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4026780672 (1 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4032023552 (2 %)
120322 17:29:23 InnoDB: Starting an apply batch of log records to the
database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16
17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39
40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62
63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85
86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
[snip]
120322 17:30:06 InnoDB: Starting an apply batch of log records to the
database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16
17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39
40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62
63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85
86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 1552
4215524352 (16 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4220767232 (16 %)
InnoDB: ############### CORRUPT LOG RECORD FOUND
InnoDB: Log record type 47, space id 5032, page number 0
InnoDB: Log parsing proceeded successfully up to 1552 4225394403
InnoDB: Previous log record type 4, is multi 0
InnoDB: Recv offset 166502, prev 166495
InnoDB: Hex dump of corrupt log starting 100 bytes before the start
InnoDB: of the previous log rec,
InnoDB: and ending 100 bytes after the start of the corrupt rec:
len 207; hex
e6554be6ad482dc6622b6ddbed76e4aa1be072c26c001900018004800680078008ffffffffffffffff8004800480047fff800480048004800400047fff0004800480017fff8010801080082d5682003d002a811082003d003802880007002e00000013e8840007003e93a8af93a80000000021001d62757a7a636170747572652f2373716c2d623539615f613434376466001d93a8011b93a8011f1d93a8000293a8000018080493a800002693a80493a800002a000493a800002e040493a8000032000493a8000036210493a80000;
asc UK H- b+m v r
l -V = * =
8 . > ! db/#sql-
b59a_a447df & * . 2
6! ;
InnoDB: WARNING: the log file may have been corrupt and it
InnoDB: is possible that the log scan did not proceed
InnoDB: far enough in recovery! Please run CHECK TABLE
InnoDB: on your InnoDB tables to check that they are ok!
InnoDB: If mysqld crashes after this recovery, look at
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
InnoDB: Doing recovery: scanned up to log sequence number 1552
4226010112 (16 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4231252992 (17 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4236495872 (17 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4241738752 (18 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4246981632 (18 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4252224512 (18 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4257467392 (19 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4262710272 (19 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4267953152 (20 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4273196032 (20 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4278438912 (20 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4283681792 (21 %)
InnoDB: Doing recovery: scanned up to log sequence number 1552
4288924672 (21 %)
[snip]
InnoDB: Doing recovery: scanned up to log sequence number 1553
866167654 (88 %)
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 2 row operations to undo
InnoDB: Trx id counter is 2 1084739072
120322 17:30:16 InnoDB: Error: table 'db/#sql-405d_44ee4'
InnoDB: in InnoDB data dictionary has tablespace id 7,
InnoDB: but tablespace with that id or name does not exist. It will be
removed from data dictionary.
120322 18:05:35 InnoDB: Error: Write to file ./ibdata1 failed at
offset 127 2458910720.
InnoDB: 1048576 bytes should have been written, only -1 were written.
InnoDB: Operating system error number 28.
InnoDB: Check that your OS and file system support files of this size.
InnoDB: Check also that the disk is not full or a disk quota exceeded.
InnoDB: Error number 28 means 'No space left on device'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/operating-system-error-codes.html
InnoDB: Error: trying to access page number 1298932917 in space 0,
InnoDB: space name ./ibdata1,
InnoDB: which is outside the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check that
InnoDB: your my.cnf matches the ibdata files that you have in the
InnoDB: MySQL server.
120322 18:05:35 InnoDB: Assertion failure in thread 47967927478528 in
file fil/fil0fil.c line 4328
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
xtrabackup_51 version 1.6.5 for MySQL server 5.1.59 unknown-linux-gnu
(x86_64) (revision id: 328)
xtrabackup: xtrabackup_logfile detected: size=1462206464,
start_lsn=(1552 4005809231)
innobackupex: Error:
innobackupex: ibbackup failed at /usr/bin/innobackupex line 349.
Reply all
Reply to author
Forward
0 new messages