Skip to content

Commit a0946fa

Browse files
author
Alfranio Correia
committed
BUG#50038 Deadlock on flush logs with concurrent DML and RBR
In auto-commit mode, updating both trx and non-trx tables (i.e. issuing a mixed statement) causes the following sequence of events: 1 - "Flush trx changes" (MYSQL_BIN_LOG::write) - T1: 1.1 - mutex_lock (&LOCK_log) 1.2 - mutex_lock (&LOCK_prep_xids) 1.3 - increase prepared_xids 1.4 - mutex_unlock (&LOCK_prep_xids) 1.5 - mutex_unlock (&LOCK_log) 2 - "Flush non-trx changes" (MYSQL_BIN_LOG::write) - T1: 2.1 - mutex_lock (&LOCK_log) 2.2 - mutex_unlock (&LOCK_log) 3. "unlog" - T1 3.1 - mutex_lock (&LOCK_prep_xids) 3.2 - decrease prepared xids 3.3 - pthread_cond_signal(&COND_prep_xids); 3.4 - mutex_unlock (&LOCK_prep_xids) The "FLUSH logs" command produces the following sequence of events: 1 - "FLUSH logs" command (MYSQL_BIN_LOG::new_file_impl) - user thread: 1.1 - mutex_lock (&LOCK_log) 1.2 - mutex_lock (&LOCK_prep_xids) 1.3 - while (prepared_xids) pthread_cond_wait(..., &LOCK_prep_xids); 1.4 - mutex_unlock (&LOCK_prep_xids) 1.5 - mutex_unlock (&LOCK_log) A deadlock will arise if T1 flushes the trx changes and thus increases prepared_xids but before it is able to continue the execution and flush the non-trx changes, an user thread calls the "FLUSH logs" command and wait that the prepared_xids is decreased and gets to zero. However, T1 cannot proceed with the call to "Flush non-trx changes" because it will block in the mutex "LOCK_log" and by consequence cannot complete the execution and call the unlog to decrease the prepared_xids. To fix the problem, we ensure that the non-trx changes are always flushed before the trx changes. Note that if you call "Flush non-trx changes" and a concurrent "FLUSH logs" is issued, the "Flush non-trx changes" may block, but a deadlock will never happen because the prepared_xids will eventually get to zero. Bottom line, there will not be any transaction able to increase the prepared_xids because they will block in the mutex "LOCK_log" (MYSQL_BIN_LOG::write) and those that increased the prepared_xids will eventually commit and decrease the prepared_xids.
1 parent 8e1d1e4 commit a0946fa

File tree

7 files changed

+102
-101
lines changed

7 files changed

+102
-101
lines changed

‎mysql-test/suite/binlog/r/binlog_innodb.result

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -123,7 +123,7 @@ Binlog_cache_disk_use 0
123123
create table t1 (a int) engine=innodb;
124124
show status like "binlog_cache_use";
125125
Variable_name Value
126-
Binlog_cache_use 1
126+
Binlog_cache_use 2
127127
show status like "binlog_cache_disk_use";
128128
Variable_name Value
129129
Binlog_cache_disk_use 1
@@ -132,7 +132,7 @@ delete from t1;
132132
commit;
133133
show status like "binlog_cache_use";
134134
Variable_name Value
135-
Binlog_cache_use 2
135+
Binlog_cache_use 4
136136
show status like "binlog_cache_disk_use";
137137
Variable_name Value
138138
Binlog_cache_disk_use 1

‎mysql-test/suite/binlog/r/binlog_mix_innodb_stat.result

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -9,7 +9,7 @@ drop table if exists t1;
99
create table t1 (a int) engine=innodb;
1010
show status like "binlog_cache_use";
1111
Variable_name Value
12-
Binlog_cache_use 1
12+
Binlog_cache_use 2
1313
show status like "binlog_cache_disk_use";
1414
Variable_name Value
1515
Binlog_cache_disk_use 1
@@ -18,7 +18,7 @@ delete from t1;
1818
commit;
1919
show status like "binlog_cache_use";
2020
Variable_name Value
21-
Binlog_cache_use 2
21+
Binlog_cache_use 4
2222
show status like "binlog_cache_disk_use";
2323
Variable_name Value
2424
Binlog_cache_disk_use 1

‎mysql-test/suite/binlog/r/binlog_row_innodb_stat.result

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -9,7 +9,7 @@ drop table if exists t1;
99
create table t1 (a int) engine=innodb;
1010
show status like "binlog_cache_use";
1111
Variable_name Value
12-
Binlog_cache_use 1
12+
Binlog_cache_use 2
1313
show status like "binlog_cache_disk_use";
1414
Variable_name Value
1515
Binlog_cache_disk_use 1
@@ -18,7 +18,7 @@ delete from t1;
1818
commit;
1919
show status like "binlog_cache_use";
2020
Variable_name Value
21-
Binlog_cache_use 2
21+
Binlog_cache_use 4
2222
show status like "binlog_cache_disk_use";
2323
Variable_name Value
2424
Binlog_cache_disk_use 1

‎mysql-test/suite/binlog/r/binlog_stm_innodb_stat.result

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -9,7 +9,7 @@ drop table if exists t1;
99
create table t1 (a int) engine=innodb;
1010
show status like "binlog_cache_use";
1111
Variable_name Value
12-
Binlog_cache_use 1
12+
Binlog_cache_use 2
1313
show status like "binlog_cache_disk_use";
1414
Variable_name Value
1515
Binlog_cache_disk_use 1
@@ -18,7 +18,7 @@ delete from t1;
1818
commit;
1919
show status like "binlog_cache_use";
2020
Variable_name Value
21-
Binlog_cache_use 2
21+
Binlog_cache_use 4
2222
show status like "binlog_cache_disk_use";
2323
Variable_name Value
2424
Binlog_cache_disk_use 1

‎mysql-test/suite/rpl/r/rpl_mixed_mixing_engines.result

Lines changed: 46 additions & 46 deletions
Original file line numberDiff line numberDiff line change
@@ -425,70 +425,76 @@ master-bin.000001 # Xid # # COMMIT /* XID */
425425
UPDATE nt_3, tt_3 SET nt_3.info= "new text 25 --> 1", tt_3.info= "new text 25 --> 1" where nt_3.trans_id = tt_3.trans_id and tt_3.trans_id = 1;
426426
Log_name Pos Event_type Server_id End_log_pos Info
427427
master-bin.000001 # Query # # BEGIN
428-
master-bin.000001 # Table_map # # table_id: # (test.tt_3)
429-
master-bin.000001 # Update_rows # # table_id: # flags: STMT_END_F
430-
master-bin.000001 # Xid # # COMMIT /* XID */
431-
master-bin.000001 # Query # # BEGIN
432428
master-bin.000001 # Table_map # # table_id: # (test.nt_3)
433429
master-bin.000001 # Update_rows # # table_id: # flags: STMT_END_F
434430
master-bin.000001 # Query # # COMMIT
435-
-e-e-e-e-e-e-e-e-e-e-e- >> NT << -e-e-e-e-e-e-e-e-e-e-e-
436-
-b-b-b-b-b-b-b-b-b-b-b- >> NT << -b-b-b-b-b-b-b-b-b-b-b-
437-
Log_name Pos Event_type Server_id End_log_pos Info
438431
master-bin.000001 # Query # # BEGIN
439432
master-bin.000001 # Table_map # # table_id: # (test.tt_3)
440433
master-bin.000001 # Update_rows # # table_id: # flags: STMT_END_F
441434
master-bin.000001 # Xid # # COMMIT /* XID */
435+
-e-e-e-e-e-e-e-e-e-e-e- >> NT << -e-e-e-e-e-e-e-e-e-e-e-
436+
-b-b-b-b-b-b-b-b-b-b-b- >> NT << -b-b-b-b-b-b-b-b-b-b-b-
437+
Log_name Pos Event_type Server_id End_log_pos Info
442438
master-bin.000001 # Query # # BEGIN
443439
master-bin.000001 # Table_map # # table_id: # (test.nt_3)
444440
master-bin.000001 # Update_rows # # table_id: # flags: STMT_END_F
445441
master-bin.000001 # Query # # COMMIT
442+
master-bin.000001 # Query # # BEGIN
443+
master-bin.000001 # Table_map # # table_id: # (test.tt_3)
444+
master-bin.000001 # Update_rows # # table_id: # flags: STMT_END_F
445+
master-bin.000001 # Xid # # COMMIT /* XID */
446446
-e-e-e-e-e-e-e-e-e-e-e- >> NT << -e-e-e-e-e-e-e-e-e-e-e-
447447

448448
-b-b-b-b-b-b-b-b-b-b-b- >> NT-trig << -b-b-b-b-b-b-b-b-b-b-b-
449449
INSERT INTO nt_4(trans_id, stmt_id) VALUES (26, 1);
450450
Log_name Pos Event_type Server_id End_log_pos Info
451451
master-bin.000001 # Query # # BEGIN
452-
master-bin.000001 # Table_map # # table_id: # (test.tt_4)
453-
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
454-
master-bin.000001 # Xid # # COMMIT /* XID */
455-
master-bin.000001 # Query # # BEGIN
456452
master-bin.000001 # Table_map # # table_id: # (test.nt_4)
457453
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
458454
master-bin.000001 # Query # # COMMIT
459-
-e-e-e-e-e-e-e-e-e-e-e- >> NT-trig << -e-e-e-e-e-e-e-e-e-e-e-
460-
-b-b-b-b-b-b-b-b-b-b-b- >> NT-trig << -b-b-b-b-b-b-b-b-b-b-b-
461-
Log_name Pos Event_type Server_id End_log_pos Info
462455
master-bin.000001 # Query # # BEGIN
463456
master-bin.000001 # Table_map # # table_id: # (test.tt_4)
464457
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
465458
master-bin.000001 # Xid # # COMMIT /* XID */
459+
-e-e-e-e-e-e-e-e-e-e-e- >> NT-trig << -e-e-e-e-e-e-e-e-e-e-e-
460+
-b-b-b-b-b-b-b-b-b-b-b- >> NT-trig << -b-b-b-b-b-b-b-b-b-b-b-
461+
Log_name Pos Event_type Server_id End_log_pos Info
466462
master-bin.000001 # Query # # BEGIN
467463
master-bin.000001 # Table_map # # table_id: # (test.nt_4)
468464
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
469465
master-bin.000001 # Query # # COMMIT
466+
master-bin.000001 # Query # # BEGIN
467+
master-bin.000001 # Table_map # # table_id: # (test.tt_4)
468+
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
469+
master-bin.000001 # Xid # # COMMIT /* XID */
470470
-e-e-e-e-e-e-e-e-e-e-e- >> NT-trig << -e-e-e-e-e-e-e-e-e-e-e-
471471

472472
-b-b-b-b-b-b-b-b-b-b-b- >> NT-func << -b-b-b-b-b-b-b-b-b-b-b-
473473
INSERT INTO nt_5(trans_id, stmt_id, info) VALUES (27, 1, fc_i_tt_5_suc(27, 1));
474474
Log_name Pos Event_type Server_id End_log_pos Info
475475
master-bin.000001 # Query # # BEGIN
476+
master-bin.000001 # Table_map # # table_id: # (test.nt_5)
477+
master-bin.000001 # Table_map # # table_id: # (test.nt_6)
478+
master-bin.000001 # Write_rows # # table_id: #
479+
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
480+
master-bin.000001 # Query # # COMMIT
481+
master-bin.000001 # Query # # BEGIN
476482
master-bin.000001 # Table_map # # table_id: # (test.tt_5)
477483
master-bin.000001 # Table_map # # table_id: # (test.tt_6)
478484
master-bin.000001 # Write_rows # # table_id: #
479485
master-bin.000001 # Write_rows # # table_id: #
480486
master-bin.000001 # Write_rows # # table_id: #
481487
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
482488
master-bin.000001 # Xid # # COMMIT /* XID */
489+
-e-e-e-e-e-e-e-e-e-e-e- >> NT-func << -e-e-e-e-e-e-e-e-e-e-e-
490+
-b-b-b-b-b-b-b-b-b-b-b- >> NT-func << -b-b-b-b-b-b-b-b-b-b-b-
491+
Log_name Pos Event_type Server_id End_log_pos Info
483492
master-bin.000001 # Query # # BEGIN
484493
master-bin.000001 # Table_map # # table_id: # (test.nt_5)
485494
master-bin.000001 # Table_map # # table_id: # (test.nt_6)
486495
master-bin.000001 # Write_rows # # table_id: #
487496
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
488497
master-bin.000001 # Query # # COMMIT
489-
-e-e-e-e-e-e-e-e-e-e-e- >> NT-func << -e-e-e-e-e-e-e-e-e-e-e-
490-
-b-b-b-b-b-b-b-b-b-b-b- >> NT-func << -b-b-b-b-b-b-b-b-b-b-b-
491-
Log_name Pos Event_type Server_id End_log_pos Info
492498
master-bin.000001 # Query # # BEGIN
493499
master-bin.000001 # Table_map # # table_id: # (test.tt_5)
494500
master-bin.000001 # Table_map # # table_id: # (test.tt_6)
@@ -497,88 +503,76 @@ master-bin.000001 # Write_rows # # table_id: #
497503
master-bin.000001 # Write_rows # # table_id: #
498504
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
499505
master-bin.000001 # Xid # # COMMIT /* XID */
500-
master-bin.000001 # Query # # BEGIN
501-
master-bin.000001 # Table_map # # table_id: # (test.nt_5)
502-
master-bin.000001 # Table_map # # table_id: # (test.nt_6)
503-
master-bin.000001 # Write_rows # # table_id: #
504-
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
505-
master-bin.000001 # Query # # COMMIT
506506
-e-e-e-e-e-e-e-e-e-e-e- >> NT-func << -e-e-e-e-e-e-e-e-e-e-e-
507507

508508
-b-b-b-b-b-b-b-b-b-b-b- >> TN << -b-b-b-b-b-b-b-b-b-b-b-
509509
UPDATE tt_4, nt_4 SET tt_4.info= "new text 28 --> 1", nt_4.info= "new text 28 --> 1" where nt_4.trans_id = tt_4.trans_id and tt_4.trans_id = 1;
510510
Log_name Pos Event_type Server_id End_log_pos Info
511511
master-bin.000001 # Query # # BEGIN
512-
master-bin.000001 # Table_map # # table_id: # (test.tt_4)
513-
master-bin.000001 # Update_rows # # table_id: # flags: STMT_END_F
514-
master-bin.000001 # Xid # # COMMIT /* XID */
515-
master-bin.000001 # Query # # BEGIN
516512
master-bin.000001 # Table_map # # table_id: # (test.nt_4)
517513
master-bin.000001 # Update_rows # # table_id: # flags: STMT_END_F
518514
master-bin.000001 # Query # # COMMIT
519-
-e-e-e-e-e-e-e-e-e-e-e- >> TN << -e-e-e-e-e-e-e-e-e-e-e-
520-
-b-b-b-b-b-b-b-b-b-b-b- >> TN << -b-b-b-b-b-b-b-b-b-b-b-
521-
Log_name Pos Event_type Server_id End_log_pos Info
522515
master-bin.000001 # Query # # BEGIN
523516
master-bin.000001 # Table_map # # table_id: # (test.tt_4)
524517
master-bin.000001 # Update_rows # # table_id: # flags: STMT_END_F
525518
master-bin.000001 # Xid # # COMMIT /* XID */
519+
-e-e-e-e-e-e-e-e-e-e-e- >> TN << -e-e-e-e-e-e-e-e-e-e-e-
520+
-b-b-b-b-b-b-b-b-b-b-b- >> TN << -b-b-b-b-b-b-b-b-b-b-b-
521+
Log_name Pos Event_type Server_id End_log_pos Info
526522
master-bin.000001 # Query # # BEGIN
527523
master-bin.000001 # Table_map # # table_id: # (test.nt_4)
528524
master-bin.000001 # Update_rows # # table_id: # flags: STMT_END_F
529525
master-bin.000001 # Query # # COMMIT
526+
master-bin.000001 # Query # # BEGIN
527+
master-bin.000001 # Table_map # # table_id: # (test.tt_4)
528+
master-bin.000001 # Update_rows # # table_id: # flags: STMT_END_F
529+
master-bin.000001 # Xid # # COMMIT /* XID */
530530
-e-e-e-e-e-e-e-e-e-e-e- >> TN << -e-e-e-e-e-e-e-e-e-e-e-
531531

532532
-b-b-b-b-b-b-b-b-b-b-b- >> TN-trig << -b-b-b-b-b-b-b-b-b-b-b-
533533
INSERT INTO tt_3(trans_id, stmt_id) VALUES (29, 1);
534534
Log_name Pos Event_type Server_id End_log_pos Info
535535
master-bin.000001 # Query # # BEGIN
536-
master-bin.000001 # Table_map # # table_id: # (test.tt_3)
537-
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
538-
master-bin.000001 # Xid # # COMMIT /* XID */
539-
master-bin.000001 # Query # # BEGIN
540536
master-bin.000001 # Table_map # # table_id: # (test.nt_3)
541537
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
542538
master-bin.000001 # Query # # COMMIT
543-
-e-e-e-e-e-e-e-e-e-e-e- >> TN-trig << -e-e-e-e-e-e-e-e-e-e-e-
544-
-b-b-b-b-b-b-b-b-b-b-b- >> TN-trig << -b-b-b-b-b-b-b-b-b-b-b-
545-
Log_name Pos Event_type Server_id End_log_pos Info
546539
master-bin.000001 # Query # # BEGIN
547540
master-bin.000001 # Table_map # # table_id: # (test.tt_3)
548541
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
549542
master-bin.000001 # Xid # # COMMIT /* XID */
543+
-e-e-e-e-e-e-e-e-e-e-e- >> TN-trig << -e-e-e-e-e-e-e-e-e-e-e-
544+
-b-b-b-b-b-b-b-b-b-b-b- >> TN-trig << -b-b-b-b-b-b-b-b-b-b-b-
545+
Log_name Pos Event_type Server_id End_log_pos Info
550546
master-bin.000001 # Query # # BEGIN
551547
master-bin.000001 # Table_map # # table_id: # (test.nt_3)
552548
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
553549
master-bin.000001 # Query # # COMMIT
550+
master-bin.000001 # Query # # BEGIN
551+
master-bin.000001 # Table_map # # table_id: # (test.tt_3)
552+
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
553+
master-bin.000001 # Xid # # COMMIT /* XID */
554554
-e-e-e-e-e-e-e-e-e-e-e- >> TN-trig << -e-e-e-e-e-e-e-e-e-e-e-
555555

556556
-b-b-b-b-b-b-b-b-b-b-b- >> TN-func << -b-b-b-b-b-b-b-b-b-b-b-
557557
INSERT INTO tt_5(trans_id, stmt_id, info) VALUES (30, 1, fc_i_nt_5_suc(30, 1));
558558
Log_name Pos Event_type Server_id End_log_pos Info
559559
master-bin.000001 # Query # # BEGIN
560-
master-bin.000001 # Table_map # # table_id: # (test.tt_5)
561-
master-bin.000001 # Table_map # # table_id: # (test.tt_6)
562-
master-bin.000001 # Write_rows # # table_id: #
563-
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
564-
master-bin.000001 # Xid # # COMMIT /* XID */
565-
master-bin.000001 # Query # # BEGIN
566560
master-bin.000001 # Table_map # # table_id: # (test.nt_5)
567561
master-bin.000001 # Table_map # # table_id: # (test.nt_6)
568562
master-bin.000001 # Write_rows # # table_id: #
569563
master-bin.000001 # Write_rows # # table_id: #
570564
master-bin.000001 # Write_rows # # table_id: #
571565
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
572566
master-bin.000001 # Query # # COMMIT
573-
-e-e-e-e-e-e-e-e-e-e-e- >> TN-func << -e-e-e-e-e-e-e-e-e-e-e-
574-
-b-b-b-b-b-b-b-b-b-b-b- >> TN-func << -b-b-b-b-b-b-b-b-b-b-b-
575-
Log_name Pos Event_type Server_id End_log_pos Info
576567
master-bin.000001 # Query # # BEGIN
577568
master-bin.000001 # Table_map # # table_id: # (test.tt_5)
578569
master-bin.000001 # Table_map # # table_id: # (test.tt_6)
579570
master-bin.000001 # Write_rows # # table_id: #
580571
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
581572
master-bin.000001 # Xid # # COMMIT /* XID */
573+
-e-e-e-e-e-e-e-e-e-e-e- >> TN-func << -e-e-e-e-e-e-e-e-e-e-e-
574+
-b-b-b-b-b-b-b-b-b-b-b- >> TN-func << -b-b-b-b-b-b-b-b-b-b-b-
575+
Log_name Pos Event_type Server_id End_log_pos Info
582576
master-bin.000001 # Query # # BEGIN
583577
master-bin.000001 # Table_map # # table_id: # (test.nt_5)
584578
master-bin.000001 # Table_map # # table_id: # (test.nt_6)
@@ -587,6 +581,12 @@ master-bin.000001 # Write_rows # # table_id: #
587581
master-bin.000001 # Write_rows # # table_id: #
588582
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
589583
master-bin.000001 # Query # # COMMIT
584+
master-bin.000001 # Query # # BEGIN
585+
master-bin.000001 # Table_map # # table_id: # (test.tt_5)
586+
master-bin.000001 # Table_map # # table_id: # (test.tt_6)
587+
master-bin.000001 # Write_rows # # table_id: #
588+
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
589+
master-bin.000001 # Xid # # COMMIT /* XID */
590590
-e-e-e-e-e-e-e-e-e-e-e- >> TN-func << -e-e-e-e-e-e-e-e-e-e-e-
591591

592592

0 commit comments

Comments
 (0)