MySQL Bugs: #76618: SHOW BINLOG EVENTS completely locks down writes to binlog, hence transactions

Bug #76618	SHOW BINLOG EVENTS completely locks down writes to binlog, hence transactions
Submitted:	8 Apr 2015 11:23	Modified:	24 Aug 2015 15:06
Reporter:	Shlomi Noach (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Utilities: Binlog Events	Severity:	S3 (Non-critical)
Version:	5.6.15-log	OS:	Linux (CentOS release 6.5)
Assigned to:		CPU Architecture:	Any
Tags:	binary logs, binlogs, lock

Description:
While a `SHOW BINLOG EVENTS IN 'logfile' LIMIT X,Y` is executing, any write statement is blocked.

Consider:

mysql-session0> show master logs;
+---------------+-----------+
| binlog.010447 | 104858802 |
| binlog.010448 | 104857773 |
| binlog.010449 | 104858591 |
| binlog.010450 | 104860638 |
| binlog.010451 |  19627840 |
+---------------+-----------+

[externally, issue: `show binlog events in 'binlog.010450' LIMIT 0,1000000`, takes 9 seconds to complete]

mysql-session0> update heartbeat set update_by=rand();
(blocks)

mysql-session1> show processlist;
+---------+---------+----------------+-------------------------------------------------------+
| Command | Time    | State          | Info                                                  |
+---------+---------+----------------+-------------------------------------------------------+
| Query   |       7 | query end      | update heartbeat set update_by=rand()                 |
| Query   |       8 | Writing to net | show binlog events in 'binlog.010450' LIMIT 0,1000000 |
+---------+---------+----------------+-------------------------------------------------------+

mysql-session1> show processlist;
+---------+---------+----------------+-------------------------------------------------------+
| Command | Time    | State          | Info                                                  |
+---------+---------+----------------+-------------------------------------------------------+
| Query   |       2 | query end      | update heartbeat set update_by=rand()                 |
| Query   |       3 | Writing to net | show binlog events in 'binlog.010450' LIMIT 0,1000000 |
+---------+---------+----------------+-------------------------------------------------------+

once the SHOW BINLOG EVENTS query completes, the UPDATE is released.

NOTE that this happens even if the BINLOG at hand isn't the active binary log (as in this example)

Note: this happens even where @@sync_binlog=0; This happens both for InnoDB & MyISAM

The time it takes to issue SHOW BINLOG EVENTS varies by the LIMIT argument. But also, depending on whether the connector at hand uses buffered or unbuffered result sets, the application may add its own locking time.
In my particular use case, I'm issuing the query from Go, using the go-mysql driver, which uses *unbuffered* result sets. This means the lock time includes any incurred application delay. But the problem exists regardless.

The mysql client binary uses buffered results and so you will notice a much shorter lock time.

How to repeat:
Issue SHOW BINLOG EVENTS on any existing binlog file, then try some UPDATE concurrently

Suggested fix:
In my opinion:
- SHOW BINLOG EVENTS on the non-active binlogfile should not lock anything at all, EXCEPT for the case of log rotation and possible purging.
- SHOW BINLOG EVENTS on the active binary log should not lock if not reaching the executing position (as in SHOW MASTER STATUS)
- SHOW BINLOG EVENTS on the active binary log could implicitly return once reaching the executing position (as in SHOW MASTER STATUS), hence does not need to compete with ongoing writes.

I wonder why these locks take place in the first place, when the natural replication mechanism, where the slave practically requests for the same info (and much more) does not incur any such locks.

I pasted the "show processlist" above in reverse order. Anyway the purpose was to show how lock was taken through many seconds.

Cross-referencing feature request for go-mysql driver: https://github.com/go-sql-driver/mysql/issues/328

On 5.6.15, commits hang here:
ntdll!ZwWaitForSingleObject+0xa
ntdll!RtlpWaitOnCriticalSection+0xe8
ntdll!RtlEnterCriticalSection+0xd1
mysqld!MYSQL_BIN_LOG::change_stage+0xa8 [.\mysql-5.6.15\sql\binlog.cc @ 6568]
mysqld!MYSQL_BIN_LOG::ordered_commit+0x6c [.\mysql-5.6.15\sql\binlog.cc @ 6780]
mysqld!MYSQL_BIN_LOG::commit+0x333 [.\mysql-5.6.15\sql\binlog.cc @ 6288]
mysqld!ha_commit_trans+0x1a5 [.\mysql-5.6.15\sql\handler.cc @ 1435]
mysqld!trans_commit_stmt+0x35 [.\mysql-5.6.15\sql\transaction.cc @ 435]
mysqld!mysql_execute_command+0x3c2d [.\mysql-5.6.15\sql\sql_parse.cc @ 4998]
mysqld!mysql_parse+0x1ed [.\mysql-5.6.15\sql\sql_parse.cc @ 6240]
mysqld!dispatch_command+0x70d [.\mysql-5.6.15\sql\sql_parse.cc @ 1337]
mysqld!do_command+0x167 [.\mysql-5.6.15\sql\sql_parse.cc @ 1042]
mysqld!do_handle_one_connection+0x134 [.\mysql-5.6.15\sql\sql_connect.cc @ 982]
mysqld!handle_one_connection+0x3a [.\mysql-5.6.15\sql\sql_connect.cc @ 900]
mysqld!pfs_spawn_thread+0x136 [.\mysql-5.6.15\storage\perfschema\pfs.cc @ 1861]
mysqld!pthread_start+0x1e [.\mysql-5.6.15\mysys\my_winthread.c @ 63]

While a low client using mysql_use_result is transfering data:

| Time | State          | Info
+------+----------------+----------------------------------------
|   33 | query end      | update ignore `blobtest_12` as `t1`,`bl
|    0 | init           | show processlist
|   31 | Writing to net | show binlog events in "i7-bin.000003"
+------+----------------+----------------------------------------

WS2_32!DPROVIDER::WSPSend+0x6c
WS2_32!send+0xce
mysqld!vio_write+0xc6 [.\mysql-5.6.15\vio\viosocket.c @ 192]
mysqld!net_write_raw_loop+0x42 [.\mysql-5.6.15\sql\net_serv.cc @ 503]
mysqld!net_write_packet+0x8b [.\mysql-5.6.15\sql\net_serv.cc @ 636]
mysqld!net_write_buff+0x78 [.\mysql-5.6.15\sql\net_serv.cc @ 452]
mysqld!my_net_write+0xe6 [.\mysql-5.6.15\sql\net_serv.cc @ 325]
mysqld!Protocol::write+0x1f [.\mysql-5.6.15\sql\protocol.cc @ 822]
mysqld!Log_event::net_send+0xd2 [.\mysql-5.6.15\sql\log_event.cc @ 918]
mysqld!show_binlog_events+0x37e [.\mysql-5.6.15\sql\binlog.cc @ 2295]
mysqld!mysql_show_binlog_events+0x71 [.\mysql-5.6.15\sql\binlog.cc @ 2375]
mysqld!mysql_execute_command+0x8a9 [.\mysql-5.6.15\sql\sql_parse.cc @ 2757]
mysqld!mysql_parse+0x1ed [.\mysql-5.6.15\sql\sql_parse.cc @ 6240]
mysqld!dispatch_command+0x70d [.\mysql-5.6.15\sql\sql_parse.cc @ 1337]
mysqld!do_command+0x167 [.\mysql-5.6.15\sql\sql_parse.cc @ 1042]
mysqld!do_handle_one_connection+0x134 [.\mysql-5.6.15\sql\sql_connect.cc @ 982]
mysqld!handle_one_connection+0x3a [.\mysql-5.6.15\sql\sql_connect.cc @ 900]
mysqld!pfs_spawn_thread+0x136 [.\mysql-5.6.15\storage\perfschema\pfs.cc @ 1861]
mysqld!pthread_start+0x1e [.\mysql-5.6.15\mysys\my_winthread.c @ 63]
mysqld!_callthreadstartex+0x17 [f:\dd\vctools\crt_bld\self_64_amd64\crt\src\thr
mysqld!_threadstartex+0x7f [f:\dd\vctools\crt_bld\self_64_amd64\crt\src\threade
kernel32!BaseThreadInitThunk+0xd

same on 5.6.24

same symptom on 5.7.8..

Thanks for your feedback. This has been fixed in upcoming versions and the following was added to the 5.6.27 and 5.7.9 changelogs:
While a SHOW BINLOG EVENTS statement was executing, any parallel transaction was blocked. The fix ensures that the SHOW BINLOG EVENTS process now only acquires a lock for the duration of calculating the file's end position, therefore parallel transactions are not blocked for long durations.