MySQL Bugs: #21653: Mysql appears to hang at bin log file rotation (not every rotation)

Bug #21653	Mysql appears to hang at bin log file rotation (not every rotation)
Submitted:	15 Aug 2006 12:06	Modified:	26 Aug 2006 10:00
Reporter:	Brian Robinson	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server	Severity:	S2 (Serious)
Version:	5.0.19	OS:	Linux (SuSE 10.0)
Assigned to:		CPU Architecture:	Any
Tags:	log file rotation

Description:
We seem to have a problem in that every few days the server hangs. We have narrowed this down to be occurring when the binary log file rotates (we have 2 in the group). This does not occur every time the log file rotates - but when we see that our system hangs - we also see that the bin log is about to rotate - well its reached the max size (1GB) anyway.

Also below is the results of show full processlist; in this list there are several statements with status "end;". We have understood that if this is the case then there is some error in processing the statement.

any help/pointers would be appreciated. We have trawled (unsuccessfully) the forums and the bugs database looking for errors associated with log rotation

here are our variables and my.cnf and result of show full process list;

we can provide other log files as you require

show full processlist;
===========================

[http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - Free Mem:1.8 GB
2006-08-14 06:13:52.788 [http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - id:184614 command:Execute time:27 state:end info:UPDATE FileInfo SET CacheStatus='NYNNNNNNNNNNNNNNNNNN',ThumbnailWidth=60,ThumbnailHeight=40,TnStatus='F' WHERE FileId=430318803
2006-08-14 06:13:52.788 [http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - id:184615 command:Query time:28 state: info:commit
2006-08-14 06:13:52.788 [http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - id:184616 command:Execute time:27 state:end info:UPDATE FileInfo SET CacheStatus='NNNNNNNN',ThumbnailWidth=0,ThumbnailHeight=0,TnStatus='F' WHERE FileId=431590889
2006-08-14 06:13:52.788 [http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - id:184617 command:Execute time:28 state:end info:UPDATE FileInfo SET CacheStatus='NYNNNNNNNNNNNNNNNNNN',ThumbnailWidth=60,ThumbnailHeight=45,TnStatus='F' WHERE FileId=431086763
2006-08-14 06:13:52.788 [http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - id:184618 command:Execute time:27 state:end info:UPDATE RemoteComputer SET LastLifesign=1155561205236 WHERE RemoteClientId=1154255357630
2006-08-14 06:13:52.788 [http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - id:184619 command:Execute time:28 state:end info:UPDATE FileInfo SET CacheStatus='NYNNNNNNNNNNNNNNNNNN',ThumbnailWidth=49,ThumbnailHeight=60,TnStatus='F' WHERE FileId=417782760
2006-08-14 06:13:52.788 [http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - id:184620 command:Execute time:26 state:end info:UPDATE RemoteComputer SET LastConnect=1155561206068,LastStatus='Incorrect login' WHERE RemoteClientId=1146103618729
2006-08-14 06:13:52.788 [http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - id:184621 command:Execute time:27 state:end info:UPDATE FileInfo SET TnStatus='1' WHERE FileId=429072831
2006-08-14 06:13:52.788 [http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - id:184622 command:Execute time:27 state:end info:UPDATE RemoteComputer SET LastLifesign=1155561205954 WHERE RemoteClientId=1152201399269
2006-08-14 06:13:52.788 [http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - id:184623 command:Execute time:24 state:end info:UPDATE RemoteComputer SET LastConnect=1155561208009,LastStatus='Incorrect login' WHERE RemoteClientId=0
2006-08-14 06:13:52.788 [http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - id:184624 command:Execute time:24 state:end info:UPDATE RemoteComputer SET LastConnect=1155561208688,LastStatus='' WHERE RemoteClientId=1153603001591
2006-08-14 06:13:52.788 [http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - id:184625 command:Execute time:23 state:end info:UPDATE RemoteComputer SET ClientOptions='YYYYYNYN' WHERE RemoteClientId=1154814274815
2006-08-14 06:13:52.788 [http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - id:184627 command:Execute time:20 state:end info:UPDATE RemoteComputer SET LastLifesign=1155561212086 WHERE RemoteClientId=1153490508700
2006-08-14 06:13:52.789 [http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - id:184628 command:Execute time:21 state:end info:UPDATE RemoteComputer SET LastLifesign=1155561211973 WHERE RemoteClientId=1151837033829
2006-08-14 06:13:52.789 [http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - id:184629 command:Execute time:22 state:end info:UPDATE RemoteComputer SET LastLifesign=1155561210832 WHERE RemoteClientId=1153055096082
2006-08-14 06:13:52.789 [http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - id:184630 command:Execute time:4 state:end info:UPDATE SMSActivity SET StatusCode=4,IsProcessed='Y' WHERE Ticket='12006-0814J-0838Q-48V8D'
2006-08-14 06:13:52.789 [http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - id:184631 command:Execute time:0 state: info:show full processlist
2006-08-14 06:13:52.789 [http-192.168.2.1-8443-Processor30] INFO  com.managers.StatusManager  - id:184632 command:Execute time:11 state:update info:INSERT INTO AccountSignup(FullName,PhoneNumber,Email,TimeZoneId,IMAccount,Company,BusinessType,Title,UserName,Password, SecQuestion, SecAnswer, ProcessUserId, Campaign, Partner, PartnerId) VALUES ('','','','','','','','','Filson','indiranagar','','',1,'','','')

my.cnf
===========================================
[mysqld]
#1
lower_case_table_names=1

#2
sql-mode="NO_BACKSLASH_ESCAPES"

#3
default-storage-engine=INNODB

#4
default-character-set=UTF8

#5,6, 112
datadir = /var/lib/mysql
innodb_data_home_dir = /var/lib/mysql
innodb_data_file_path = ibdata1:1282M:autoextend
innodb_autoextend_increment = 500M
innodb_buffer_pool_size=1792M
innodb_log_file_size=128M
innodb_log_group_home_dir = /var/lib/mysql/log
innodb_log_arch_dir = /var/lib/mysql/arch
innodb_log_files_in_group = 2

key_buffer_size = 128M
#7
log-bin=mysql01

#8
innodb_file_per_table

#9
# see http://dev.mysql.com/doc/refman/5.0/en/innodb-parameters.html
innodb_flush_log_at_trx_commit = 0

#10  Replication
server-id=1

#10  only ir_db_dbo to be replicated
binlog-do-db = ir_db_dbo

# wait timeout = 15 minutes
wait_timeout=900
thread_cache_size=40
max_connections=180
max_user_connections=140

How to repeat:
this is dificlut to give instructions as to how to repeat as we cannot yet get the "hang" to occur at will. 

BUT every time it does hang we see that he bin log has reached max size. (1GB).

below you can see the end of two binary log files (after having run mysqlbinlog).
The first log is from a log file that rotated OK.
The second is from a log file that did not rotate OK and the server hung. We could continue to do queries etc - but updates/inserts/deletes etc were prevented (as expected if there is a problem in rotating the log and the log file size has reached max or thereabouts)

First Example tail of Log that rotated OK 
==========================================
# at 104857560
#060817 20:37:56 server id 1  end_log_pos 181   Query   thread_id=42310 exec_time=0     error_code=0
SET TIMESTAMP=1155872276;
UPDATE FileInfo SET CacheStatus='NNNNNNNN',ThumbnailWidth=0,ThumbnailHeight=0,TnStatus='F' WHERE FileId=445769973;
# at 104857741
#060817 20:37:56 server id 1  end_log_pos 104857768     Xid = 61074298
COMMIT;
# at 104857768
#060817 20:37:56 server id 1  end_log_pos 104857809     Rotate to mysql01.000538  pos: 4
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

Example tail of Log that DID NOT rotate OK 
==========================================
SET TIMESTAMP=1155728763;
BEGIN;
# at 104857594
#060816  4:46:03 server id 1  end_log_pos 114   Query
SET TIMESTAMP=1155728763;
DELETE FROM CacheRemove WHERE FileId=440834385;
# at 104857708
#060816  4:46:03 server id 1  end_log_pos 104857735
COMMIT;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

Sounds like the same problem that we have experienced for the last 8 months.

Bug ID: 20408
http://bugs.mysql.com/?id=20408

I cannot offer you a solution, but a small workaround that might or might not be applicable to your situation:

In our experience, a DB server bounce (shutdown/start) rotates the log and never hangs. So we do this once every day and to keep us out of trouble.

But any real solution or method to track the problem would be obviously preferred.

Thanks Andreas. Its nice to know we are not alone. 
And your symptoms seem to match ours exactly.
High load. 
Droppng down the size of the bin log does not help (neither does it increase the frequency of the occurrence !!!!)
We may move in the next couple of days to 5.0.24 - I'll keep you posted.
cheers
Brian

Please do not submit the same bug more than once. An existing bug report, bug #20408, already describes this very problem. Even if you feel that your issue is somewhat different, the resolution is likely to be the same. Because of this, we hope you add your comments to the original bug instead.

Thank you for your interest in MySQL.