MySQLDump Error – Couldn’t Execute ‘ROLLBACK TO SAVEPOINT sp’

amazon-rdsMySQLmysqldump

Can any one please explain what is happening with our DB dumps?

We are executing dump as below

mysqldump -v --single-transaction --quick --lock-tables=false --skip-triggers -uXXX -pXXX $EXCLUDETABLES dbname -h xxx.xxx.xxx > $FLNM

$EXCLUDETABLES contains multiple –ignore-table statements

Instance details : AWS RDS MYSQL MULTIAZ 5.6.21 us-east-1c 40GB

Warning: Using a password on the command line interface can be insecure.
-- Connecting to xxx.xxx.xxx...
-- Starting transaction...
-- Setting savepoint...
-- Retrieving table structure for table t_XXX_XXX...
-- Sending SELECT query...
-- Retrieving rows...
-- Rolling back to savepoint sp...
-- Retrieving table structure for table t_XXX...
-- Sending SELECT query...
-- Retrieving rows...
-- Rolling back to savepoint sp...
-- Retrieving table structure for table t_XXX...
-- Sending SELECT query...
-- Retrieving rows...
-- Rolling back to savepoint sp...
-- Retrieving table structure for table t_XXX_XXX...
-- Sending SELECT query...
-- Retrieving rows...
-- Rolling back to savepoint sp...
-- Retrieving table structure for table t_XXX...
-- Sending SELECT query...
-- Retrieving rows...
-- Rolling back to savepoint sp...
mysqldump: Couldn't execute 'ROLLBACK TO SAVEPOINT sp': SAVEPOINT sp does not exist (1305)

RDS error log at the same time

2014-11-18 12:59:03 28522 [Note] Plugin 'FEDERATED' is disabled.
2014-11-18 12:59:03 28522 [Note] InnoDB: Using atomics to ref count buffer pool pages
2014-11-18 12:59:03 28522 [Note] InnoDB: The InnoDB memory heap is disabled
2014-11-18 12:59:03 28522 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2014-11-18 12:59:03 28522 [Note] InnoDB: Memory barrier is not used
2014-11-18 12:59:03 28522 [Note] InnoDB: Compressed tables use zlib 1.2.3
2014-11-18 12:59:03 28522 [Note] InnoDB: Using Linux native AIO
2014-11-18 12:59:03 28522 [Note] InnoDB: Using CPU crc32 instructions
2014-11-18 12:59:03 28522 [Note] InnoDB: Initializing buffer pool, size = 5.3G
2014-11-18 12:59:04 28522 [Note] InnoDB: Completed initialization of buffer pool
2014-11-18 12:59:04 28522 [Note] InnoDB: Highest supported file format is Barracuda.
2014-11-18 12:59:04 28522 [Note] InnoDB: The log sequence numbers 32416243155 and 32416243155 in ibdata files do not match the log sequence number 42069849641 in the ib_logfiles!
2014-11-18 12:59:04 28522 [Note] InnoDB: Database was not shutdown normally!
2014-11-18 12:59:04 28522 [Note] InnoDB: Starting crash recovery.
2014-11-18 12:59:04 28522 [Note] InnoDB: Reading tablespace information from the .ibd files...
2014-11-18 12:59:05 28522 [Note] InnoDB: Restoring possible half-written data pages 
2014-11-18 12:59:05 28522 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Last MySQL binlog file position 0 184648, file name mysql-bin-changelog.001861
2014-11-18 12:59:06 28522 [Note] InnoDB: 128 rollback segment(s) are active.
2014-11-18 12:59:06 28522 [Note] InnoDB: Waiting for purge to start
2014-11-18 12:59:06 28522 [Note] InnoDB: 5.6.21 started; log sequence number 42069849641
2014-11-18 12:59:06 28522 [Note] Recovering after a crash using /rdsdbdata/log/binlog/mysql-bin-changelog
2014-11-18 12:59:06 28522 [Note] Starting crash recovery...
2014-11-18 12:59:06 28522 [Note] Crash recovery finished.
2014-11-18 12:59:06 28522 [Note] Server hostname (bind-address): '*'; port: 3306
2014-11-18 12:59:06 28522 [Note] IPv6 is available.
2014-11-18 12:59:06 28522 [Note] - '::' resolves to '::';
2014-11-18 12:59:06 28522 [Note] Server socket created on IP: '::'.
2014-11-18 12:59:06 28522 [Note] Event Scheduler: Loaded 0 events
2014-11-18 12:59:06 28522 [Note] /rdsdbbin/mysql/bin/mysqld: ready for connections.
Version: '5.6.21-log' socket: '/tmp/mysql.sock' port: 3306 MySQL Community Server (GPL)

–Edit–

Would like to know if there are any relation with –skip-triggers. We added a trigger to a table a week back. Trigger basically updates a shadow table. We do not require shadow table in daily backups, so we are ignoring that table also.

Is there any know issues while backing up mysql databases with triggers, any other item to consider?

Best Answer

Sounds like a bug from a year ago (mysqldump creates useless metadata locks)

This bug was fixed for MySQL 5.5 and I see you are using MySQL 5.6.21

SUGGESTIONS

Don't use --lock-tables=false with --single-transaction because MySQL Documentation says "The --single-transaction option and the --lock-tables option are mutually exclusive because LOCK TABLES causes any pending transactions to be committed implicitly."
Don't do any DDL from other DB Session while the mysqldump is in progress

GIVE IT A TRY !!!

Related Solutions

MySQL – Troubleshooting Startup Issues After Increasing innodb_buffer_pool_size

The two answers given from @RickJames and @drogart are essentially the remedies. (+1 for each).

Right from the error log you present, the last two lines say:

InnoDB: Error: log file ./ib_logfile0 is of different size 0 134217728 bytes

InnoDB: than specified in the .cnf file 0 268435456 bytes! `

At that point, it was evident that you set innodb_log_file_size to 256M (268435456) in my.cnf while the InnoDB Transaction Logs (ib_logfile0,ib_logfile1) were respectively 128M (134217728) each. Looking back at the link to my StackOverflow answer in your question, you had to do the following:

Step 01) Add this to my.cnf:

[mysqld]
innodb_buffer_pool_size=4G
innodb_log_file_size=1G

Step 02) Run these command in the OS

mysql -u... -p... -e"SET GLOBAL innodb_fast_shutdown = 1"
service mysql stop
rm -f /var/lib/mysql/ib_logfile*
service mysql start

So as to have confidence in what is happening, run tail -f against the error log. You will see message telling you when each innodb log file is being created.

MySQL InnoDB logfiles resized – review thesql-err.log for potential problems

It is sort of yes and no. Why would I say both?

There are still some transactional data embedded in the old ib_logfiles in conjunction with the ibdata1 file. (See pictorial representation)

What you should have done is this:

mysql -u... -p... -ANe"SET GLOBAL innodb_fast_shutdown = 0"
/etc/init.d/mysql.server stop
mv ib_logfile0 ib_logfile0.OLD
mv ib_logfile0 ib_logfile0.OLD
/etc/init.d/mysql.server start

If you did not know of disabling innodb_fast_shutdown, ther you steps should have been

/etc/init.d/mysql.server stop
/etc/init.d/mysql.server start
/etc/init.d/mysql.server stop
mv ib_logfile0 ib_logfile0.OLD
mv ib_logfile0 ib_logfile0.OLD
/etc/init.d/mysql.server start

Doing either of these coordinate the purging of all uncommitted writes to tables and indexes. Just looking at the error log, I think you dodged a bullet in this instance. In future, please follow this protocol.

If you are not sure either way, you could put back the old log files, set the old size of innodb_log_file_size, restart mysql. Then, start the process over again as I prescribed above.