Quickly tell who is writing to a MySQL replica

Many of us have been there in the past, you get an alert telling you that replication has stopped because of an error, you dig in to it to find that you’re getting an error for an update event that is trying to update a non-existent row, or a duplicate key error because the row ID for some INSERT already exists.

Even with the server set to read only (and not using the new super_read_only variable from MySQL 5.7.8), these problems can still happen – how many of you have seen over-zealous ops trying to “quickly fix” some problem only to royally screw up your data integrity?

The question then becomes – “who or what is making changes on my replica that shouldn’t be?!?”.

The only way to find this out in the past, and still “the conventional wisdom” (I just saw it recommended in a discussion in the MySQL support group) was to turn on the binary log on the replica, make sure log_slave_updates is not enabled, and then see what events turn up in the binary log.

But if you are using 5.6, you can already get an idea of who is executing what kinds of DML statements very easily, with the default statement instrumentation in Performance Schema, via the performance_schema.events_statements_summary_by_user_by_event_name and performance_schema.events_statements_summary_by_host_by_event_name tables. These have a structure like this:

mysql> desc performance_schema.events_statements_summary_by_user_by_event_name;
+-----------------------------+---------------------+------+-----+---------+-------+
| Field                       | Type                | Null | Key | Default | Extra |
+-----------------------------+---------------------+------+-----+---------+-------+
| USER                        | char(16)            | YES  |     | NULL    |       |
| EVENT_NAME                  | varchar(128)        | NO   |     | NULL    |       |
| COUNT_STAR                  | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_TIMER_WAIT              | bigint(20) unsigned | NO   |     | NULL    |       |
| MIN_TIMER_WAIT              | bigint(20) unsigned | NO   |     | NULL    |       |
| AVG_TIMER_WAIT              | bigint(20) unsigned | NO   |     | NULL    |       |
| MAX_TIMER_WAIT              | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_LOCK_TIME               | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_ERRORS                  | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_WARNINGS                | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_ROWS_AFFECTED           | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_ROWS_SENT               | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_ROWS_EXAMINED           | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_CREATED_TMP_DISK_TABLES | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_CREATED_TMP_TABLES      | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_SELECT_FULL_JOIN        | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_SELECT_FULL_RANGE_JOIN  | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_SELECT_RANGE            | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_SELECT_RANGE_CHECK      | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_SELECT_SCAN             | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_SORT_MERGE_PASSES       | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_SORT_RANGE              | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_SORT_ROWS               | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_SORT_SCAN               | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_NO_INDEX_USED           | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_NO_GOOD_INDEX_USED      | bigint(20) unsigned | NO   |     | NULL    |       |
+-----------------------------+---------------------+------+-----+---------+-------+

The data within them is like the merged output of “SHOW GLOBAL STATUS LIKE ‘Com_%'” (only by user here for example, or by host/account in the other base summary views), with the regular performance schema statement data (latency, lock time, result info, sorting info, temporary table info etc.).

So you can get an idea of the query profile of users:

mysql> select user, event_name, count_star, sum_timer_wait, sum_rows_affected
    ->   from performance_schema.events_statements_summary_by_user_by_event_name
    ->  where sum_timer_wait > 0
    ->  order by user, sum_timer_wait desc;
+------+----------------------------------+------------+-------------------+-------------------+
| user | event_name                       | count_star | sum_timer_wait    | sum_rows_affected |
+------+----------------------------------+------------+-------------------+-------------------+
| root | statement/sql/insert             |    4654750 | 10889839312962492 |           6147833 |
| root | statement/sql/select             |    1763971 |  2685440113284300 |                16 |
| root | statement/sql/commit             |    3549022 |  2076707580306888 |                 0 |
| root | statement/sql/update             |     692793 |   429644976873960 |            692961 |
| root | statement/sql/alter_table        |       2294 |   349258266736668 |                 0 |
| root | statement/sql/set_option         |    3638143 |   175255961793804 |                 0 |
| root | statement/sql/truncate           |       4416 |   169644392962740 |                 0 |
| root | statement/sql/create_table       |       2042 |   119925607500528 |                 0 |
| root | statement/sql/show_fields        |      15795 |   119878604121228 |                 0 |
| root | statement/sql/delete             |     699378 |   116732970789132 |             40298 |
| root | statement/com/Init DB            |     218258 |    90260554011048 |                 0 |
| root | statement/sql/call_procedure     |          5 |    84983311882308 |                 0 |
| root | statement/sql/show_binlogs       |       5832 |    73956599513124 |                 0 |
| root | statement/sql/create_index       |       1530 |    53709192098256 |                 0 |
| root | statement/sql/show_tables        |      37924 |    45532153498296 |                 0 |
| root | statement/sql/show_warnings      |     892204 |    40929165782628 |                 0 |
| root | statement/sql/rollback           |     224391 |    30362071807164 |                 0 |
| root | statement/sql/show_variables     |      30521 |    25090556161620 |                 0 |
| root | statement/sql/show_status        |      17403 |    12531077415552 |                 0 |
| root | statement/com/Ping               |     358412 |    10763876159712 |                 0 |
| root | statement/sql/show_engine_status |       6964 |     9874889717568 |                 0 |
| root | statement/sql/show_keys          |      15739 |     6773811516912 |                 0 |
| root | statement/sql/show_create_table  |      34677 |     4967611443876 |                 0 |
| root | statement/sql/drop_db            |         78 |     3803154575244 |               289 |
| root | statement/com/Quit               |     566175 |     2860317274356 |                 0 |
| root | statement/sql/show_slave_status  |      11592 |     2394918433356 |                 0 |
| root | statement/sql/show_databases     |       1187 |     1722377297184 |                 0 |
| root | statement/sql/delete_multi       |       5737 |      946103948844 |                10 |
| root | statement/sql/show_master_status |       6961 |      861468069984 |                 0 |
| root | statement/sql/execute_sql        |          4 |      649259110140 |                 0 |
| root | statement/sql/create_db          |       1139 |      558651095628 |              1139 |
| root | statement/sql/change_db          |        363 |       49894596144 |                 0 |
| root | statement/sql/prepare_sql        |          4 |       31004518200 |                 0 |
| root | statement/sql/error              |        363 |       28835029596 |                 0 |
| root | statement/sql/create_procedure   |          4 |       27429645936 |                 0 |
| root | statement/sql/show_collations    |         47 |       24375874704 |                 0 |
| root | statement/sql/drop_event         |         77 |       12535227684 |                 0 |
| root | statement/sql/show_processlist   |         42 |        8276037864 |                 0 |
| root | statement/com/Set option         |        134 |        6454170660 |                 0 |
| root | statement/sql/drop_procedure     |          4 |        1955618676 |                 0 |
| root | statement/sql/create_function    |          1 |         329743728 |                 0 |
| root | statement/sql/dealloc_sql        |          4 |         304913628 |                 0 |
| root | statement/sql/empty_query        |          7 |         214863132 |                 0 |
| root | statement/sql/drop_function      |          1 |         137393220 |                 0 |
+------+----------------------------------+------------+-------------------+-------------------+
44 rows in set (0.00 sec)

This data is what forms the basis for the sys.user_summary_by_statement_type view:

mysql> select * from sys.user_summary_by_statement_type;
+------+--------------------+---------+---------------+-------------+--------------+-----------+---------------+---------------+------------+
| user | statement          | total   | total_latency | max_latency | lock_latency | rows_sent | rows_examined | rows_affected | full_scans |
+------+--------------------+---------+---------------+-------------+--------------+-----------+---------------+---------------+------------+
| root | insert             | 4656002 | 3.03 h        | 2.31 s      | 16.27 m      |         0 |             0 |       6149526 |          0 |
| root | select             | 1764359 | 44.77 m       | 25.23 s     | 9.03 m       |   4496820 |     132814197 |            16 |     395133 |
| root | commit             | 3549836 | 34.62 m       | 11.31 s     | 0 ps         |         0 |             0 |             0 |          0 |
| root | update             |  693048 | 7.16 m        | 1.19 s      | 39.14 s      |         0 |        727567 |        693216 |          0 |
| root | alter_table        |    2294 | 5.82 m        | 3.26 s      | 47.69 s      |         0 |             0 |             0 |          0 |
| root | set_option         | 3638446 | 2.92 m        | 56.50 ms    | 0 ps         |         0 |             0 |             0 |          0 |
| root | truncate           |    4416 | 2.83 m        | 727.25 ms   | 5.07 s       |         0 |             0 |             0 |          0 |
| root | create_table       |    2042 | 2.00 m        | 1.17 s      | 0 ps         |         0 |             0 |             0 |          0 |
| root | show_fields        |   15795 | 2.00 m        | 556.60 ms   | 1.55 m       |    172209 |        172209 |             0 |      15795 |
| root | delete             |  699378 | 1.95 m        | 10.39 s     | 1.03 m       |         0 |        207604 |         40298 |          0 |
| root | Init DB            |  218291 | 1.50 m        | 116.22 ms   | 0 ps         |         0 |             0 |             0 |          0 |
| root | call_procedure     |       5 | 1.42 m        | 38.21 s     | 58.00 ms     |         0 |             0 |             0 |          0 |
| root | show_binlogs       |    5834 | 1.23 m        | 3.81 s      | 0 ps         |         0 |             0 |             0 |          0 |
| root | create_index       |    1530 | 53.71 s       | 811.27 ms   | 20.99 s      |         0 |             0 |             0 |          0 |
| root | show_tables        |   37925 | 45.53 s       | 626.26 ms   | 1.55 s       |     40239 |         40239 |             0 |      37925 |
| root | show_warnings      |  892204 | 40.93 s       | 97.00 ms    | 0 ps         |         0 |             0 |             0 |          0 |
| root | rollback           |  224427 | 30.36 s       | 1.32 s      | 0 ps         |         0 |             0 |             0 |          0 |
| root | show_variables     |   30527 | 25.09 s       | 43.79 ms    | 1.49 s       |   5712888 |       5712888 |             0 |      30527 |
| root | show_status        |   17406 | 12.53 s       | 57.92 ms    | 837.06 ms    |   3966858 |       3966858 |             0 |      17406 |
| root | Ping               |  358451 | 10.77 s       | 3.01 ms     | 0 ps         |         0 |             0 |             0 |          0 |
| root | show_engine_status |    6966 | 9.88 s        | 106.50 ms   | 0 ps         |         0 |             0 |             0 |          0 |
| root | show_keys          |   15739 | 6.77 s        | 95.82 ms    | 1.14 s       |     52285 |         52285 |             0 |      15739 |
| root | show_create_table  |   34677 | 4.97 s        | 78.85 ms    | 0 ps         |         0 |             0 |             0 |          0 |
| root | drop_db            |      78 | 3.80 s        | 1.88 s      | 3.71 s       |         0 |             0 |           289 |          0 |
| root | Quit               |  566250 | 2.86 s        | 2.25 ms     | 0 ps         |         0 |             0 |             0 |          0 |
| root | show_slave_status  |   11594 | 2.40 s        | 32.97 ms    | 0 ps         |         0 |             0 |             0 |          0 |
| root | show_databases     |    1188 | 1.72 s        | 6.25 ms     | 50.00 ms     |      1488 |          1488 |             0 |       1188 |
| root | delete_multi       |    5737 | 946.10 ms     | 39.19 ms    | 313.02 ms    |         0 |           160 |            10 |       1444 |
| root | show_master_status |    6963 | 861.56 ms     | 22.81 ms    | 0 ps         |         0 |             0 |             0 |          0 |
| root | execute_sql        |       4 | 649.26 ms     | 184.78 ms   | 0 ps         |         0 |             0 |             0 |          0 |
| root | create_db          |    1139 | 558.65 ms     | 22.92 ms    | 0 ps         |         0 |             0 |          1139 |          0 |
| root | change_db          |     363 | 49.89 ms      | 692.26 us   | 0 ps         |         0 |             0 |             0 |          0 |
| root | prepare_sql        |       4 | 31.00 ms      | 29.86 ms    | 0 ps         |         0 |             0 |             0 |          0 |
| root | error              |     364 | 28.92 ms      | 347.29 us   | 0 ps         |         0 |             0 |             0 |          0 |
| root | create_procedure   |       4 | 27.43 ms      | 22.09 ms    | 10.00 ms     |         0 |             0 |             0 |          0 |
| root | show_collations    |      47 | 24.38 ms      | 1.37 ms     | 2.00 ms      |     10293 |         10293 |             0 |         47 |
| root | drop_event         |      77 | 12.54 ms      | 1.01 ms     | 4.00 ms      |         0 |             0 |             0 |          0 |
| root | show_processlist   |      42 | 8.28 ms       | 5.87 ms     | 0 ps         |         0 |             0 |             0 |          0 |
| root | Set option         |     134 | 6.45 ms       | 1.52 ms     | 0 ps         |         0 |             0 |             0 |          0 |
| root | drop_procedure     |       4 | 1.96 ms       | 916.73 us   | 1.00 ms      |         0 |             0 |             0 |          0 |
| root | create_function    |       1 | 329.74 us     | 329.74 us   | 0 ps         |         0 |             0 |             0 |          0 |
| root | dealloc_sql        |       4 | 304.91 us     | 87.73 us    | 0 ps         |         0 |             0 |             0 |          0 |
| root | empty_query        |       7 | 214.86 us     | 43.04 us    | 0 ps         |         0 |             0 |             0 |          0 |
| root | drop_function      |       1 | 137.39 us     | 137.39 us   | 1.00 ms      |         0 |             0 |             0 |          0 |
+------+--------------------+---------+---------------+-------------+--------------+-----------+---------------+---------------+------------+

The replication SQL thread statement activity is also recorded within these tables. Within the base performance schema tables, these will have a user / host of NULL, and in the sys schema these are translated to a generic “background” user (an example from my local sandbox topology where one table was created with one row via replication, shown in the “background” user, and the msandbox user has created newly the sys schema):

slave1 [localhost] {msandbox} (sys) > select * from user_summary_by_statement_type;
+------------+-------------------+-------+---------------+-------------+--------------+-----------+---------------+---------------+------------+
| user       | statement         | total | total_latency | max_latency | lock_latency | rows_sent | rows_examined | rows_affected | full_scans |
+------------+-------------------+-------+---------------+-------------+--------------+-----------+---------------+---------------+------------+
| background | create_table      |     1 | 712.32 ms     | 712.32 ms   | 0 ps         |         0 |             0 |             0 |          0 |
| background | insert            |     1 | 546.87 us     | 546.87 us   | 444.00 us    |         0 |             0 |             1 |          0 |
| background | begin             |     1 | 26.83 us      | 26.83 us    | 0 ps         |         0 |             0 |             0 |          0 |
| msandbox   | create_view       |    82 | 13.05 s       | 277.68 ms   | 25.59 ms     |         0 |             0 |             0 |          0 |
| msandbox   | create_trigger    |     2 | 738.17 ms     | 410.11 ms   | 837.00 us    |         0 |             0 |             0 |          0 |
| msandbox   | create_table      |     1 | 315.86 ms     | 315.86 ms   | 0 ps         |         0 |             0 |             0 |          0 |
| msandbox   | Field List        |   135 | 262.68 ms     | 67.72 ms    | 24.98 ms     |         0 |             0 |             0 |          0 |
| msandbox   | select            |    17 | 183.08 ms     | 78.50 ms    | 59.71 ms     |       406 |          2371 |             0 |          7 |
| msandbox   | show_databases    |     5 | 173.19 ms     | 125.45 ms   | 1.53 ms      |        21 |            21 |             0 |          5 |
| msandbox   | drop_function     |    14 | 66.93 ms      | 66.00 ms    | 66.24 ms     |         0 |             0 |             0 |          0 |
| msandbox   | insert            |     2 | 66.18 ms      | 65.09 ms    | 574.00 us    |         0 |             0 |             6 |          0 |
| msandbox   | show_tables       |     2 | 47.10 ms      | 46.69 ms    | 123.00 us    |       135 |           135 |             0 |          2 |
| msandbox   | Init DB           |     3 | 46.19 ms      | 46.09 ms    | 0 ps         |         0 |             0 |             0 |          0 |
| msandbox   | show_create_table |     1 | 36.10 ms      | 36.10 ms    | 0 ps         |         0 |             0 |             0 |          0 |
| msandbox   | show_slave_status |     2 | 34.82 ms      | 34.69 ms    | 0 ps         |         0 |             0 |             0 |          0 |
| msandbox   | create_procedure  |    26 | 24.32 ms      | 6.57 ms     | 18.21 ms     |         0 |             0 |             0 |          0 |
| msandbox   | create_function   |    14 | 5.46 ms       | 965.16 us   | 3.38 ms      |         0 |             0 |             0 |          0 |
| msandbox   | drop_procedure    |    26 | 2.04 ms       | 155.18 us   | 838.00 us    |         0 |             0 |             0 |          0 |
| msandbox   | create_db         |     1 | 733.32 us     | 733.32 us   | 0 ps         |         0 |             0 |             1 |          0 |
| msandbox   | set_option        |     6 | 638.51 us     | 307.45 us   | 0 ps         |         0 |             0 |             0 |          0 |
| msandbox   | drop_trigger      |     2 | 164.66 us     | 93.56 us    | 0 ps         |         0 |             0 |             0 |          0 |
| msandbox   | Quit              |     3 | 94.20 us      | 69.39 us    | 0 ps         |         0 |             0 |             0 |          0 |
+------------+-------------------+-------+---------------+-------------+--------------+-----------+---------------+---------------+------------+
22 rows in set (0.00 sec)

So the quick answer to the question “who is currently changing data on my replica, that is not the replication SQL thread, and how?” is:

slave1 [localhost] {msandbox} (sys) > SELECT * FROM sys.user_summary_by_statement_type WHERE user != 'background' AND rows_affected > 0;
+----------+-----------+-------+---------------+-------------+--------------+-----------+---------------+---------------+------------+
| user     | statement | total | total_latency | max_latency | lock_latency | rows_sent | rows_examined | rows_affected | full_scans |
+----------+-----------+-------+---------------+-------------+--------------+-----------+---------------+---------------+------------+
| msandbox | insert    |     2 | 66.18 ms      | 65.09 ms    | 574.00 us    |         0 |             0 |             6 |          0 |
| msandbox | create_db |     1 | 733.32 us     | 733.32 us   | 0 ps         |         0 |             0 |             1 |          0 |
+----------+-----------+-------+---------------+-------------+--------------+-----------+---------------+---------------+------------+
2 rows in set (0.00 sec)

Or direct from Performance Schema:

slave1 [localhost] {msandbox} (sys) > SELECT * FROM performance_schema.events_statements_summary_by_user_by_event_name WHERE user IS NOT NULL AND sum_rows_affected > 0\G
*************************** 1. row ***************************
                       USER: msandbox
                 EVENT_NAME: statement/sql/insert
                 COUNT_STAR: 2
             SUM_TIMER_WAIT: 66179499000
             MIN_TIMER_WAIT: 1090899000
             AVG_TIMER_WAIT: 33089749000
             MAX_TIMER_WAIT: 65088600000
              SUM_LOCK_TIME: 574000000
                 SUM_ERRORS: 0
               SUM_WARNINGS: 0
          SUM_ROWS_AFFECTED: 6
              SUM_ROWS_SENT: 0
          SUM_ROWS_EXAMINED: 0
SUM_CREATED_TMP_DISK_TABLES: 0
     SUM_CREATED_TMP_TABLES: 0
       SUM_SELECT_FULL_JOIN: 0
 SUM_SELECT_FULL_RANGE_JOIN: 0
           SUM_SELECT_RANGE: 0
     SUM_SELECT_RANGE_CHECK: 0
            SUM_SELECT_SCAN: 0
      SUM_SORT_MERGE_PASSES: 0
             SUM_SORT_RANGE: 0
              SUM_SORT_ROWS: 0
              SUM_SORT_SCAN: 0
          SUM_NO_INDEX_USED: 0
     SUM_NO_GOOD_INDEX_USED: 0
*************************** 2. row ***************************
                       USER: msandbox
                 EVENT_NAME: statement/sql/create_db
                 COUNT_STAR: 1
             SUM_TIMER_WAIT: 733319000
             MIN_TIMER_WAIT: 733319000
             AVG_TIMER_WAIT: 733319000
             MAX_TIMER_WAIT: 733319000
              SUM_LOCK_TIME: 0
                 SUM_ERRORS: 0
               SUM_WARNINGS: 0
          SUM_ROWS_AFFECTED: 1
              SUM_ROWS_SENT: 0
          SUM_ROWS_EXAMINED: 0
SUM_CREATED_TMP_DISK_TABLES: 0
     SUM_CREATED_TMP_TABLES: 0
       SUM_SELECT_FULL_JOIN: 0
 SUM_SELECT_FULL_RANGE_JOIN: 0
           SUM_SELECT_RANGE: 0
     SUM_SELECT_RANGE_CHECK: 0
            SUM_SELECT_SCAN: 0
      SUM_SORT_MERGE_PASSES: 0
             SUM_SORT_RANGE: 0
              SUM_SORT_ROWS: 0
              SUM_SORT_SCAN: 0
          SUM_NO_INDEX_USED: 0
     SUM_NO_GOOD_INDEX_USED: 0
2 rows in set (0.00 sec)

You can similarly do this by host, by replacing “user” with “host” in the above view names, if you are trying to track down which host is causing issues, too.

2 thoughts on “Quickly tell who is writing to a MySQL replica”

Got something to say?