Bug #101717 | Poor performance on a GTID slave when log_slave_updates is disabled | ||
---|---|---|---|
Submitted: | 23 Nov 2020 12:03 | Modified: | 11 Dec 2020 5:23 |
Reporter: | Venkatesh Prasad Venugopal (OCA) | Email Updates: | |
Status: | Verified | Impact on me: | |
Category: | MySQL Server: Replication | Severity: | S2 (Serious) |
Version: | 8.0, 8.0.22 | OS: | Any |
Assigned to: | CPU Architecture: | Any | |
Tags: | Clone, regression, rpl |
[23 Nov 2020 12:03]
Venkatesh Prasad Venugopal
[23 Nov 2020 12:41]
Venkatesh Prasad Venugopal
Here is a small comparision of how much time the server takes to update the `previous_gtid_logged` in `update_prev_gtids()` in different scenarios 1. Time taken by the `update_prev_gtids()` with log-bin=1 and log-slave-updates=1 (printing the average of every 1000 calls) ===BEGIN=== [DEBUG] Average of last 1000 calls = 128 microseconds [DEBUG] Average of last 1000 calls = 108 microseconds [DEBUG] Average of last 1000 calls = 111 microseconds [DEBUG] Average of last 1000 calls = 108 microseconds [DEBUG] Average of last 1000 calls = 105 microseconds [DEBUG] Average of last 1000 calls = 104 microseconds [DEBUG] Average of last 1000 calls = 105 microseconds [DEBUG] Average of last 1000 calls = 106 microseconds [DEBUG] Average of last 1000 calls = 113 microseconds [DEBUG] Average of last 1000 calls = 108 microseconds [DEBUG] Average of last 1000 calls = 106 microseconds [DEBUG] Average of last 1000 calls = 104 microseconds [DEBUG] Average of last 1000 calls = 109 microseconds [DEBUG] Average of last 1000 calls = 112 microseconds [DEBUG] Average of last 1000 calls = 115 microseconds [DEBUG] Average of last 1000 calls = 112 microseconds [DEBUG] Average of last 1000 calls = 100 microseconds [DEBUG] Average of last 1000 calls = 93 microseconds [DEBUG] Average of last 1000 calls = 94 microseconds [DEBUG] Average of last 1000 calls = 98 microseconds [DEBUG] Average of last 1000 calls = 91 microseconds [DEBUG] Average of last 1000 calls = 95 microseconds [DEBUG] Average of last 1000 calls = 97 microseconds [DEBUG] Average of last 1000 calls = 97 microseconds [DEBUG] Average of last 1000 calls = 99 microseconds [DEBUG] Average of last 1000 calls = 100 microseconds [DEBUG] Average of last 1000 calls = 94 microseconds [DEBUG] Average of last 1000 calls = 102 microseconds ===END=== 2. Time taken by the `update_prev_gtids()` with log-bin=1 and log-slave-updates=0 (printing the average of every 1000 calls) ===BEGIN=== [DEBUG] Average of last 1000 calls = 205 microseconds [DEBUG] Average of last 1000 calls = 577 microseconds [DEBUG] Average of last 1000 calls = 917 microseconds [DEBUG] Average of last 1000 calls = 1250 microseconds [DEBUG] Average of last 1000 calls = 1650 microseconds [DEBUG] Average of last 1000 calls = 1984 microseconds [DEBUG] Average of last 1000 calls = 2377 microseconds [DEBUG] Average of last 1000 calls = 2843 microseconds [DEBUG] Average of last 1000 calls = 3218 microseconds [DEBUG] Average of last 1000 calls = 3813 microseconds [DEBUG] Average of last 1000 calls = 4179 microseconds [DEBUG] Average of last 1000 calls = 4746 microseconds [DEBUG] Average of last 1000 calls = 4938 microseconds [DEBUG] Average of last 1000 calls = 5528 microseconds [DEBUG] Average of last 1000 calls = 6339 microseconds [DEBUG] Average of last 1000 calls = 6446 microseconds [DEBUG] Average of last 1000 calls = 7013 microseconds [DEBUG] Average of last 1000 calls = 7489 microseconds [DEBUG] Average of last 1000 calls = 8246 microseconds [DEBUG] Average of last 1000 calls = 9053 microseconds [DEBUG] Average of last 1000 calls = 9830 microseconds [DEBUG] Average of last 1000 calls = 10464 microseconds [DEBUG] Average of last 1000 calls = 11233 microseconds [DEBUG] Average of last 1000 calls = 11800 microseconds [DEBUG] Average of last 1000 calls = 12671 microseconds ===END===
[23 Nov 2020 12:47]
Venkatesh Prasad Venugopal
Error logs with debug prints of previous_gtids_logged in update_prev_gtids()
Attachment: Bug101717_slave_error_logs.txt (text/plain), 528.83 KiB.
[24 Nov 2020 6:50]
MySQL Verification Team
Hello Venu, Thank you for the report and feedback. Could you please share exact cmake options used for the build(or I can use the same build from Bug #100118?), any patch etc required for step (5) in your how to repeat ? Thank you. regards, Umesh
[25 Nov 2020 7:00]
Venkatesh Prasad Venugopal
Testcase to repeat the bug
Attachment: 0001-Bug-101717-Testcase-to-repeat-the-bug.patch (text/x-patch), 6.39 KiB.
[25 Nov 2020 7:23]
Venkatesh Prasad Venugopal
Hi Umesh, Yes, you can use the same build from Bug #100118. Steps: 1. Apply the atached patch (0001-Bug-101717-Testcase-to-repeat-the-bug.patch) on the 8.0.22 code. 2. Build the server. I used cmake -DBUILD_CONFIG=mysql_release -DWITH_BOOST=$HOME/utilities/boost/ -DCMAKE_BUILD_TYPE=debug -DWITH_UNIT_TESTS=OFF -DWITH_ROUTER=OFF ../ 3. Run the `rpl_gtid_bug_101717.test` MTR testcase. 4. Check slave's error logs (var/log/mysqld.2.err) for the debug prints. 5. Execute grep "Average of" var/log/mysqld.2.err for the details of the average time taken by the `update_prev_gtids()` function when the test progressed. Regards, Venkatesh
[25 Nov 2020 7:24]
MySQL Verification Team
Thank you Venu for the requested details, I'll get back to you if anything further needed. Thank you!
[25 Nov 2020 9:35]
MySQL Verification Team
Thank you Venu, on a medium-large test box I'm seeing this: - grep "Average of" var/log/mysqld.2.err [DEBUG] Average of last 100 calls = 78 microseconds [DEBUG] Average of last 100 calls = 139 microseconds [DEBUG] Average of last 100 calls = 188 microseconds [DEBUG] Average of last 100 calls = 250 microseconds [DEBUG] Average of last 100 calls = 317 microseconds [DEBUG] Average of last 100 calls = 374 microseconds [DEBUG] Average of last 100 calls = 418 microseconds [DEBUG] Average of last 100 calls = 491 microseconds [DEBUG] Average of last 100 calls = 530 microseconds [DEBUG] Average of last 100 calls = 629 microseconds [DEBUG] Average of last 100 calls = 974 microseconds [DEBUG] Average of last 100 calls = 736 microseconds [DEBUG] Average of last 100 calls = 823 microseconds [DEBUG] Average of last 100 calls = 884 microseconds [DEBUG] Average of last 100 calls = 876 microseconds [DEBUG] Average of last 100 calls = 993 microseconds [DEBUG] Average of last 100 calls = 1076 microseconds [DEBUG] Average of last 100 calls = 1089 microseconds [DEBUG] Average of last 100 calls = 1150 microseconds [DEBUG] Average of last 100 calls = 1218 microseconds [DEBUG] Average of last 100 calls = 1301 microseconds [DEBUG] Average of last 100 calls = 1373 microseconds [DEBUG] Average of last 100 calls = 1422 microseconds [DEBUG] Average of last 100 calls = 1660 microseconds [DEBUG] Average of last 100 calls = 1576 microseconds [DEBUG] Average of last 100 calls = 1628 microseconds [DEBUG] Average of last 100 calls = 1622 microseconds [DEBUG] Average of last 100 calls = 1759 microseconds [DEBUG] Average of last 100 calls = 1840 microseconds [DEBUG] Average of last 100 calls = 1868 microseconds [DEBUG] Average of last 100 calls = 2603 microseconds [DEBUG] Average of last 100 calls = 2004 microseconds [DEBUG] Average of last 100 calls = 2025 microseconds [DEBUG] Average of last 100 calls = 2051 microseconds [DEBUG] Average of last 100 calls = 2088 microseconds [DEBUG] Average of last 100 calls = 2240 microseconds [DEBUG] Average of last 100 calls = 2262 microseconds [DEBUG] Average of last 100 calls = 2364 microseconds [DEBUG] Average of last 100 calls = 2354 microseconds [DEBUG] Average of last 100 calls = 2526 microseconds [DEBUG] Average of last 100 calls = 2475 microseconds [DEBUG] Average of last 100 calls = 2604 microseconds [DEBUG] Average of last 100 calls = 2682 microseconds [DEBUG] Average of last 100 calls = 3238 microseconds [DEBUG] Average of last 100 calls = 2792 microseconds [DEBUG] Average of last 100 calls = 2789 microseconds [DEBUG] Average of last 100 calls = 2848 microseconds [DEBUG] Average of last 100 calls = 2903 microseconds [DEBUG] Average of last 100 calls = 2964 microseconds regards, Umesh
[8 Dec 2020 10:35]
Yakir Gibraltar
I'm able to reproduce the issue also with log_slave_updates and log_bin disabled: ``` abc625:(none)> select @@log_slave_updates, @@log_bin; +---------------------+-----------+ | @@log_slave_updates | @@log_bin | +---------------------+-----------+ | 0 | 0 | +---------------------+-----------+ 1 row in set (0.00 sec) abc625:(none)> select format(count(0),0) from mysql.gtid_executed; +--------------------+ | format(count(0),0) | +--------------------+ | 31,335,250 | +--------------------+ 1 row in set (5.55 sec) ``` And restart to MySQL failed: [ERROR] [MY-011975] [InnoDB] Wait for GTID thread to start timed out Thank you, Yakir.
[10 Dec 2020 18:34]
Pedro Figueiredo
Posted by developer: Hi! This bug is a duplicate of bug #101717 / #31599938 Tried to reproduce the issue against 8.0.23 and the result of the script to reproduce was: [DEBUG] Average of last 100 calls = 25 microseconds [DEBUG] Average of last 100 calls = 28 microseconds Thank you for your time. Regards,
[11 Dec 2020 5:23]
Venkatesh Prasad Venugopal
Hi Pedro, Do you mean that the issue is fixed in 8.0.23? Was it fixed as part of another bug? Thank you,
[15 Dec 2020 12:53]
Pedro Figueiredo
Posted by developer: Hi! Mixed up the bug numbers, the above issue was fixed as part of bug #100118 Thank you for your time. Regards,