Bug #49337 100% CPU loop on BACKUP DATABASE
Submitted: 2 Dec 2009 11:44 Modified: 15 Dec 2009 10:14
Reporter: Philip Stoev Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: Backup Severity:S2 (Serious)
Version:6.0-backup OS:Any
Assigned to: Rafal Somla CPU Architecture:Any

[2 Dec 2009 11:44] Philip Stoev
Description:
When executing a concurrent workload with BACKUP/RESTORE and DDL, mysqld ended up with a 100% CPU loop with the following stack trace:

#0  0x000000315b00df5b in read () from /lib64/libpthread.so.0
#1  0x0000000000a014cd in my_read (Filedes=87, Buffer=0x3053e29 "ЧЧ\a\001", Count=1048575, MyFlags=16) at my_read.c:50
#2  0x00000000009d3123 in myisam_backup::File_backup::get_data (this=0x2e977b8, buf=@0x2de3160) at myisam_backup_engine.cc:1227
#3  0x00000000009d322a in myisam_backup::Log_backup::get_data (this=0x2e977a0, buf=@0x2de3160) at myisam_backup_engine.cc:1175
#4  0x00000000009d5a4f in myisam_backup::Backup::get_data (this=0x2e971a0, buf=@0x2de3160) at myisam_backup_engine.cc:712
#5  0x0000000000adf647 in backup::Backup_pump::pump (this=0x2de3120, howmuch=0x7fd18f2fbfb8) at data_backup.cc:1405
#6  0x0000000000ae03a1 in backup::Scheduler::step (this=0x7fd18f2fc030) at data_backup.cc:836
#7  0x0000000000ae11d7 in backup::write_table_data (thd=0x7fd1881f2cb8, info=@0x2fc9820, s=@0x2e4bdd0) at data_backup.cc:666
#8  0x0000000000ad6fbb in Backup_restore_ctx::do_backup (this=0x7fd18f2fc220) at kernel.cc:1395
#9  0x0000000000ad9bcc in execute_backup_command (thd=0x7fd1881f2cb8, lex=0x7fd1881f4588, backupdir=0x7fd18f2fd1a0, overwrite=false, skip_gap_event=false)
    at kernel.cc:269
#10 0x000000000068549f in mysql_execute_command (thd=0x7fd1881f2cb8) at sql_parse.cc:2482
#11 0x000000000068d0cf in mysql_parse (thd=0x7fd1881f2cb8,
    inBuf=0x2deb850 "BACKUP DATABASE testdb_N TO '/tmp/gentest8496-1259752997.14649-0.295562722390549.tmp'", length=85, found_semicolon=0x7fd18f2fdf00)
    at sql_parse.cc:5985
#12 0x000000000068dd38 in dispatch_command (command=COM_QUERY, thd=0x7fd1881f2cb8,
    packet=0x7fd1881fd829 "BACKUP DATABASE testdb_N TO '/tmp/gentest8496-1259752997.14649-0.295562722390549.tmp' ", packet_length=86) at sql_parse.cc:1078
#13 0x000000000068f2aa in do_command (thd=0x7fd1881f2cb8) at sql_parse.cc:760
#14 0x000000000067bff8 in handle_one_connection (arg=0x7fd1881f2cb8) at sql_connect.cc:1164
#15 0x000000315b0073da in start_thread () from /lib64/libpthread.so.0
#16 0x000000315a4e627d in clone () from /lib64/libc.so.6

strace reports an infinite progression of read calls

[pid  8497] read(87, ""..., 1048575)    = 0

meaning that EOF is being returned by read() but does not cause BACKUP to give up. The file descriptor 87 is connected to var/tmp/#sql210a_8_0-backuplog, which has a file size of zero.

How to repeat:
If this is repeatable, a test case will be provided.

In the meantime, the core and the binary will be made available.
[2 Dec 2009 12:46] Rafal Somla
Looks like duplicate of Bug#33019. We know about the tight data reading loop and plan to fix eventually.
[2 Dec 2009 14:10] Philip Stoev
Core and binary:

http://mysql-systemqa.s3.amazonaws.com/var-bug49337.zip
[2 Dec 2009 15:07] Philip Stoev
This issue is more than a minor inconvenience or inneficiency. I observe 20 000 read calls per second and no productive work is being done. BACKUP and all other queries hang, though BACKUP can be killed to remove the issue.
[9 Dec 2009 21:21] Chuck Bell
Can we get a bit more information about how to setup the scenario? Like what tables were used, storage engines, DDL, etc. It would be a big help.
[15 Dec 2009 10:14] Rafal Somla
Duplicate of BUG#33019. I'll work on a fix for the latter bug.