測試場景MySQL 5.7.12主要測試 不同刷盤參數 對性能的影響, 使用以下三個場景:sync_binlog=1, innodb_flush_log_at_trx_commit=1, 簡寫為b1e1 (binlog-1-engine-1)sync_binlog=0, innodb_flush_log_at_trx_commit=1, 簡寫為b0e1sync_binlog=0, innodb_flush_log_at_trx_commit=0, 簡寫為b0e0
MySQL 環境搭建使用 MySQL sandbox, 對應三個場景的啟動參數如下:1. ./start --sync-binlog=1 --log-bin=bin --server-id=5712 --gtid-mode=ON --enforce-gtid-consistency=1 --log-slave-updates=12. ./start --sync-binlog=0 --log-bin=bin --server-id=5712 --gtid-mode=ON --enforce-gtid-consistency=1 --log-slave-updates=13. ./start --sync-binlog=0 --log-bin=bin --server-id=5712 --gtid-mode=ON --enforce-gtid-consistency=1 --log-slave-updates=1 --innodb-flush-log-at-trx-commit=0
壓力生成使用sysbench:
mysql -h127.0.0.1 -P5712 -uroot -pmsandbox -e"truncate table test.sbtest1"; /opt/sysbench-0.5/dist/bin/sysbench --test=/opt/sysbench-0.5/dist/db/insert.lua --mysql-table-engine=innodb --mysql-host=127.0.0.1 --mysql-user=root --mysql-password=msandbox --mysql-port=5712 --oltp-table-size=1000000 --mysql-db=test --oltp-table-name=stest --num-threads=1 --max-time=30 --max-requests=1000000000 --oltp-auto-inc=off --db-driver=mysql run
性能觀測工具使用systemtap(簡稱stap), version 2.7/0.160
基準在沒有觀測壓力的情況下, 對三種場景分別進行基準測試, 用以矯正之后測試的誤差:
場景sysbench事務數b1e167546b0e1125699b0e0181612
火焰圖與offcpu火焰圖火焰圖是Brendan Gregg首創的表示性能的圖形方式, 其可以直觀的看到壓力的分布. Brendan提供了豐富的工具生成火焰圖.
火焰圖比較b0e1和b0e0使用stap腳本獲取CPU profile, 并生成火焰圖(火焰圖生成的命令略, 參看Brendan的文檔)
stap腳本
global tids probe process("/home/huangyan/sandboxes/5.7.12/bin/mysqld").function("mysql_execute_command") { if (pid() == target() && tids[tid()] == 0) { tids[tid()] = 1; } } global oncpu probe timer.profile { if (tids[tid()] == 1) { oncpu[ubacktrace()] <<< 1; } } probe timer.s(10) { exit(); } probe end { foreach (i in oncpu+) { print_stack(i); printf("\t%d\n", @count(oncpu[i])); } }
注意:1. 腳本只抓取MySQL的用戶線程的CPU profile, 不抓取后臺進程.2. 腳本只抓取10s, 相當于對整個sysbench的30s過程進行了短期抽樣.
b0e1生成的火焰圖
性能
在開啟觀測的情況下, 觀察性能:
場景sysbench事務數b0e1119274b0e0166424
分析
在生成的火焰圖中, 可以看到:
在b0e1場景中, _ZL27log_write_flush_to_disk_lowv的占比是12.93%, 其絕大部分時間是用于將innodb的log刷盤.在b0e0場景中, _ZL27log_write_flush_to_disk_lowv的開銷被節省掉, 理論上的事務數比例應是1-12.93%=87.07%, 實際事務數的比例是119274/166424=71.67%, 誤差較大誤差較大的問題, 要引入offcpu來解決.
offcpu在之前的分析中我們看到理論和實際的事務數誤差較大. 考慮_ZL27log_write_flush_to_disk_lowv的主要操作是IO操作, IO操作開始, 進程就會被OS進行上下文切換換下臺, 以等待IO操作結束, 那么只分析CPU profile就忽略了IO等待的時間, 也就是說_ZL27log_write_flush_to_disk_lowv的開銷被低估了.
offcpu也是Brendan Gregg提出的概念. 對于IO操作的觀測, 除了CPU profile(稱為oncpu時間), 還需要觀測其上下文切換的代價, 即offcpu時間.
修改一下stap腳本可以觀測offcpu時間. 不過為了將oncpu和offcpu的時間顯示在一張火焰圖上作對比, 我對于Brendan的工具做了微量修改, 本文將不介紹這些修改.
stap腳本
global tids probe process("/home/huangyan/sandboxes/5.7.12/bin/mysqld").function("mysql_execute_command") { if (pid() == target() && tids[tid()] == 0) { tids[tid()] = 1; } } global oncpu, offcpu, timer_count, first_cpu_id = -1; probe timer.profile { if (first_cpu_id == -1) { first_cpu_id = cpu(); } if (tids[tid()] == 1) { oncpu[ubacktrace()] <<< 1; } if (first_cpu_id == cpu()) { timer_count++; } } global switchout_ustack, switchout_timestamp probe scheduler.ctxswitch { if (tids[prev_tid] == 1) { switchout_ustack[prev_tid] = ubacktrace(); switchout_timestamp[prev_tid] = timer_count; } if (tids[next_tid] == 1 && switchout_ustack[next_tid] != "") { offcpu[switchout_ustack[next_tid]] <<< timer_count - switchout_timestamp[next_tid]; switchout_ustack[next_tid] = ""; } } probe timer.s(10) { exit(); } probe end { foreach (i in oncpu+) { print_stack(i); printf("\t%d\n", @sum(oncpu[i])); } foreach (i in offcpu+) { printf("---"); print_stack(i); printf("\t%d\n", @sum(offcpu[i])); } }
注意: timer.profile的說明中是這樣寫的:
Profiling timers are available to provide probes that execute on all CPUs at each system tick.
也就是說在一個時間片中, timer.profile會對每一個CPU調用一次. 因此代碼中使用了如下代碼, 保證時間片技術的正確性:
if (first_cpu_id == cpu()) { timer_count++; }
b0e1生成的帶有offcpu的火焰圖
性能
由于變更了觀測腳本, 需要重新觀測性能以減小誤差:
場景sysbench事務數b0e1105980b0e0164739
分析
在火焰圖中, 可以看到:1. _ZL27log_write_flush_to_disk_lowv的占比為31.23%2. 理論上的事務數比例應是1-31.23%=68.77%, 實際事務數的比例是105980/164739=64.33%, 誤差較小.
觀測誤差的矯正在比較b0e1和b0e0兩個場景時, 獲得了比較好的結果. 但同樣的方法在比較b1e1和b0e1兩個場景時, 出現了一些誤差.
誤差現象b1e1的火焰圖如圖:
其中_ZN13MYSQL_BIN_LOG16sync_binlog_fileEb(sync_binlog的函數)占比為26.52%.
但性能差異為:
場景sysbench事務數b1e153752b0e1105980
理論的事務數比例為1-26.52%=73.48%, 實際事務數比例為53752/105980=50.71%, 誤差較大.
分析壓力分布首先懷疑壓力轉移, 即當sync_binlog的壓力消除后, 服務器壓力被轉移到了其它的瓶頸上. 但如果壓力產生了轉移, 那么實際事務數比例應大于理論事務數比例, 即sync_binlog=0帶來的性能提升更小.
不過我們還是可以衡量一下壓力分布, 看看b1e1和b0e1的壓力有什么不同, 步驟如下:
修改stap腳本, 在b1e1中不統計sync_binlog的代價. 生成的火焰圖表示消除sync_binlog代價后, 理論上的服務器壓力類型.與b0e1產生的火焰圖做比較.stap腳本
只修改了probe end部分, 略過對my_sync堆棧的統計:
probe end { foreach (i in oncpu+) { if (isinstr(sprint_stack(i), "my_sync")) { continue; } print_stack(i); printf("\t%d\n", @sum(oncpu[i])); } foreach (i in offcpu+) { if (isinstr(sprint_stack(i), "my_sync")) { continue; } printf("---"); print_stack(i); printf("\t%d\n", @sum(offcpu[i])); } }
結果
b1e1, 理論的服務器壓力圖:
b0e1, 實際的服務器壓力圖:
可以看到, 壓力分布是非常類似, 即沒有發生壓力分布.
BTW: 這兩張圖的類似, 具有一定隨機性, 需要做多次試驗才能產生這個結果.
分析
既然理論和實際的壓力分布類似, 那么可能發生的就是壓力的整體等比縮小. 推測是兩個場景上的觀測成本不同, 導致觀測影響到了所有壓力的觀測.
觀察stap腳本, 其中成本較大的是ctxswitch, 即上下文切換時的觀測成本.
上下文切換的觀測成本如果 “上下文切換的觀測成本 影響 場景觀測 的公平性” 這一結論成立, 那么我們需要解釋兩個現象:1. b1e1和b0e1的比較, 受到了 上下文切換的觀測成本 的影響2. b0e1和b0e0的比較, 未受到 上下文切換的觀測成本 的影響
假設 上下文切換的觀測成本 正比于 上下文切換的次數, 那么我們只需要:1. 觀測每個場景的上下文切換次數2. 對于b1e1和b0e1的比較, 由上下文切換次數計算得到理論的降速比, 與實際的降速比進行比較3. 對于b0e1和b0e0的比較, 由上下文切換次數計算得到是否會帶來降速.
stap腳本
在probe scheduler.ctxswitch和probe end 增加了 ctxswitch_times 相關的內容:
global ctxswitch_times probe scheduler.ctxswitch { ctxswitch_times++; ... } probe end { ... printf("ctxswitch_times=%d\n", ctxswitch_times); }
結果
場景sysbench事務數上下文切換次數sync_binlog占比b1e15535282637036.80%b0e1105995693383–b0e0162709675092–
分析結果:1. b1e1與b0e1的比較1. 理論降速比: 693383/826370 = 83.90%2. 實際降速比: (實際的事務數比例/由sync_binlog占比推算的理論的事務數比例) = (55352/105995)/(1-36.80%) = 0.5222/0.6320 = 82.63%3. 誤差很小. 即b1e1與b0e1的比較中, 理論值和實際值的誤差來自于: IO操作的減少導致上下文切換的數量減小, 使得兩個場景的觀察成本不同.2. b0e1與b0e0的比較: 上下文切換次數相近, 即兩個場景的觀察成本相同.
實驗結果符合之前的分析.
結論利用火焰圖, 可以快速診斷出MySQL服務器級別的性能瓶頸, 做出合理的參數調整對于IO類型的操作的觀測, 需要考慮oncpu和offcpu兩種情況由于觀測手段中使用了上下文切換作為觀測點, 那IO操作數量的不同, 會引起上下文切換次數的不同, 從而引起觀測誤差.