threads=20
log_write_up_to calls = 375 744
catchup time: 624.609522 sec.
Slave without the tracing code (for comparison)
sysbench on master: 145,089 transactions
catchup time: 592.940083
There are many more log_write_up_to calls than transactions
Sergei Petrunia
added a comment - Debugging InnoDB on 10.2
Master
sysbench: 151 676 transactions
Binlog_commits += 151 676
Binlog_commit_groups += 95 717
Slave (debug build):
threads=20
log_write_up_to calls = 375 744
catchup time: 624.609522 sec.
Slave without the tracing code (for comparison)
sysbench on master: 145,089 transactions
catchup time: 592.940083
There are many more log_write_up_to calls than transactions
Using the same test setup as before (145K transactions, slave with slave_parallel_workers=20, _mode=conservative, NO log-slave-updates) to look at which code in innobase_commit executes in parallel:
This piece of code is executed by one thread at a time :
/* Run the fast part of commit if we did not already. */
if (!trx_is_active_commit_ordered(trx)) {
innobase_commit_ordered_2(trx, thd);
}
/* We were instructed to commit the whole transaction, or
this is an SQL statement end and autocommit is on */
/* At this point commit order is fixed and transaction is
visible to others. So we can wakeup other commits waiting for
this one, to allow then to group commit with us. */
histogram:
n_active histogram= {
0, 0
1, 145158
2, 0
3, 0
...
while this part of code runs in parallel, most likely due to the first call it is making:
thd_wakeup_subsequent_commits(thd, 0);
/* Now do a write + flush of logs. */
trx_commit_complete_for_mysql(trx);
trx_deregister_from_2pc(trx);
} else {
histogram:
n_active histogram= {
0, 0
1, 39488
2, 29460
3, 20922
4, 14941
5, 10823
6, 7922
7, 5884
8, 4360
9, 3136
10, 2266
11, 1659
12, 1234
13, 880
14, 632
15, 479
16, 360
17, 275
18, 212
19, 150
20, 75
21, 0
22, 0
23, 0
...
}
Sergei Petrunia
added a comment - - edited Using the same test setup as before (145K transactions, slave with slave_parallel_workers=20, _mode=conservative, NO log-slave-updates ) to look at which code in innobase_commit executes in parallel:
This piece of code is executed by one thread at a time :
if (commit_trx
|| (!thd_test_options(thd, OPTION_NOT_AUTOCOMMIT | OPTION_BEGIN))) {
DBUG_EXECUTE_IF( "crash_innodb_before_commit" ,
DBUG_SUICIDE(););
/* Run the fast part of commit if we did not already. */
if (!trx_is_active_commit_ordered(trx)) {
innobase_commit_ordered_2(trx, thd);
}
/* We were instructed to commit the whole transaction, or
this is an SQL statement end and autocommit is on */
/* At this point commit order is fixed and transaction is
visible to others. So we can wakeup other commits waiting for
this one, to allow then to group commit with us. */
histogram:
n_active histogram= {
0, 0
1, 145158
2, 0
3, 0
...
while this part of code runs in parallel, most likely due to the first call it is making:
thd_wakeup_subsequent_commits(thd, 0);
/* Now do a write + flush of logs. */
trx_commit_complete_for_mysql(trx);
trx_deregister_from_2pc(trx);
} else {
histogram:
n_active histogram= {
0, 0
1, 39488
2, 29460
3, 20922
4, 14941
5, 10823
6, 7922
7, 5884
8, 4360
9, 3136
10, 2266
11, 1659
12, 1234
13, 880
14, 632
15, 479
16, 360
17, 275
18, 212
19, 150
20, 75
21, 0
22, 0
23, 0
...
}
Filed MDEV-15372: Parallel slave speedup very limited when log_slave_updates=OFF, now testing a fix for it.
Sergei Petrunia
added a comment - - edited Filed MDEV-15372 : Parallel slave speedup very limited when log_slave_updates=OFF , now testing a fix for it.
Debugging InnoDB on 10.2
Master
sysbench: 151 676 transactions
Binlog_commits += 151 676
Binlog_commit_groups += 95 717
Slave (debug build):
threads=20
log_write_up_to calls = 375 744
catchup time: 624.609522 sec.
Slave without the tracing code (for comparison)
sysbench on master: 145,089 transactions
catchup time: 592.940083
There are many more log_write_up_to calls than transactions