on time in mysql processlist

There was one MySQL feature that I was always very afraid to ask for. I sure needed it for past 15 years of my MySQL practice, and yet I never got to it. I wanted MySQL processlist (‘SHOW PROCESSLIST’, later – information_schema.processlist) to have more accurate query execution time.

I submitted a patch for that to MongoDB (and it got merged and released really quickly). I couldn’t admit to myself and others that MySQL does not have this functionality, even though it is hard to reason about systems in production without such data.

When 99.999% of queries happen within 1s, one has to resort to statistical analysis of zeroes and ones to determine how long they may be running (that is, if nine queries are at 0s and one is at 1s, there’s a chance that all of them are running for 0.1s). Unfortunately, this kind of statistical analysis is not feasible in runtime environment when dealing with issues at hand.

One of reasons why I did not submit this feature request is because I did not want to be subjected to the embarrassment of not understanding MySQL Release Cycles, Stability and Performance Architecture.

Someone else (Hi, Simon!) decided to ask for this in late 2014.
By 2015 spring MySQL engineering team responded with “thank you for your feature request”.
Few months later engineering team wrote that they won’t be improving tools like processlist and instead will change behavior of performance_schema tables (which were not useful at that time anyway).

So, even though MySQL already shows time based on arithmetics of subtracting query start time from current time, having the tiny improvement on top of that was not deemed the right way, because, I guess, it doesn’t fit the Performance Vision.

So, I’m confused. I’d like to see “SHOW PROCESSLIST” expanded to have this. Over time you learn the quirks and differences between it and I_S.PROCESSLIST that was added later in 5.1 (for example, one of them will truncate queries at zero-bytes, other will truncate queries at invalid unicode, even if data in queries is all binary). The whole truncation hierarchy of “SHOW PROCESSLIST” -> “I_S.PROCESSLIST” -> “SHOW FULL PROCESSLIST” deserves a separate discussion (rant?).

Enter Performance Schema. Assuming you don’t care about degraded performance of your MySQL environment you compiled it in.

It already has performance_schema.threads table, which has same second-level precision on the PROCESSLIST_TIME column. It has few additional columns over standard processlist although it has a very interesting behavior – it doesn’t show prepared statement texts in PROCESSLIST_INFO, so that information is truncated to 0 bytes (regular queries are truncated at 1024 bytes). So we have a third place to look for information, it was added in newer release, is Much Better (I don’t know in what way though) than existing INFORMATION_SCHEMA and SHOW options.

Apparently the real place to look at this (with bugs fixed in latest release) is performance_schema.events_statements_current.

Timing data is in picoseconds so everything has to be divided by a trillion to get a meaningful number. I can mentally handle microseconds or milliseconds, but dealing with 17-digit-numbers is not for my simpleton mind. This is not supposed to be used directly and one has to use specially built tools to access this data or write their own layers of views.

It won’t have user or schema information, so you’re forced to join to another table (threads or I_S). The sad part of this is that there’s no indexing/direct access methods provided and MySQL will use same methods as for any other non-indexed joins… The query would look something like:

select end_event_id, processlist_id id, processlist_user user, processlist_host host, processlist_db db, processlist_command command, processlist_state state, if(end_event_id is null,timer_wait/1000000000000,processlist_time) time, if (end_event_id is null, sql_text, NULL) info from events_statements_current right join threads using (thread_id) where type='foreground';

Now that I got to actual source of data I was wondering how useful it is in production environment. The answer is “not much”. Apparently if you have few hundred queries running MySQL will be writing to gigabytes of memory courtesy of Performance Schema SQL digests feature even with said feature disabled.
I filed a bug here, but was still confused.

It looks that the way to answer any idea how to improve MySQL DBA experience is by throwing in more expensive, buggy, complicated features, that are painful or impossible to use and wave a flag of “nobody complained but you”.

So I guess I can expose myself to more embarrassment, file same bug again. I really can’t believe that current implementation is supposed to be helpful and useful to DBAs. I guess someone does. Unfortunately, the only time they try their features is when they have to write a blog post how to use it.

P.S. We use either instrumentation on client side or our slocket – slow-log-datagram-socket – interface to do ad-hoc aggregations with high precision timings. I have no idea why we didn’t add direct high precision processlist ourselves.

See also:

7 thoughts on “on time in mysql processlist”

  1. mysql[sandbox]> select @@version, time, time_ms, info from information_Schema.processlist;
    +——————–+——+———+—————————————————————————+
    | @@version | time | time_ms | info |
    +——————–+——+———+—————————————————————————+
    | 5.5.42-MariaDB-log | 0 | 0.445 | select @@version, time, time_ms, info from information_Schema.processlist |
    +——————–+——+———+—————————————————————————+
    1 row in set (0.00 sec)

  2. Hi Domas,

    Notwithstanding your other comments, this is an example that should work out of the box on MySQL 5.7 (sys ships by default):

    mysql> SELECT * FROM sys.processlist WHERE conn_id > 1\G
    *************************** 1. row ***************************
    thd_id: 32
    conn_id: 5
    user: msandbox@localhost
    db: performance_schema
    command: Query
    state: Sending data
    time: 0
    current_statement: SELECT * FROM sys.processlist WHERE conn_id > 1
    statement_latency: 2.99 ms
    progress: NULL
    lock_latency: 856.00 us
    rows_examined: 0
    rows_sent: 0
    rows_affected: 0
    tmp_tables: 4
    tmp_disk_tables: 1
    full_scan: YES
    last_statement: NULL
    last_statement_latency: NULL
    current_memory: 2.91 MiB
    last_wait: NULL
    last_wait_latency: NULL
    source: NULL
    pid: 15871
    program_name: mysql
    1 row in set (0.05 sec)

    Mark Leith has accepted a pull request suggestion I had to have a processlist view for foreground threads only. It will hopefully make it into a future version:
    https://github.com/MarkLeith/mysql-sys/blob/development/views/p_s/sessions.sql

  3. Hi Domas,

    Notwithstanding your other comments, this is an example that should work out of the box on MySQL 5.7 (sys ships by default):

    mysql> SELECT * FROM sys.processlist WHERE conn_id > 1\G
    *************************** 1. row ***************************
    thd_id: 32
    conn_id: 5
    user: msandbox@localhost
    db: performance_schema
    command: Query
    state: Sending data
    time: 0
    current_statement: SELECT * FROM sys.processlist WHERE conn_id > 1
    statement_latency: 2.99 ms
    progress: NULL
    lock_latency: 856.00 us
    rows_examined: 0
    rows_sent: 0
    rows_affected: 0
    tmp_tables: 4
    tmp_disk_tables: 1
    full_scan: YES
    last_statement: NULL
    last_statement_latency: NULL
    current_memory: 2.91 MiB
    last_wait: NULL
    last_wait_latency: NULL
    source: NULL
    pid: 15871
    program_name: mysql
    1 row in set (0.05 sec)

    Mark Leith has accepted a pull request suggestion I had to have a processlist view for foreground threads only. It will hopefully make it into a future version:
    https://github.com/MarkLeith/mysql-sys/blob/development/views/p_s/sessions.sql

  4. Also interesting: Why do they need my home address, phone number etc. to file a bug report?

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s