Monitoring Processes with Performance Schema in MySQL 5.6

I’ve written before about how you can monitor the last wait per connection with Performance Schema in MySQL 5.5.

That solution joined the performance_schema.events_waits_current with the performance_schema.threads and INFORMATION_SCHEMA.PROCESSLIST tables.

Joining to INFORMATION_SCHEMA.PROCESSLIST is a necessary evil within MySQL 5.5, to be able to get the user and host information etc. – however it is certainly not optimal, because using INFORMATION_SCHEMA.PROCESSLIST (and it’s SHOW [FULL] PROCESSLIST cousin) incurs a bunch of mutexes to be locked – the fill_schema_processlist() function attempts to lock LOCK_thread_count globally (which will block new connections whilst the entire processlist output is generated), as well as tmp->LOCK_thd_data per thread that it iterates over (which could in turn stall each thread if they try to access this) and mysys_var->mutex which protects the mysys_var struct (used around killing connections).

If you are polling the processlist output frequently (I’ve seen some solutions out there poll it once a second, or even lower, sometimes), then the chances are, you are stalling real application connections as well. This is why we don’t use these commands within MySQL Enterprise Monitor for things like Query Analysis.

With that in mind, we have now extended the performance_schema.threads table in MySQL 5.6 to include all of the information that is available within the INFORMATION_SCHEMA.PROCESSLIST table:

mysql> desc performance_schema.threads;
+---------------------+------------------+------+-----+---------+-------+
| Field               | Type             | Null | Key | Default | Extra |
+---------------------+------------------+------+-----+---------+-------+
| THREAD_ID           | int(11)          | NO   |     | NULL    |       |
| NAME                | varchar(128)     | NO   |     | NULL    |       |
| TYPE                | varchar(10)      | NO   |     | NULL    |       |
| PROCESSLIST_ID      | int(11)          | YES  |     | NULL    |       |
| PROCESSLIST_USER    | varchar(16)      | YES  |     | NULL    |       |
| PROCESSLIST_HOST    | varchar(60)      | YES  |     | NULL    |       |
| PROCESSLIST_DB      | varchar(64)      | YES  |     | NULL    |       |
| PROCESSLIST_COMMAND | varchar(16)      | YES  |     | NULL    |       |
| PROCESSLIST_TIME    | bigint(20)       | YES  |     | NULL    |       |
| PROCESSLIST_STATE   | varchar(64)      | YES  |     | NULL    |       |
| PROCESSLIST_INFO    | longtext         | YES  |     | NULL    |       |
| PARENT_THREAD_ID    | int(11)          | YES  |     | NULL    |       |
| ROLE                | varchar(64)      | YES  |     | NULL    |       |
| INSTRUMENTED        | enum('YES','NO') | NO   |     | NULL    |       |
+---------------------+------------------+------+-----+---------+-------+
14 rows in set (0.02 sec)

As with all other instrumentation within Performance Schema, this is entirely non-blocking. When you upgrade to MySQL 5.6, it’s time to start forgetting about SHOW PROCESSLIST, or INFORMATION_SCHEMA.PROCESSLIST. They’ve served us well for a long time, but it’s time to wave goodbye to their contentious ways.

There’s another bonus in the threads table within MySQL 5.6 as well, and that is the newly added INSTRUMENTED column. This allows you turn on and off instrumentation, per thread, dynamically. You do this by simply running an UPDATE:

mysql> select name, type, instrumented from threads;
+----------------------------------------+------------+--------------+
| name                                   | type       | instrumented |
+----------------------------------------+------------+--------------+
| thread/sql/main                        | BACKGROUND | YES          |
| thread/innodb/io_handler_thread        | BACKGROUND | YES          |
| thread/innodb/io_handler_thread        | BACKGROUND | YES          |
| thread/innodb/io_handler_thread        | BACKGROUND | YES          |
| thread/innodb/io_handler_thread        | BACKGROUND | YES          |
| thread/innodb/io_handler_thread        | BACKGROUND | YES          |
| thread/innodb/io_handler_thread        | BACKGROUND | YES          |
| thread/innodb/io_handler_thread        | BACKGROUND | YES          |
| thread/innodb/io_handler_thread        | BACKGROUND | YES          |
| thread/innodb/io_handler_thread        | BACKGROUND | YES          |
| thread/innodb/io_handler_thread        | BACKGROUND | YES          |
| thread/innodb/srv_lock_timeout_thread  | BACKGROUND | YES          |
| thread/innodb/srv_error_monitor_thread | BACKGROUND | YES          |
| thread/innodb/srv_monitor_thread       | BACKGROUND | YES          |
| thread/innodb/srv_master_thread        | BACKGROUND | YES          |
| thread/innodb/srv_purge_thread         | BACKGROUND | YES          |
| thread/innodb/page_cleaner_thread      | BACKGROUND | YES          |
| thread/sql/shutdown                    | BACKGROUND | YES          |
| thread/sql/manager                     | BACKGROUND | YES          |
| thread/sql/con_sockets                 | BACKGROUND | YES          |
| thread/sql/one_connection              | FOREGROUND | YES          |
| thread/sql/one_connection              | FOREGROUND | YES          |
| thread/sql/one_connection              | FOREGROUND | YES          |
| thread/sql/one_connection              | FOREGROUND | YES          |
| thread/sql/one_connection              | FOREGROUND | YES          |
| thread/sql/one_connection              | FOREGROUND | YES          |
| thread/sql/one_connection              | FOREGROUND | YES          |
+----------------------------------------+------------+--------------+
27 rows in set (0.00 sec)

mysql> update threads set instrumented = 'NO' where name != 'thread/sql/one_connection';
Query OK, 20 rows affected (0.00 sec)
Rows matched: 20  Changed: 20  Warnings: 0

mysql> select name, type, instrumented from threads;
+----------------------------------------+------------+--------------+
| name                                   | type       | instrumented |
+----------------------------------------+------------+--------------+
| thread/sql/main                        | BACKGROUND | NO           |
| thread/innodb/io_handler_thread        | BACKGROUND | NO           |
| thread/innodb/io_handler_thread        | BACKGROUND | NO           |
| thread/innodb/io_handler_thread        | BACKGROUND | NO           |
| thread/innodb/io_handler_thread        | BACKGROUND | NO           |
| thread/innodb/io_handler_thread        | BACKGROUND | NO           |
| thread/innodb/io_handler_thread        | BACKGROUND | NO           |
| thread/innodb/io_handler_thread        | BACKGROUND | NO           |
| thread/innodb/io_handler_thread        | BACKGROUND | NO           |
| thread/innodb/io_handler_thread        | BACKGROUND | NO           |
| thread/innodb/io_handler_thread        | BACKGROUND | NO           |
| thread/innodb/srv_lock_timeout_thread  | BACKGROUND | NO           |
| thread/innodb/srv_error_monitor_thread | BACKGROUND | NO           |
| thread/innodb/srv_monitor_thread       | BACKGROUND | NO           |
| thread/innodb/srv_master_thread        | BACKGROUND | NO           |
| thread/innodb/srv_purge_thread         | BACKGROUND | NO           |
| thread/innodb/page_cleaner_thread      | BACKGROUND | NO           |
| thread/sql/shutdown                    | BACKGROUND | NO           |
| thread/sql/manager                     | BACKGROUND | NO           |
| thread/sql/con_sockets                 | BACKGROUND | NO           |
| thread/sql/one_connection              | FOREGROUND | YES          |
| thread/sql/one_connection              | FOREGROUND | YES          |
| thread/sql/one_connection              | FOREGROUND | YES          |
| thread/sql/one_connection              | FOREGROUND | YES          |
| thread/sql/one_connection              | FOREGROUND | YES          |
+----------------------------------------+------------+--------------+
25 rows in set (0.00 sec)

This then enables/disables all instrumentation within Performance Schema for each thread appropriately.

Now we have all of this data directly within the threads table, we can also start joining it to some of the other tables within Performance Schema as well, to get even more data on what threads are currently doing within the database. Particularly, we can join to the new events_statements_current table as well, to get extra information on statement execution (you will need to ensure that the events_statements_current consumer is enabled within the setup_consumers table).

Here’s an example of another view I’m about to add to ps_helper:

DROP VIEW IF EXISTS processlist_full;

CREATE VIEW processlist_full AS
SELECT pps.thread_id AS thd_id,
       pps.processlist_id AS conn_id,
       IF(pps.name = 'thread/sql/one_connection', 
          CONCAT(pps.processlist_user, '@', pps.processlist_host), 
          REPLACE(pps.name, 'thread/', '')) user,
       pps.processlist_db AS db,
       pps.processlist_command AS command,
       pps.processlist_state AS state,
       pps.processlist_time AS time,
       format_statement(pps.processlist_info) AS current_statement,
       IF(esc.timer_wait IS NOT NULL,
          format_statement(esc.sql_text),
          NULL) AS last_statement,
       IF(esc.timer_wait IS NOT NULL,
          format_time(esc.timer_wait),
          NULL) as last_statement_latency,
       format_time(esc.lock_time) AS lock_latency,
       esc.rows_examined,
       esc.rows_sent,
       esc.rows_affected,
       esc.created_tmp_tables AS tmp_tables,
       esc.created_tmp_disk_tables as tmp_disk_tables,
       IF(esc.no_good_index_used > 0 OR esc.no_index_used > 0, 
          'YES', 'NO') AS full_scan,
       ewc.event_name AS last_wait,
       IF(ewc.timer_wait IS NULL AND ewc.event_name IS NOT NULL, 
          'Still Waiting', 
          format_time(ewc.timer_wait)) last_wait_latency,
       ewc.source
  FROM performance_schema.threads AS pps
  LEFT JOIN performance_schema.events_waits_current AS ewc USING (thread_id)
  LEFT JOIN performance_schema.events_statements_current as esc USING (thread_id)
ORDER BY pps.processlist_time DESC, last_wait_latency DESC;

And some sample output:

...
*************************** 3. row ***************************
                thd_id: 11617
               conn_id: 11596
                  user: root@localhost
                    db: mysql
               command: Sleep
                 state: cleaning up
                  time: 0
     current_statement: NULL
        last_statement: SELECT CAST(SUM_NUMBER_OF_BYTE ... nnodb/innodb_log_file' limit 1
last_statement_latency: 2.02 ms
          lock_latency: 0 ps
         rows_examined: 39
             rows_sent: 0
         rows_affected: 0
            tmp_tables: 0
       tmp_disk_tables: 0
             full_scan: YES
             last_wait: idle
     last_wait_latency: Still Waiting
                source: mysqld.cc:848
*************************** 4. row ***************************
                thd_id: 12474
               conn_id: 12453
                  user: root@localhost
                    db: mem
               command: Sleep
                 state: cleaning up
                  time: 0
     current_statement: NULL
        last_statement: commit
last_statement_latency: 952.49 µs
          lock_latency: 0 ps
         rows_examined: 0
             rows_sent: 0
         rows_affected: 0
            tmp_tables: 0
       tmp_disk_tables: 0
             full_scan: NO
             last_wait: idle
     last_wait_latency: Still Waiting
                source: mysqld.cc:848
*************************** 5. row ***************************
                thd_id: 12400
               conn_id: 12379
                  user: root@localhost
                    db: ps_helper
               command: Query
                 state: Copying to tmp table
                  time: 0
     current_statement: SELECT pps.thread_id AS thd_id ... e DESC, last_wait_latency DESC
        last_statement: NULL
last_statement_latency: NULL
          lock_latency: 1.00 ms
         rows_examined: 0
             rows_sent: 0
         rows_affected: 0
            tmp_tables: 1
       tmp_disk_tables: 0
             full_scan: YES
             last_wait: wait/synch/mutex/sql/THD::LOCK_thd_data
     last_wait_latency: 77.11 ns
                source: sql_class.h:3843
...

Listed here are two idle connections, and one active connection (which was the one gathering the data).

The events_statements_current table stores the currently executing, or last executed (if no currently executing), statement per thread. This means that this new form of processlist can not only tell you what is currently executing, but also what last executed for sleeping threads.

All of the statistics listed, such as lock latency, row stats, temporary table stats are for either the current or last statement too. So with “conn_id: 12453″ we can see that it last executed a COMMIT (in the last_statement column), which took 952.49 µs (in the last_statement_latency column).

I can’t count how many times I wanted to know the last statement that executed for sleeping connections (particularly those holding open a transaction), nor how many times customers and users asked that question whilst I was in the MySQL Support group, so this is a great step forward.

For idle connections, we now have a new “idle” wait type, which records how long sessions sit idle for as well. For sleeping connections this will always be the current wait (unless you disable the idle instrument). However for active connections, we show the last wait that happened within that statement’s execution.

You can see that the last session listed is copying to a temporary table, had lock latency of 1 ms, and last waited on the wait/synch/mutex/sql/THD::LOCK_thd_data event, which basically corresponds to the LOCK_thd_data mutex I was talking about above.

But hang on? I said above that SHOW PROCESSLIST etc. lock this in a blocking way as well right? And this is also grabbing this mutex? What gives? Well, performance_schema is true table storage engine, and the statement executed is still grabbing a read lock against the performance schema table. The statement itself is also creating a temporary table, doing it’s own thing within it’s own thread as well, and whilst doing that, threads tend to grab their own LOCK_thd_data mutex (there is one per thread), to protect access from other threads – for instance, we LOCK_thd_data to set the current query string, which protects SHOW FULL PROCESSLIST from reading a half written query string for it’s INFO. That doesn’t change for Performance Schema access – but it does help to show just the kind of contention that SHOW FULL PROCESSLIST can cause!

The above view only gets a subset of the available data per statement available within the events_statements_current table as well – I’ve omitted all of the sort / scan information for instance. You can add these to the view as you see fit.

I’ll be adding some views like this to ps_helper shortly. If you have any feedback in the meantime feel free to comment!

5 comments

  1. Why not make SHOW PROCESSLIST and I_S.PROCESSLIST use the same backend as the P_S implementation so that they are all effectively doing the same thing and you can use any/all of them? Why have two implementations of the same thing, some of which have negative performance impact on the server?

    • Hmm, perhaps that would be possible.

      One key thing is that Performance Schema can be entirely disabled if you so wish, however SHOW PROCESSLIST and INFORMATION_SCHEMA.PROCESSLIST both can not be.

      I guess it may be possible to switch implementations when this is the case though.. I’d open a feature request over at bugs.mysql.com..

      • And I should also note, I’d rather see INFORMATION_SCHEMA.PROCESSLIST deprecated, and not have to maintain the *three* ways. I_S for database metadata.. P_S for database runtime statistics..

Got something to say?