MySQL Bugs: #75156: statements elapsed time with good time resolution

Bug #75156	statements elapsed time with good time resolution
Submitted:	10 Dec 2014 6:54	Modified:	1 Jul 2015 15:47
Reporter:	Simon Mudd (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Performance Schema	Severity:	S3 (Non-critical)
Version:	5.6,5.7	OS:	Any
Assigned to:	Marc ALFF	CPU Architecture:	Any
Tags:	information_schema.processlist, performance_schema.threads

Description:
The TIME column in the output of show processlist, or the performance_schema.threads.processlist_time tables is accurate to 1 second.  On many busy servers I do not allow queries to run for more than a few seconds to avoid locking etc but may have thousands of queries running. So often this value is 0 or sometimes 1.

To get a better idea of how long queries have been running it would be most convenient to have a higher resolution counter, in ms, us etc so that I can sum these values over the running processlist and get a better idea of the runtime of the queries on the server.

Performance_schema has much higher timer resolution for most other timers so doing the same here would be very good.

How to repeat:
RUN:
SHOW PROCESSLIST
SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST
SELECT * FROM PERFORMANCE_SCHEMA.THREADS

Notice the time columns are accurate to 1 second.

Suggested fix:
Change the resolution of the column to be equivalent to what's used elsewhere in say performance_schema, or change it to a fixed/floating value number of seconds.

This extra precision will make measuring the current query list much better.

I'd guess it is too late to put this is 5.7 which is a shame, but I'd love to see that there.

Related to my pstop program (https://github.com/sjmudd/pstop which has a user page that is mainly useless as the runtime resolution here is whole number of seconds and on many systems I use the large number of connected users never do queries for > 1 second...  Having such higher resolution would make this page really interesting, but now it's somewhat limited.

Thank you for the feature request.

Changing the TIME resolution on processlist is:

- an incompatible change for 5.6, because DDL for the TIME column needs to change

- only a partial solution, as it allows to measure the elapsed time for statements (queries) only, but not waits, stages or transactions.

A better way to see statements currently running is to query:
- table performance_schema.events_statements_current

and likewise:
- table performance_schema.events_waits_current
- table performance_schema.events_stages_current
- table performance_schema.events_transactions_current

In these *_current tables, TIMER_WAIT is only populated once the wait/stage/statement/transaction completes.

This is a limitation that can be lifted, a more useful behavior would be:

- for events that are completed already, no change, as TIMER_WAIT is already populated (for timed events)

- for events still executing, change TIMER_WAIT to be the time waited between TIMER_START and NOW, instead of NULL.

Also changing the bug category to a bug (TIMER_WAIT was missed when column END_EVENTID was added) instead of a feature request.

Hi Mark,

I hadn't expected you to change 5.6 with what would be an incompatible change. I was just recording that this is visible in both versions. The intention of the request was for 5.7.

Thanks for taking the time to explain how the data can be collected as many people may not be aware of all the performance_schema tables (and new ones are being added to 5.7).

However, be careful:
* events_stages_* is disabled by default at least in 5.6.
* events_transactions_current is new in 5.7 but *is* enabled, so good to know of that.

I had a quick look and see that I can get the information I was looking for.

root@my56host [performance_schema]> SELECT PROCESSLIST_USER, COUNT(*), SUM(TIMER_WAIT) FROM threads t JOIN events_statements_current esc ON ( t.THREAD_ID = esc.THREAD_ID )  GROUP BY PROCESSL
+------------------+----------+-----------------+
| PROCESSLIST_USER | COUNT(*) | SUM(TIMER_WAIT) |
+------------------+----------+-----------------+
| xxxx             |     1381 |   1248319097000 |
| yyyy             |        2 |     14457603000 |
| zzzz             |        2 |       123496000 |
+------------------+----------+-----------------+
3 rows in set (0.34 sec)

root@my56host [performance_schema]> EXPLAIN SELECT PROCESSLIST_USER, COUNT(*), SUM(TIMER_WAIT) FROM threads t JOIN events_statements_current esc ON ( t.THREAD_ID = esc.THREAD_ID )  GROUP BY PROCESSLIST
+----+-------------+-------+------+---------------+------+---------+------+------+----------------------------------------------------+
| id | select_type | table | type | possible_keys | key  | key_len | ref  | rows | Extra                                              |
+----+-------------+-------+------+---------------+------+---------+------+------+----------------------------------------------------+
|  1 | SIMPLE      | t     | ALL  | NULL          | NULL | NULL    | NULL | 1000 | Using temporary; Using filesort                    |
|  1 | SIMPLE      | esc   | ALL  | NULL          | NULL | NULL    | NULL | 1000 | Using where; Using join buffer (Block Nested Loop) |
+----+-------------+-------+------+---------------+------+---------+------+------+----------------------------------------------------+
2 rows in set (0.00 sec)

root@my56host [performance_schema]> 

So the query can be done, the only thing that potentially is problematic is the join which as performance_schema has no indexes is a bit more expensive than perhaps I'd like.
That said as other stuff I've done with ps-top, I can do a SELECT of the 2 tables myself and join them in the application. Inconsistencies are not an issue and performance will be much better.

So thanks for the feedback and pointers. Either way for 5.7 for those who don't want to do complex stuff like this maybe changing the column type might be an easy way to get the data.
In the meantime I'll look to modify my collections statistics to use P_S as indicated above.

Noted in 5.6.26, 5.7.8, 5.8.0 changelogs.

Current event timing now provides more information. Previously, while
a wait, stage, statement, or transaction event was executing, the
respective tables displayed the event with TIMER_START populated, but
with TIMER_END and TIMER_WAIT as NULL:

events_waits_current
events_stages_current
events_statements_current
events_transactions_current

To make it possible to determine how how long a not-yet-completed
event has been running, the timer columns now are set as follows:

* TIMER_START is populated (unchanged from previous behavior)
* TIMER_END is populated with the current timer value
* TIMER_WAIT is populated with the time elapsed so far (TIMER_END -
  TIMER_START)

To find events that have not yet completed (that is, have no
END_EVENT_ID) and have taken longer than N picoseconds thus far,
monitoring applications can use this expression in queries:

WHERE END_EVENT_ID IS NULL AND TIMER_WAIT > N