Query with AFTER UPDATE trigger not visible in binary logs
Hi!
We have a deadlock issue, where one query being part of the deadlock is on the following form:
DELETE FROM tblZ WHERE colA = 'tblA' AND id IN (... list of IDs ...);
It's running in parallel with a transaction which targets a bunch of tables, including tblA. tblA has an AFTER UPDATE trigger which in turn manages rows in tblZ. This setup sometimes causes deadlocks.
To identify the problematic transaction I've investigated the binary logs and found something suspicious. Namely that an AFTER INSERT trigger gets properly logged (both the original INSERT and the trigger query), but with an AFTER UPDATE trigger you will end up with only of the the UPDATE query or the trigger query being logged.
I've constructed a tiny reproduceable example that shows the problem.
MySQL version where this was tested: 5.6.27-log
Binary logging needs to be enabled and the binlog_format should be set to ROW.
/*
* Table trg_A definition
*/
CREATE TABLE `trg_a` (
`id` int(11) NOT NULL AUTO_INCREMENT,
`val` int(11) NOT NULL,
PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1;
/*
* Table trg_B definition
*/
CREATE TABLE `trg_b` (
`source` varchar(45) NOT NULL,
`id` int(11) NOT NULL,
PRIMARY KEY (`source`,`id`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1;
/*
* AFTER INSERT trigger for table trg_A
*/
CREATE TRIGGER `test`.`trg_a_AFTER_INSERT` AFTER INSERT ON `trg_a` FOR EACH ROW
BEGIN
IF(new.val <= 1000) THEN
INSERT INTO trg_b (`source`, `id`) VALUES ('trg_a_ok', new.id);
ELSE
INSERT INTO trg_b (`source`, `id`) VALUES ('trg_a_toohigh', new.id);
END IF;
END
/*
* AFTER UPDATE trigger for table trg_A
*/
CREATE TRIGGER `test`.`trg_a_AFTER_UPDATE` AFTER UPDATE ON `trg_a` FOR EACH ROW
BEGIN
REPLACE INTO trg_b (`source`, `id`) VALUES ('trg_a_ok', new.id);
END
Now, in a MySQL client execute these queries:
INSERT INTO trg_a (val) VALUES (777);
UPDATE trg_a SET val = 888 WHERE id = 1;
Now, check the binary log. It should look something like this:
=========================================
---------------------------------------
BINARY LOG PART 1 (AFTER INSERT TRG)
---------------------------------------
# at 5202
#170720 12:04:32 server id 1 end_log_pos 5274 CRC32 0x1ea007f7 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1500545072/*!*/;
BEGIN
/*!*/;
# at 5274
#170720 12:04:32 server id 1 end_log_pos 5323 CRC32 0x944bb3fe Table_map: `test`.`trg_a` mapped to number 109
# at 5323
#170720 12:04:32 server id 1 end_log_pos 5374 CRC32 0x57b28c9e Table_map: `test`.`trg_b` mapped to number 110
# at 5374
#170720 12:04:32 server id 1 end_log_pos 5418 CRC32 0x2efa2cae Write_rows: table id 109
# at 5418
#170720 12:04:32 server id 1 end_log_pos 5467 CRC32 0xcccc7781 Write_rows: table id 110 flags: STMT_END_F
BINLOG '
MIBwWRMBAAAAMQAAAMsUAAAAAG0AAAAAAAEABHRlc3QABXRyZ19hAAIDAwAA/rNLlA==
MIBwWRMBAAAAMwAAAP4UAAAAAG4AAAAAAAEABHRlc3QABXRyZ19iAAIPAwItAACejLJX
MIBwWR4BAAAALAAAACoVAAAAAG0AAAAAAAAAAgAC//wCAAAAeAMAAK4s+i4=
### INSERT INTO `test`.`trg_a`
### SET
### @1=2 /* INT meta=0 nullable=0 is_null=0 */
### @2=888 /* INT meta=0 nullable=0 is_null=0 */
MIBwWR4BAAAAMQAAAFsVAAAAAG4AAAAAAAEAAgAC//wIdHJnX2Ffb2sCAAAAgXfMzA==
'/*!*/;
### INSERT INTO `test`.`trg_b`
### SET
### @1='trg_a_ok' /* VARSTRING(45) meta=45 nullable=0 is_null=0 */
### @2=2 /* INT meta=0 nullable=0 is_null=0 */
# at 5467
#170720 12:04:32 server id 1 end_log_pos 5498 CRC32 0x5b9a471d Xid = 476
COMMIT/*!*/;
DELIMITER ;
---------------------------------------
BINARY LOG PART 2 (AFTER UPDATE TRG)
---------------------------------------
# at 4945
#170720 11:54:12 server id 1 end_log_pos 5017 CRC32 0x96d5c92b Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1500544452/*!*/;
SET @@session.pseudo_thread_id=3/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1073741824/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C cp850 *//*!*/;
SET @@session.character_set_client=4,@@session.collation_connection=4,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 5017
#170720 11:54:12 server id 1 end_log_pos 5066 CRC32 0xd0f73bc7 Table_map: `test`.`trg_a` mapped to number 109
# at 5066
#170720 11:54:12 server id 1 end_log_pos 5117 CRC32 0xf351ece6 Table_map: `test`.`trg_b` mapped to number 110
# at 5117
#170720 11:54:12 server id 1 end_log_pos 5171 CRC32 0xaf79fd92 Update_rows: table id 109 flags: STMT_END_F
BINLOG '
xH1wWRMBAAAAMQAAAMoTAAAAAG0AAAAAAAEABHRlc3QABXRyZ19hAAIDAwAAxzv30A==
xH1wWRMBAAAAMwAAAP0TAAAAAG4AAAAAAAEABHRlc3QABXRyZ19iAAIPAwItAADm7FHz
xH1wWR8BAAAANgAAADMUAAAAAG0AAAAAAAEAAgAC///8AQAAAAkDAAD8AQAAAOgDAACS/Xmv
'/*!*/;
### UPDATE `test`.`trg_a`
### WHERE
### @1=1 /* INT meta=0 nullable=0 is_null=0 */
### @2=777 /* INT meta=0 nullable=0 is_null=0 */
### SET
### @1=1 /* INT meta=0 nullable=0 is_null=0 */
### @2=1000 /* INT meta=0 nullable=0 is_null=0 */
# at 5171
#170720 11:54:12 server id 1 end_log_pos 5202 CRC32 0x14b1f37b Xid = 456
COMMIT/*!*/;
DELIMITER ;
=========================================
In the example only the UPDATE query is shown, not the trigger query. For the INSERT, both queries are shown.
In a copy of the binary log of our production server, I see a similar pattern. Whenever an AFTER UPDATE trigger is involved I can only see one query and quite often it's just the trigger query. So in my deadlock case I couldn't identify the root cause (guilty transaction), even though I could find the thread id that I got from the error log (which shows all deadlocks).
Question 1: Is there any way to make the binary log show all statements of a transaction when an AFTER UPDATE trigger is invovled?
Question 2: Is this a bug?
Question 3: The DELETE FROM x WHERE id IN (...) isn't part of a transaction. How can it cause a deadlock? Is there something I should know about the locking strategy of such a query? (I know, this isn't related to triggers).
Any answer to any of the questions would be highly appreciated!
Best regards
David