MySQL 8.0.28 から performance_schema に CPU_TIME を記録できるようになりました。
これまでも実行時間は performance_schema から確認できていました。ただ、実行時間が長いだけでは、そのクエリが必ずしもCPUに負荷をかけているクエリとは言いきれませんでした。
今回の機能追加で、CPUに負荷をかけているクエリがバシっと performance_schema から確認できるようになったのは嬉しいですね(欲を言うと、CPU_TIME を スロークエリログにも出してほしいなぁ)。
デフォルトではOFFになっています。以下の設定を my.cnf に記述し、有効化します。
performance-schema-consumer-events-statements-cpu=ON
sys.statement_analysis にも cpu_latency が追加され、レスポンスタイムに占めるCPU時間が確認できます。
この例では total_time = cpu_latency になってます。テーブルが小さく、ほとんどIOの発生しないクエリだったため、このような結果になってます。
mysql> select * from sys.statement_analysis limit 1\G
*************************** 1. row ***************************
query: SELECT SUM ( `salary` ) FROM `salaries`
db: employees
full_scan: *
exec_count: 5
err_count: 0
warn_count: 0
total_latency: 2.12 s
max_latency: 523.29 ms
avg_latency: 424.49 ms
lock_latency: 17.00 us
cpu_latency: 2.12 s
<snip>
1 row in set (0.00 sec)
total_letency != cpu_latency となりそうな、IOバウンドなクエリで試してみます*1。
7.14 min のうち、cpu_latency が 15.80 s と IOに時間がかかったことが、しっかり読み取れました。
mysql> SELECT * FROM sbtest.sbtest1 WHERE c = 'X';
Empty set (7 min 5.33 sec)
mysql> select * from sys.statement_analysis LIMIT 1\G
*************************** 1. row ***************************
query: SELECT * FROM `sbtest` . `sbtest1` WHERE `c` = ?
db: NULL
full_scan: *
exec_count: 2
err_count: 1
warn_count: 0
total_latency: 7.14 min
max_latency: 7.09 min
avg_latency: 3.57 min
lock_latency: 19.00 us
cpu_latency: 15.80 s
<snip>
実装
CPU時間は clock_gettime() を利用して取得してる。
mysys/my_rdtsc.cc
/**
THREAD_CPU timer.
Expressed in nanoseconds.
*/
ulonglong my_timer_thread_cpu(void) {
#if defined(HAVE_CLOCK_GETTIME) && defined(CLOCK_THREAD_CPUTIME_ID)
{
struct timespec tp;
clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp);
return (ulonglong)tp.tv_sec * 1000000000 + (ulonglong)tp.tv_nsec;
}
