EmergencyEMERGENCY? Get 24/7 Help Now!

Profiling MySQL queries from Performance Schema

 | April 16, 2015 |  Posted In: MySQL

PREVIOUS POST
NEXT POST

When optimizing queries and investigating performance issues, MySQL comes with built in support for profiling queries aka SET profiling = 1; . This is already awesome and simple to use, but why the PERFORMANCE_SCHEMA alternative?

Because profiling will be removed soon (already deprecated on MySQL 5.6 ad 5.7); the built-in profiling capability can only be enabled per session. This means that you cannot capture profiling information for queries running from other connections. If you are using Percona Server, the profiling option for log_slow_verbosity is a nice alternative, unfortunately, not everyone is using Percona Server.

Now, for a quick demo: I execute a simple query and profile it below. Note that all of these commands are executed from a single session to my test instance.

To demonstrate how we can achieve the same with Performance Schema, we first identify our current connection id. In the real world, you might want to get the connection/processlist id of the thread you want to watch i.e. from SHOW PROCESSLIST .

Next, we identify the bounding EVENT_IDs for the statement stages. We will look for the statement we wanted to profile using the query below from the events_statements_history_long table. Your LIMIT clause may vary depending on how much queries the server might be getting.

From the results above, we are mostly interested with the EVENT_ID and END_EVENT_ID values from the second row, this will give us the stage events of this particular query from the events_stages_history_long table.

As you can see the results are pretty close, not exactly the same but close. SHOW PROFILE shows Duration in seconds, while the results above is in milliseconds.

Some limitations to this method though:

  • As we’ve seen it takes a few hoops to dish out the information we need. Because we have to identify the statement we have to profile manually, this procedure may not be easy to port into tools like the sys schema or pstop.
  • Only possible if Performance Schema is enabled (by default its enabled since MySQL 5.6.6, yay!)
  • Does not cover all metrics compared to the native profiling i.e. CONTEXT SWITCHES, BLOCK IO, SWAPS
  • Depending on how busy the server you are running the tests, the sizes of the history tables may be too small, as such you either have to increase or loose the history to early i.e. performance_schema_events_stages_history_long_size variable. Using ps_history might help in this case though with a little modification to the queries.
  • The resulting Duration per event may vary, I would think this may be due to the additional as described on performance_timers table. In any case we hope to get this cleared up as result when this bug is fixed.
PREVIOUS POST
NEXT POST
Jervin Real

As Senior Consultant, Jervin partners with Percona's customers on building reliable and highly performant MySQL infrastructures while also doing other fun stuff like watching cat videos on the internet. Jervin joined Percona in Apr 2010.

5 Comments

  • I could not repeat this with mysql 5.6.11.

    mysql> SHOW VARIABLES LIKE ‘performance_schema’;
    +——————–+——-+
    | Variable_name | Value |
    +——————–+——-+
    | performance_schema | ON |
    +——————–+——-+
    1 row in set (0.00 sec)

    mysql> SELECT THREAD_ID, EVENT_ID, END_EVENT_ID, SQL_TEXT, NESTING_EVENT_ID FROM events_statements_history_long WHERE THREAD_ID=@my_thread_id ORDER BY EVENT_ID DESC LIMIT 3 \G
    Empty set (0.00 sec)

  • Vlad,

    Have you enabled your consumers and instruments for statements and stages?

  • Jervin,

    I could not get any from events_statements_history_long even after enabled setup_instruments and setup_consumers

    version 5.6.24 (Percona)

  • You’ll have to enable the proper consumers and instruments. What Jervin said in the comment above is correct but the consumers query does have a typo. The fixed query is:

    UPDATE performance_schema.setup_consumers
    SET ENABLED = ‘YES’
    WHERE NAME LIKE ‘events_statements%’ OR NAME LIKE ‘events_stages%’;

    Instruments one is okay:

    UPDATE performance_schema.setup_instruments
    SET ENABLED = ‘YES’, TIMED = ‘YES’
    WHERE NAME LIKE ‘statement/%’ OR NAME LIKE ‘stage/%’;

  • It’s a shame SET profiling = 1; is deprecated > 5.5. I just activated performance_schema and a query that took 0.51 seconds, now takes 2.32 seconds. There may be other reasons (hence why I am optimizing in the first place), but for now, this tool is doing a great job to impact performance!

Leave a Reply