I noticed reduced performance numbers when running somewhat large update_no_index sysbench benchmark, when comparing 10.2 to 10.3
Here is the setup
- Windows Azure VMwith 16 virtual CPUs, 32GB RAM and SSD storage (I used Local temporary disk)
Intel(R) Xeon(R) CPU E5-2673 v4 @ 2.30GHz
Sockets: 1
Virtual processors: 16
- MariaDB 10.2.14 vs 10.3.7 (recent build of 4a5e23e257e229b548599133dbed5162af9df6d9)
the relevant part of my.ini file is as follows
[mysqld]
|
back_log=500
|
max_connections=4096
|
max_prepared_stmt_count=500000
|
table_open_cache=10000
|
transaction_isolation=REPEATABLE-READ
|
innodb_status_file=0
|
innodb_buffer_pool_size=20G
|
innodb_log_file_size=15G
|
innodb_log_buffer_size=1000M
|
innodb-io-capacity=4000
|
innodb-io-capacity-max=5000
|
innodb_doublewrite=0
|
innodb-page-cleaners=1
|
innodb-buffer-pool-instances=1
|
innodb_adaptive_flushing=0
|
innodb_adaptive_flushing_lwm=10
|
- sysbench 0.4 (I mention it because current versions of sysbench do not run on Windows anymore, but we do not need anything from the current versions)
The update-no-index run on a single large table (50 mio rows), with number of users ranging from 1 to 4096, in powers of 2
Loading table, sysbench prepare
sysbench --test=oltp --oltp-table-size=50000000 --mysql-host=localhost --mysql-db=sbtest --mysql-user=root --mysql-password= --db-driver=mysql --mysql-table-engine=innodb --max-time=300 --oltp-test-mode=complex --oltp-read-only=off --max-requests=0 --oltp-point-selects=0 --oltp-simple-ranges=0 --oltp-sum-ranges=0 --oltp-order-ranges=0 --oltp-distinct-ranges=0 --oltp-index-updates=0 --oltp-delete-inserts=0 --oltp-non-index-updates=1 --oltp-skip-trx=on --oltp-dist-type=uniform --mysql-socket=MySQL --num-threads=1 prepare
|
sysbench run
sysbench --test=oltp --oltp-table-size=50000000 --mysql-host=localhost --mysql-db=sbtest --mysql-user=root --mysql-password= --db-driver=mysql --mysql-table-engine=innodb --max-time=300 --oltp-test-mode=complex --oltp-read-only=off --max-requests=0 --oltp-point-selects=0 --oltp-simple-ranges=0 --oltp-sum-ranges=0 --oltp-order-ranges=0 --oltp-distinct-ranges=0 --oltp-index-updates=0 --oltp-delete-inserts=0 --oltp-non-index-updates=1 --oltp-skip-trx=on --oltp-dist-type=uniform --mysql-socket=MySQL --num-threads=%N% run
|
where %N% is 1,2,4,8,16,32,64,128,256,512,1024,2048,4096
The test takes a nap of 80 seconds between runs, and also between load and first test, and as far as I can see it is enough for all Innodb backgroup IO activity to finish (MB/sec goes down to 0 on a disk where test is ran). Due to innodb-flush-log-at-trx-commit being default (1), the test does not appear to be very CPU bound (sysbench and mysql use 70% of all available 16 CPUs, in windows measurement, i.e over 10 CPUs are busy)
Below are the results from the runs, for 10.2.4 and recent 10.3.7
UPDATE: marko mentioned the git 1a62c8a39647db00283b4e35fb6db3c7bc31e3ca as the version right before 10.3 switched to lockless, so
I added a column for it too. It appears to be better than 10.3.7, but worse than 10.2.14
Users |
TPS 10.2.14 |
TPS 10.3.7 |
10.3-pre-lockless |
1 |
1549.92 |
1547.75 |
1551.07 |
2 |
2373.89 |
2209.05 |
2334.80 |
4 |
4466.03 |
4276.46 |
4446.64 |
8 |
9069.82 |
8587.59 |
9098.95 |
16 |
16631.45 |
15719.70 |
16231.39 |
32 |
28989.79 |
27482.44 |
27786.32 |
64 |
36996.12 |
34843.23 |
35089.44 |
128 |
37287.05 |
35172.49 |
36223.68 |
256 |
38038.01 |
35896.52 |
36818.22 |
512 |
38360.71 |
36567.07 |
37195.47 |
1024 |
38265.25 |
36328.62 |
37253.98 |
2048 |
39990.85 |
36328.62 |
38572.81 |
4096 |
41988.71 |
39032.83 |
39606.38 |
(also see the graph https://docs.google.com/spreadsheets/d/1VqRYCwF4QATCKEKwxKuCcvRXKm2GWnICCdv4fSo4_IU/edit#gid=0)
It is not as big as I thought initially (somehow I counted 15%, and it is more like 5%), but it is consistent starting from 64 users, and keeping until the 4K . So it needs investigating.
It is odd because the test itself is not CPU bound, nor IO bound, the bottleneck in my understanding is waiting for flush in log_write_up_to() . I did not try to make it CPU bound by relaxing durability, this might be another exercise, however with increased TPS purging can become more of a bottleneck, and disturb the picture.
I tried to do some initial profiling (based on CPU sampling), and this is what showed up.
Below., in all places, baseline refers to 10.2.14, and *comparison" is 10.3.7
Exclusive samples comparison
Individual functions (or, exclusive sample percentage with threshold 1% difference)
Comparison Column |
Delta |
Baseline Value |
Comparison Value |
ut_delay |
4.02 |
16.05 |
20.07 |
l_find |
2.44 |
0.16 |
2.60 |
PolicyMutex<TTASEventMutex<GenericPolicy> >::enter |
2.42 |
0.18 |
2.60 |
TTASEventMutex<GenericPolicy>::enter |
-4.42 |
4.42 |
0.00 |
SleepConditionVariableCS |
-5.41 |
28.70 |
23.29 |
In short, more busy wait ut_delay, less lazy wait SleepConditionVariableCS . There is a new quite visible function (4th most expensive individual functions now), l_find , which seems to come from replacing stl with custom hashtable in innodb.
Inclusive samples comparison
Comparing inclusive samples with 1% difference threshold, gives the below table, which gives me a vague idea that there something is more expensive in purge, and again that lazy wait was replaced with busy wait somewhere, background threads probably use more CPU , for example "coordinator" purge thread. foreground use less of it (as shown by decreased time in do_command for example)
Comparison Column |
Delta |
Baseline Value |
Comparison Value |
PolicyMutex<TTASEventMutex<GenericPolicy> >::enter |
28.69 |
2.53 |
31.22 |
ut_delay |
4.02 |
16.05 |
20.07 |
trx_purge |
3.81 |
5.67 |
9.48 |
srv_do_purge |
3.80 |
5.70 |
9.49 |
row_purge |
3.66 |
0.00 |
3.67 |
row_purge_step |
3.47 |
0.71 |
4.18 |
que_thr_step |
3.31 |
0.94 |
4.25 |
srv_purge_coordinator_thread |
3.25 |
6.37 |
9.63 |
trx_sys_t::clone_oldest_view |
3.18 |
0.00 |
3.18 |
btr_cur_search_to_nth_level_func |
3.12 |
0.00 |
3.12 |
row_purge_record_func |
2.94 |
0.00 |
2.94 |
row_purge_upd_exist_or_extern_func |
2.77 |
0.00 |
2.77 |
row_purge_reset_trx_id |
2.72 |
0.00 |
2.72 |
que_run_threads_low |
2.70 |
1.73 |
4.43 |
que_run_threads |
2.69 |
1.75 |
4.45 |
l_find |
2.46 |
0.18 |
2.64 |
ReadView::snapshot |
2.30 |
0.00 |
2.30 |
rw_trx_hash_t::iterate |
2.27 |
0.00 |
2.27 |
lf_hash_iterate |
2.25 |
0.00 |
2.25 |
srv_task_execute |
2.12 |
1.95 |
4.08 |
row_purge_reposition_pcur |
1.53 |
0.00 |
1.53 |
row_search_on_row_ref |
1.33 |
0.00 |
1.33 |
btr_pcur_open_low |
1.31 |
0.00 |
1.31 |
btr_search_guess_on_hash |
1.31 |
1.54 |
2.85 |
trx_purge_wait_for_workers_to_complete |
1.10 |
1.52 |
2.62 |
trx_undo_assign_low |
1.07 |
0.00 |
1.07 |
mtr_t::commit |
1.05 |
2.57 |
3.62 |
mtr_t::Command::execute |
1.01 |
2.42 |
3.43 |
srv_worker_thread |
-1.09 |
9.84 |
8.75 |
sync_array_wait_event |
-1.29 |
9.69 |
8.40 |
trx_write_serialisation_history |
-1.34 |
2.62 |
1.28 |
trx_commit_low |
-1.39 |
3.15 |
1.76 |
innobase_commit |
-1.75 |
47.36 |
45.61 |
trx_commit |
-1.75 |
4.79 |
3.04 |
ha_commit_one_phase |
-1.76 |
47.55 |
45.78 |
commit_one_phase_2 |
-1.76 |
47.54 |
45.77 |
trans_commit_stmt |
-1.80 |
48.68 |
46.88 |
ha_commit_trans |
-1.80 |
48.65 |
46.84 |
btr_cur_search_to_nth_level |
-1.85 |
1.85 |
0.00 |
innobase_commit_ordered_2 |
-2.04 |
5.17 |
3.13 |
trx_commit_for_mysql |
-2.05 |
5.10 |
3.05 |
innobase_commit_low |
-2.05 |
5.11 |
3.06 |
Prepared_statement::execute_loop |
-2.05 |
74.58 |
72.52 |
mysql_stmt_execute_common |
-2.14 |
74.85 |
72.71 |
mysqld_stmt_execute |
-2.15 |
74.89 |
72.74 |
mysql_execute_command |
-2.21 |
73.03 |
70.81 |
trx_undo_assign_undo |
-2.24 |
2.24 |
0.00 |
Prepared_statement::execute |
-2.24 |
74.03 |
71.79 |
threadpool_process_request |
-2.32 |
81.71 |
79.38 |
dispatch_command |
-2.33 |
79.21 |
76.88 |
do_command |
-2.34 |
81.33 |
79.00 |
tp_callback |
-2.38 |
82.66 |
80.28 |
srv_resume_thread |
-3.33 |
7.94 |
4.61 |
os_event::wait_low |
-4.98 |
28.41 |
23.43 |
SleepConditionVariableCS |
-5.41 |
28.70 |
23.29 |
TTASEventMutex<GenericPolicy>::enter |
-30.49 |
30.49 |
0.00 |
{"report":{"fcp":1496,"ttfb":400.7000000476837,"pageVisibility":"visible","entityId":67524,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":0.5,"journeyId":"45cb54a7-1af9-46fd-963f-9be463e8d216","navigationType":0,"readyForUser":1662.6000001430511,"redirectCount":0,"resourceLoadedEnd":1943.2000000476837,"resourceLoadedStart":408.60000014305115,"resourceTiming":[{"duration":396.59999990463257,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":408.60000014305115,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":408.60000014305115,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":805.2000000476837,"responseStart":0,"secureConnectionStart":0},{"duration":398.7999999523163,"initiatorType":"link","name":"https://jira.mariadb.org/s/7ebd35e77e471bc30ff0eba799ebc151-CDN/lu2cib/820016/12ta74/494e4c556ecbb29f90a3d3b4f09cb99c/_/download/contextbatch/css/jira.browse.project,project.issue.navigator,jira.view.issue,jira.general,jira.global,atl.general,-_super/batch.css?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&slack-enabled=true&whisper-enabled=true","startTime":408.90000009536743,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":408.90000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":807.7000000476837,"responseStart":0,"secureConnectionStart":0},{"duration":508.7000000476837,"initiatorType":"script","name":"https://jira.mariadb.org/s/0917945aaa57108d00c5076fea35e069-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":409.10000014305115,"connectEnd":409.10000014305115,"connectStart":409.10000014305115,"domainLookupEnd":409.10000014305115,"domainLookupStart":409.10000014305115,"fetchStart":409.10000014305115,"redirectEnd":0,"redirectStart":0,"requestStart":409.10000014305115,"responseEnd":917.8000001907349,"responseStart":917.8000001907349,"secureConnectionStart":409.10000014305115},{"duration":617.2999999523163,"initiatorType":"script","name":"https://jira.mariadb.org/s/2d8175ec2fa4c816e8023260bd8c1786-CDN/lu2cib/820016/12ta74/494e4c556ecbb29f90a3d3b4f09cb99c/_/download/contextbatch/js/jira.browse.project,project.issue.navigator,jira.view.issue,jira.general,jira.global,atl.general,-_super/batch.js?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&locale=en&slack-enabled=true&whisper-enabled=true","startTime":409.30000019073486,"connectEnd":409.30000019073486,"connectStart":409.30000019073486,"domainLookupEnd":409.30000019073486,"domainLookupStart":409.30000019073486,"fetchStart":409.30000019073486,"redirectEnd":0,"redirectStart":0,"requestStart":409.30000019073486,"responseEnd":1026.6000001430511,"responseStart":1026.6000001430511,"secureConnectionStart":409.30000019073486},{"duration":621.2000000476837,"initiatorType":"script","name":"https://jira.mariadb.org/s/a9324d6758d385eb45c462685ad88f1d-CDN/lu2cib/820016/12ta74/c92c0caa9a024ae85b0ebdbed7fb4bd7/_/download/contextbatch/js/atl.global,-_super/batch.js?locale=en","startTime":409.60000014305115,"connectEnd":409.60000014305115,"connectStart":409.60000014305115,"domainLookupEnd":409.60000014305115,"domainLookupStart":409.60000014305115,"fetchStart":409.60000014305115,"redirectEnd":0,"redirectStart":0,"requestStart":409.60000014305115,"responseEnd":1030.8000001907349,"responseStart":1030.8000001907349,"secureConnectionStart":409.60000014305115},{"duration":621.9000000953674,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-en/jira.webresources:calendar-en.js","startTime":409.7000000476837,"connectEnd":409.7000000476837,"connectStart":409.7000000476837,"domainLookupEnd":409.7000000476837,"domainLookupStart":409.7000000476837,"fetchStart":409.7000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":409.7000000476837,"responseEnd":1031.6000001430511,"responseStart":1031.6000001430511,"secureConnectionStart":409.7000000476837},{"duration":622,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-localisation-moment/jira.webresources:calendar-localisation-moment.js","startTime":409.90000009536743,"connectEnd":409.90000009536743,"connectStart":409.90000009536743,"domainLookupEnd":409.90000009536743,"domainLookupStart":409.90000009536743,"fetchStart":409.90000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":409.90000009536743,"responseEnd":1031.9000000953674,"responseStart":1031.9000000953674,"secureConnectionStart":409.90000009536743},{"duration":695.1000001430511,"initiatorType":"link","name":"https://jira.mariadb.org/s/b04b06a02d1959df322d9cded3aeecc1-CDN/lu2cib/820016/12ta74/a2ff6aa845ffc9a1d22fe23d9ee791fc/_/download/contextbatch/css/jira.global.look-and-feel,-_super/batch.css","startTime":410,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":410,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1105.1000001430511,"responseStart":0,"secureConnectionStart":0},{"duration":622.2999999523163,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":410.2000000476837,"connectEnd":410.2000000476837,"connectStart":410.2000000476837,"domainLookupEnd":410.2000000476837,"domainLookupStart":410.2000000476837,"fetchStart":410.2000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":410.2000000476837,"responseEnd":1032.5,"responseStart":1032.5,"secureConnectionStart":410.2000000476837},{"duration":694.9000000953674,"initiatorType":"link","name":"https://jira.mariadb.org/s/3ac36323ba5e4eb0af2aa7ac7211b4bb-CDN/lu2cib/820016/12ta74/d176f0986478cc64f24226b3d20c140d/_/download/contextbatch/css/com.atlassian.jira.projects.sidebar.init,-_super,-project.issue.navigator,-jira.view.issue/batch.css?jira.create.linked.issue=true","startTime":410.40000009536743,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":410.40000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1105.3000001907349,"responseStart":0,"secureConnectionStart":0},{"duration":622.5999999046326,"initiatorType":"script","name":"https://jira.mariadb.org/s/5d5e8fe91fbc506585e83ea3b62ccc4b-CDN/lu2cib/820016/12ta74/d176f0986478cc64f24226b3d20c140d/_/download/contextbatch/js/com.atlassian.jira.projects.sidebar.init,-_super,-project.issue.navigator,-jira.view.issue/batch.js?jira.create.linked.issue=true&locale=en","startTime":410.60000014305115,"connectEnd":410.60000014305115,"connectStart":410.60000014305115,"domainLookupEnd":410.60000014305115,"domainLookupStart":410.60000014305115,"fetchStart":410.60000014305115,"redirectEnd":0,"redirectStart":0,"requestStart":410.60000014305115,"responseEnd":1033.2000000476837,"responseStart":1033.2000000476837,"secureConnectionStart":410.60000014305115},{"duration":1530.5,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-js/jira.webresources:bigpipe-js.js","startTime":412,"connectEnd":412,"connectStart":412,"domainLookupEnd":412,"domainLookupStart":412,"fetchStart":412,"redirectEnd":0,"redirectStart":0,"requestStart":412,"responseEnd":1942.5,"responseStart":1942.5,"secureConnectionStart":412},{"duration":1526.8999998569489,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-init/jira.webresources:bigpipe-init.js","startTime":416.30000019073486,"connectEnd":416.30000019073486,"connectStart":416.30000019073486,"domainLookupEnd":416.30000019073486,"domainLookupStart":416.30000019073486,"fetchStart":416.30000019073486,"redirectEnd":0,"redirectStart":0,"requestStart":416.30000019073486,"responseEnd":1943.2000000476837,"responseStart":1943.2000000476837,"secureConnectionStart":416.30000019073486},{"duration":376.10000014305115,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":1118.5,"connectEnd":1118.5,"connectStart":1118.5,"domainLookupEnd":1118.5,"domainLookupStart":1118.5,"fetchStart":1118.5,"redirectEnd":0,"redirectStart":0,"requestStart":1118.5,"responseEnd":1494.6000001430511,"responseStart":1494.6000001430511,"secureConnectionStart":1118.5},{"duration":553.5,"initiatorType":"script","name":"https://www.google-analytics.com/analytics.js","startTime":1468,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1468,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":2021.5,"responseStart":0,"secureConnectionStart":0}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":144,"responseStart":401,"responseEnd":407,"domLoading":405,"domInteractive":2026,"domContentLoadedEventStart":2026,"domContentLoadedEventEnd":2094,"domComplete":3030,"loadEventStart":3030,"loadEventEnd":3030,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":1958.6000001430511},{"name":"bigPipe.sidebar-id.end","time":1959.5},{"name":"bigPipe.activity-panel-pipe-id.start","time":1959.6000001430511},{"name":"bigPipe.activity-panel-pipe-id.end","time":1963.1000001430511},{"name":"activityTabFullyLoaded","time":2115.300000190735}],"measures":[],"correlationId":"e6c3a15942fc24","effectiveType":"4g","downlink":9.2,"rtt":0,"serverDuration":166,"dbReadsTimeInMs":22,"dbConnsTimeInMs":32,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}
You're right, we need to concentrate on original report. Which I couldn't reproduce locally, most probably due to some known issues with Samsung SSD being slow on heavy fsync.
I will try to look into ramdisk performance more closely, with longer run and more concurrent connections (like 1000).