Today’s blog post starts with a question:
“In my continuous integration environment, running tests currently takes 30 minutes. I
believe that a large percentage of time is spent in MySQL, and I want to know if putting MySQL
on tmpfs will cut that time down?”.
I have previously written about how to configure MySQL to be less durable in testing environments, but today I wanted to write about how we can really test the assumption that the question is based around. That is to say:
- We know that total time is 30 minutes.
- We assume MySQL is a large percentage of this.
- We know that this optimization will potentially allow us to avoid IO.
- We then want to know what amount of time MySQL spends waiting on IO during our test suite?
And the answer to this is performance schema.
Performance Schema instruments File IO with statistics such as bytes read/written, and wait time. So if we see that IO wait time was only a small percentage of the 30 minutes of test time, we automatically know if this optimization is worth investigating or not.
Here is a simple query that will work on 5.6 out of the box:
mysql> SELECT
`a`.`EVENT_NAME`,
`a`.`SUM_TIMER_WAIT`/1024/1024/1024 AS `total_latency_ms`,
`b`.`SUM_NUMBER_OF_BYTES_READ` AS `total_bytes_read`,
`b`.`SUM_NUMBER_OF_BYTES_WRITE` AS `total_bytes_written`
FROM
`performance_schema`.`events_waits_summary_global_by_event_name` `a`
INNER JOIN `performance_schema`.`file_summary_by_event_name` `b` USING (event_name)
WHERE
`a`.`EVENT_NAME` like 'wait/io/file/%'
AND `a`.`COUNT_STAR` > 0\G
*************************** 1. row ***************************
EVENT_NAME: wait/io/file/sql/casetest
total_latency_ms: 0.245716745034
total_bytes_read: 0
total_bytes_written: 0
*************************** 2. row ***************************
EVENT_NAME: wait/io/file/sql/ERRMSG
total_latency_ms: 0.911862457171
total_bytes_read: 58982
total_bytes_written: 0
*************************** 3. row ***************************
EVENT_NAME: wait/io/file/sql/FRM
total_latency_ms: 50.292402482592
total_bytes_read: 137771
total_bytes_written: 0
*************************** 4. row ***************************
EVENT_NAME: wait/io/file/sql/global_ddl_log
total_latency_ms: 0.012274521403
total_bytes_read: 0
total_bytes_written: 0
*************************** 5. row ***************************
EVENT_NAME: wait/io/file/sql/pid
total_latency_ms: 0.218277866021
total_bytes_read: 0
total_bytes_written: 5
*************************** 6. row ***************************
EVENT_NAME: wait/io/file/mysys/charset
total_latency_ms: 0.450179565698
total_bytes_read: 18316
total_bytes_written: 0
*************************** 7. row ***************************
EVENT_NAME: wait/io/file/mysys/cnf
total_latency_ms: 0.315982563421
total_bytes_read: 56
total_bytes_written: 0
*************************** 8. row ***************************
EVENT_NAME: wait/io/file/myisam/dfile
total_latency_ms: 0.885083482601
total_bytes_read: 2322
total_bytes_written: 0
*************************** 9. row ***************************
EVENT_NAME: wait/io/file/myisam/kfile
total_latency_ms: 3.881758853793
total_bytes_read: 7058
total_bytes_written: 0
*************************** 10. row ***************************
EVENT_NAME: wait/io/file/innodb/innodb_data_file
total_latency_ms: 114.101030502468
total_bytes_read: 10223616
total_bytes_written: 49152
*************************** 11. row ***************************
EVENT_NAME: wait/io/file/innodb/innodb_log_file
total_latency_ms: 2.865770795383
total_bytes_read: 69632
total_bytes_written: 3072
11 rows in set (0.01 sec)
Taking it one step further and combining with ps_helper, I think there is a real opportunity to build this metrics collection into the test suite:
/* start by reseting all metrics */
ps_helper.truncate_all();
/* run test suite */
/* Collect test suite metrics from MySQL */
SELECT * FROM ps_helper.wait_classes_global_by_latency;
Here is an example for wait_classes_global_by_latency from the GitHub project:
mysql> select * from wait_classes_global_by_latency;
+-------------------+--------------+---------------+-------------+-------------+-------------+
| event_class | total_events | total_latency | min_latency | avg_latency | max_latency |
+-------------------+--------------+---------------+-------------+-------------+-------------+
| wait/io/file | 550470 | 46.01 s | 19.44 ns | 83.58 µs | 4.21 s |
| wait/io/socket | 228833 | 2.71 s | 0 ps | 11.86 µs | 29.93 ms |
| wait/io/table | 64063 | 1.89 s | 99.79 ns | 29.43 µs | 68.07 ms |
| wait/lock/table | 76029 | 47.19 ms | 65.45 ns | 620.74 ns | 969.88 µs |
| wait/synch/mutex | 635925 | 34.93 ms | 19.44 ns | 54.93 ns | 107.70 µs |
| wait/synch/rwlock | 61287 | 7.62 ms | 21.38 ns | 124.37 ns | 34.65 µs |
+-------------------+--------------+---------------+-------------+-------------+-------------+
Neat, huh?
