Profiling Stored Procedures in MySQL 5.7

With the changes to performance_schema in MySQL 5.7 Development Milestone Release it is now possible to analyze and profile the execution of stored programs. This is highly useful if you develop more complex stored procedures and try to find the bottlenecks. The "old" performance_schema up to MySQL 5.6 only reported a CALL statement with a runtime, but no information on statements that were executed WITHIN the stored procedure. Now let's try this in the latest MySQL 5.7.6 DMR release. After creating some test table and a test stored procedure we need to activate the events_statements_history_long consumer, which is OFF by default:

mysql> UPDATE setup_consumers SET ENABLED="YES" 
           WHERE NAME = "events_statements_history_long"; 

Then let's call the stored procedure that we want to inspect:

mysql> CALL test.massinsert(400,405); 

To avoid that we overwrite data from the events_statements_history_long table with the following queries, let's deactivate that consumer ASAP. If you have some concurrent load running on your system, it may be wise to leverage the filter options in performance_schema like setup_actors and/or setup_objects.

mysql> UPDATE setup_consumers SET ENABLED="NO" 
          WHERE NAME = "events_statements_history_long"; 

Next step is to find our CALL statement in the events_statements_history_long table:

mysql> SELECT event_id,sql_text, 
              CONCAT(TIMER_WAIT/1000000000,"ms") AS time 
                 FROM events_statements_history_long 
       WHERE event_name="statement/sql/call_procedure"; +----------+-------------------------------+-----------+ 
| event_id | sql_text                      | time      | +----------+-------------------------------+-----------+ 
| 144      | call massinsert(100,105)      | 0.2090ms  |
| 150      | call massinsert(100,105)      | 79.9659ms | 
| 421      | CALL test.massinsert(400,405) | 74.2078ms | +----------+-------------------------------+-----------+ 
3 rows in set (0,03 sec) 

You see: I tried this stored procedure three times. The one I want to inspect in detail is event_id 421. Let's look at all nested statement events that came from 421:

 mysql> SELECT EVENT_NAME, SQL_TEXT,   
        CONCAT(TIMER_WAIT/1000000000,"ms") AS time   
     FROM events_statements_history_long   
     WHERE nesting_event_id=421 ORDER BY event_id;   
 +--------------------------+-----------------------------------+-----------+   
 | EVENT_NAME               | SQL_TEXT                          | time      |  
 +--------------------------+-----------------------------------+-----------+  
 | statement/sp/stmt        | SET @i = first                    | 0.0253ms  |   
 | statement/sp/stmt        | SET @i = @i + 1                   | 0.0155ms  |   
 | statement/sp/stmt        | INSERT INTO a VALUES (@i,MD5(@i)) | 45.6425ms |   
 | statement/sp/jump_if_not | NULL                              | 0.0311ms  |   
 | statement/sp/stmt        | SET @i = @i + 1                   | 0.0297ms  |   
 | statement/sp/stmt        | INSERT INTO a VALUES (@i,MD5(@i)) | 4.9695ms  |   
 | statement/sp/jump_if_not | NULL                              | 0.0726ms  |   
 | statement/sp/stmt        | SET @i = @i + 1                   | 0.0365ms  |   
 | statement/sp/stmt        | INSERT INTO a VALUES (@i,MD5(@i)) | 6.8518ms  |   
 | statement/sp/jump_if_not | NULL                              | 0.0343ms  |   
 | statement/sp/stmt        | SET @i = @i + 1                   | 0.0316ms  |   
 | statement/sp/stmt        | INSERT INTO a VALUES (@i,MD5(@i)) | 9.9633ms  |   
 | statement/sp/jump_if_not | NULL                              | 0.0309ms  |   
 | statement/sp/stmt        | SET @i = @i + 1                   | 0.0274ms  |   
 | statement/sp/stmt        | INSERT INTO a VALUES (@i,MD5(@i)) | 5.6235ms  |   
 | statement/sp/jump_if_not | NULL                              | 0.0308ms  |
 +--------------------------+-----------------------------------+-----------+  
 16 rows in set (0,06 sec)   

 
Now we have the statements that were executed in the stored procedure "massinsert(400,405)" with their individual execution times and in order of execution. We have all other information available as well, not only execution time. We can access number of rows affected, sql error text, used algorithms, ... All information that performance_schema offers for statement events. This is a great way to analyze your stored procedures. find the most costly statements and improve performance of your stored programs. That is really a great enhancement to performance_schema.