If you use binlog_format = statement or mixed , \u00a0there are several ways of monitoring the SQL thread. The most ancient is the log-slow-slave-statements<\/a>\u00a0 variable. From 5.6.11, it is a dynamic variable, before that you had to restart the slave mysqld to enable it.<\/p>\n Once on, you can trace what’s going on in the SQL thread and analyze the slow query log. Of course, as the SQL thread could be running long write queries or a lot of fast queries, so it is crucial to set long_query_time = 0 for say 60 seconds to catch the fast writes. Fast does not mean that they can not be optimized :-).<\/p>\n From MySQL 5.6.14, there is even better. After this bug fix :\u00a0Bug 16750433 – THE STATEMENT DIGEST DOES NOT SHOW THE SLAVE SQL THREAD STATEMENTS, <\/b>the Performance_schema statement digests are showing the SQL thread statements as well !<\/p>\n So that ps_helper<\/a> \/ mysql_sys<\/a> can be used to see what’s going on in the SQL thread.<\/p>\n Now an real example :<\/p>\n If you see this kind of things : show global status like ‘Handler%’ or in the show engine innodb status :<\/p>\n 500k index records scan per second is a bit too much for a (single) thread. No wonder that<\/p>\n Seconds_Behind_Master: 76162<\/p>\n is large and increasing.<\/p>\n The slave was up for 12 min and nearly 10 min was spent on the updates ! 18000 updates in 10 minutes, that’s fast \ud83d\ude42 So do we need to buy better hardware ?<\/p>\n No. Average rows examined is between 100 – 200. Maybe we can optimize it ?<\/p>\n Indeed, adding an index on (c1,c2) fixed the issue. And cut by 100 the rows examined average. After one hour, the slave that was lagging 1 day had caught up.<\/p>\n <\/p>\n This is the MEM<\/a> graph for the rows_examined.<\/p>\n Thank you to\u00a0Hauns\u00a0Froehlingsdorf who worked with me on this issue.<\/p>\n Things to note here :<\/p>\n A lot of customers have lagging slaves. It could be one of the top issues at support, due to the infamous row based replication without primary key issue : Bug\u00a0#53375 RBR + no PK => High load on slave (table … Continue reading Handler_read_next: 1,573,551,696 (551,543\/sec)\r\nNumber of rows inserted 172099, updated 685966, deleted 137734, read 1574302296\r\n32.14 inserts\/s, 208.76 updates\/s, 28.84 deletes\/s, 547765.56 reads\/s<\/pre>\n
mysql> select * from statement_analysis ;\r\n+-------------------------------------------------------------------+-----------+-----------+------------+-----------+------------+---------------+-------------+-------------+--------------+-----------+---------------+---------------+-------------------+------------+-----------------+-------------+-------------------+----------------------------------+---------------------+---------------------+\r\n| query | db | full_scan | exec_count | err_count | warn_count | total_latency | max_latency | avg_latency | lock_latency | rows_sent | rows_sent_avg | rows_examined | rows_examined_avg | tmp_tables | tmp_disk_tables | rows_sorted | sort_merge_passes | digest | first_seen | last_seen |\r\n+-------------------------------------------------------------------+-----------+-----------+------------+-----------+------------+---------------+-------------+-------------+--------------+-----------+---------------+---------------+-------------------+------------+-----------------+-------------+-------------------+----------------------------------+---------------------+---------------------+\r\n| UPDATE t ... c1 = ? AND c2 = ? | prod | | 13904 | 0 | 4896 | 00:06:06.71 | 4.75 s | 26.37 ms | 1.26 s | 0 | 0 | 1492198 | 107 | 0 | 0 | 0 | 0 | a36a0c617b2f696cb4889ee015541b65 | 2014-03-05 08:02:25 | 2014-03-05 08:13:30 |\r\n| UPDATE t ... c1 = ? AND c2 = ? | prod | | 2024 | 0 | 0 | 00:01:34.49 | 2.57 s | 46.69 ms | 147.32 ms | 0 | 0 | 373785 | 185 | 0 | 0 | 0 | 0 | 8dd4ee22a216fe5fcc03b03a34f3a3fd | 2014-03-05 08:02:36 | 2014-03-05 08:13:30 |\r\n| UPDATE t ... c1 = ? AND c2 = ? | prod | | 1662 | 0 | 0 | 00:01:31.54 | 3.31 s | 55.08 ms | 65.96 ms | 0 | 0 | 317512 | 191 | 0 | 0 | 0 | 0 | 27a13609455481e156ca9eb2e5c54d6d | 2014-03-05 08:02:53 | 2014-03-05 08:13:29 |\r\n| UPDATE t ... ? , c3 = IF ( ... | prod | | 1987 | 0 | 1064 | 41.06 s | 1.11 s | 20.66 ms | 206.36 ms | 0 | 0 | 206869 | 104 | 0 | 0 | 0 | 0 | f812e322c0e3dfaf905fe1d624978564 | 2014-03-05 08:02:42 | 2014-03-05 08:13:29 |\r\n| UPDATE t ... c1 = ? AND c2 = ? | prod | | 680 | 0 | 0 | 39.11 s | 1.91 s | 57.51 ms | 62.61 ms | 0 | 0 | 144791 | 213 | 0 | 0 | 0 | 0 | a9266204238e66806ca4c073650b72e5 | 2014-03-05 08:05:37 | 2014-03-05 08:13:22 |\r\n\r\nmysql> select * from io_global_by_file_by_latency ;\r\n+-------------------------------------------------------------------------------------+------------+---------------+------------+--------------+-------------+---------------+------------+--------------+\r\n| file | count_star | total_latency | count_read | read_latency | count_write | write_latency | count_misc | misc_latency |\r\n+-------------------------------------------------------------------------------------+------------+---------------+------------+--------------+-------------+---------------+------------+--------------+\r\n| @@datadir\/prod\/t.ibd | 244505 | 00:05:58.94 | 244319 | 00:05:58.83 | 114 | 4.56 ms | 72 | 105.85 ms |<\/pre>\n
mysql> explain update t set c3 = 1 where c1=6577849127655212045 and c2 = '2014-03-04'\\G\r\n*************************** 1. row ***************************\r\n id: 1\r\n select_type: SIMPLE\r\n table: t\r\n type: index_merge\r\npossible_keys: idx_c1, idx_c2\r\n key: idx_c1, idx_c2\r\n key_len: 8,3\r\n ref: NULL\r\n rows: 3\r\n Extra: Using intersect(idx_c1,idx_c2); Using where\r\n1 row in set (0.00 sec)<\/pre>\n
![\"rows_examined\"](\"http:\/\/aadant.com\/blog\/wp-content\/uploads\/2014\/03\/rows_examined-300x83.png\")
<\/a><\/p>\n\n