Bug #73112 Performance Schema - Statement Tables - Stored Procedures Counters are 0
Submitted: 25 Jun 2014 11:47 Modified: 23 Feb 2016 15:52
Reporter: Kenny Gryp Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Performance Schema Severity:S3 (Non-critical)
Version:5.6.16, 5.6.17, 5.6.20 OS:Linux
Assigned to: Marc Alff CPU Architecture:Any

[25 Jun 2014 11:47] Kenny Gryp
Description:
Most SUM_* counters in Performance Schema remain zero for Stored Procedure Calls.

How to repeat:

drop database test;
create database test;
create table test.test (a int);
insert into test.test values (1);
insert into test.test select * from test.test;
insert into test.test select * from test.test;
insert into test.test select * from test.test;
insert into test.test select * from test.test;
insert into test.test select * from test.test;
insert into test.test select * from test.test;
insert into test.test select * from test.test;
insert into test.test select * from test.test;
insert into test.test select * from test.test;
insert into test.test select * from test.test;
insert into test.test select * from test.test;
insert into test.test select * from test.test;
insert into test.test select * from test.test;
DELIMITER ;;
create procedure test.testing () BEGIN select * from test.test; end; ;;  
DELIMITER ;
TRUNCATE TABLE performance_schema.events_statements_summary_by_digest;

Now we select using stored procedures and direct select:

select * from test.test;
call test.testing;
select * from performance_schema.events_statements_summary_by_digest\G

mysql> select * from performance_schema.events_statements_summary_by_digest\G
*************************** 1. row ***************************
                SCHEMA_NAME: NULL
                     DIGEST: e4a84a547a18a89f4708509a720def58
                DIGEST_TEXT: TRUNCATE TABLE performance_schema . events_statements_summary_by_digest 
                 COUNT_STAR: 1
             SUM_TIMER_WAIT: 2380214000
             MIN_TIMER_WAIT: 2380214000
             AVG_TIMER_WAIT: 2380214000
             MAX_TIMER_WAIT: 2380214000
              SUM_LOCK_TIME: 1229000000
                 SUM_ERRORS: 0
               SUM_WARNINGS: 0
          SUM_ROWS_AFFECTED: 0
              SUM_ROWS_SENT: 0
          SUM_ROWS_EXAMINED: 0
SUM_CREATED_TMP_DISK_TABLES: 0
     SUM_CREATED_TMP_TABLES: 0
       SUM_SELECT_FULL_JOIN: 0
 SUM_SELECT_FULL_RANGE_JOIN: 0
           SUM_SELECT_RANGE: 0
     SUM_SELECT_RANGE_CHECK: 0
            SUM_SELECT_SCAN: 0
      SUM_SORT_MERGE_PASSES: 0
             SUM_SORT_RANGE: 0
              SUM_SORT_ROWS: 0
              SUM_SORT_SCAN: 0
          SUM_NO_INDEX_USED: 0
     SUM_NO_GOOD_INDEX_USED: 0
                 FIRST_SEEN: 2014-06-25 11:44:39
                  LAST_SEEN: 2014-06-25 11:44:39
*************************** 2. row ***************************
                SCHEMA_NAME: NULL
                     DIGEST: 0869d236ee3d47c52d9bd0e9058355aa
                DIGEST_TEXT: SELECT * FROM test . test 
                 COUNT_STAR: 1
             SUM_TIMER_WAIT: 10196683000
             MIN_TIMER_WAIT: 10196683000
             AVG_TIMER_WAIT: 10196683000
             MAX_TIMER_WAIT: 10196683000
              SUM_LOCK_TIME: 68000000
                 SUM_ERRORS: 0
               SUM_WARNINGS: 0
          SUM_ROWS_AFFECTED: 0
              SUM_ROWS_SENT: 8192
          SUM_ROWS_EXAMINED: 8192
SUM_CREATED_TMP_DISK_TABLES: 0
     SUM_CREATED_TMP_TABLES: 0
       SUM_SELECT_FULL_JOIN: 0
 SUM_SELECT_FULL_RANGE_JOIN: 0
           SUM_SELECT_RANGE: 0
     SUM_SELECT_RANGE_CHECK: 0
            SUM_SELECT_SCAN: 1
      SUM_SORT_MERGE_PASSES: 0
             SUM_SORT_RANGE: 0
              SUM_SORT_ROWS: 0
              SUM_SORT_SCAN: 0
          SUM_NO_INDEX_USED: 1
     SUM_NO_GOOD_INDEX_USED: 0
                 FIRST_SEEN: 2014-06-25 11:44:39
                  LAST_SEEN: 2014-06-25 11:44:39
*************************** 3. row ***************************
                SCHEMA_NAME: NULL
                     DIGEST: c6e4d1227092a9f072d02ab15c587cbf
                DIGEST_TEXT: CALL test . testing 
                 COUNT_STAR: 1
             SUM_TIMER_WAIT: 10309673000
             MIN_TIMER_WAIT: 10309673000
             AVG_TIMER_WAIT: 10309673000
             MAX_TIMER_WAIT: 10309673000
              SUM_LOCK_TIME: 62000000
                 SUM_ERRORS: 0
               SUM_WARNINGS: 0
          SUM_ROWS_AFFECTED: 0
              SUM_ROWS_SENT: 0
          SUM_ROWS_EXAMINED: 0
SUM_CREATED_TMP_DISK_TABLES: 0
     SUM_CREATED_TMP_TABLES: 0
       SUM_SELECT_FULL_JOIN: 0
 SUM_SELECT_FULL_RANGE_JOIN: 0
           SUM_SELECT_RANGE: 0
     SUM_SELECT_RANGE_CHECK: 0
            SUM_SELECT_SCAN: 0
      SUM_SORT_MERGE_PASSES: 0
             SUM_SORT_RANGE: 0
              SUM_SORT_ROWS: 0
              SUM_SORT_SCAN: 0
          SUM_NO_INDEX_USED: 0
     SUM_NO_GOOD_INDEX_USED: 0
                 FIRST_SEEN: 2014-06-25 11:44:39
                  LAST_SEEN: 2014-06-25 11:44:39
[25 Jun 2014 11:52] Kenny Gryp
This also happens for the other statements tables:

*************************** 3. row ***************************
              THREAD_ID: 189850
               EVENT_ID: 41434
           END_EVENT_ID: 49629
             EVENT_NAME: statement/sql/call_procedure
                 SOURCE: mysqld.cc:939
            TIMER_START: 3541609759914284000
              TIMER_END: 3541609772022477000
             TIMER_WAIT: 12108193000
              LOCK_TIME: 0
               SQL_TEXT: call test.testing
                 DIGEST: c6e4d1227092a9f072d02ab15c587cbf
            DIGEST_TEXT: CALL test . testing 
         CURRENT_SCHEMA: performance_schema
            OBJECT_TYPE: NULL
          OBJECT_SCHEMA: NULL
            OBJECT_NAME: NULL
  OBJECT_INSTANCE_BEGIN: NULL
            MYSQL_ERRNO: 0
      RETURNED_SQLSTATE: 00000
           MESSAGE_TEXT: NULL
                 ERRORS: 0
               WARNINGS: 0
          ROWS_AFFECTED: 0
              ROWS_SENT: 0
          ROWS_EXAMINED: 0
CREATED_TMP_DISK_TABLES: 0
     CREATED_TMP_TABLES: 0
       SELECT_FULL_JOIN: 0
 SELECT_FULL_RANGE_JOIN: 0
           SELECT_RANGE: 0
     SELECT_RANGE_CHECK: 0
            SELECT_SCAN: 0
      SORT_MERGE_PASSES: 0
             SORT_RANGE: 0
              SORT_ROWS: 0
              SORT_SCAN: 0
          NO_INDEX_USED: 0
     NO_GOOD_INDEX_USED: 0
       NESTING_EVENT_ID: NULL
     NESTING_EVENT_TYPE: NULL
[25 Jun 2014 11:52] Kenny Gryp
.
[25 Jun 2014 11:55] Kenny Gryp
The strange thing is that in some other stored procedures, I do see counter values.... Not sure when...
[25 Jun 2014 11:57] Kenny Gryp
Configuration:

+--------------------------------------------------------+-------+
| Variable_name                                          | Value |
+--------------------------------------------------------+-------+
| performance_schema                                     | ON    |
| performance_schema_accounts_size                       | 100   |
| performance_schema_digests_size                        | 10000 |
| performance_schema_events_stages_history_long_size     | 10000 |
| performance_schema_events_stages_history_size          | 10    |
| performance_schema_events_statements_history_long_size | 10000 |
| performance_schema_events_statements_history_size      | 10    |
| performance_schema_events_waits_history_long_size      | 10000 |
| performance_schema_events_waits_history_size           | 10    |
| performance_schema_hosts_size                          | 100   |
| performance_schema_max_cond_classes                    | 80    |
| performance_schema_max_cond_instances                  | 14100 |
| performance_schema_max_file_classes                    | 50    |
| performance_schema_max_file_handles                    | 32768 |
| performance_schema_max_file_instances                  | 19231 |
| performance_schema_max_mutex_classes                   | 200   |
| performance_schema_max_mutex_instances                 | 36000 |
| performance_schema_max_rwlock_classes                  | 40    |
| performance_schema_max_rwlock_instances                | 17400 |
| performance_schema_max_socket_classes                  | 10    |
| performance_schema_max_socket_instances                | 5020  |
| performance_schema_max_stage_classes                   | 150   |
| performance_schema_max_statement_classes               | 168   |
| performance_schema_max_table_handles                   | 8192  |
| performance_schema_max_table_instances                 | 12500 |
| performance_schema_max_thread_classes                  | 50    |
| performance_schema_max_thread_instances                | 5100  |
| performance_schema_session_connect_attrs_size          | 512   |
| performance_schema_setup_actors_size                   | 100   |
| performance_schema_setup_objects_size                  | 100   |
| performance_schema_users_size                          | 100   |
+--------------------------------------------------------+-------+

mysql> select * from setup_actors;
+------+------+------+
| HOST | USER | ROLE |
+------+------+------+
| %    | %    | %    |
+------+------+------+
1 row in set (0.00 sec)

mysql> select * from setup_consumers;
+--------------------------------+---------+
| NAME                           | ENABLED |
+--------------------------------+---------+
| events_stages_current          | NO      |
| events_stages_history          | NO      |
| events_stages_history_long     | NO      |
| events_statements_current      | YES     |
| events_statements_history      | NO      |
| events_statements_history_long | NO      |
| events_waits_current           | NO      |
| events_waits_history           | NO      |
| events_waits_history_long      | NO      |
| global_instrumentation         | YES     |
| thread_instrumentation         | YES     |
| statements_digest              | YES     |
+--------------------------------+---------+
12 rows in set (0.00 sec)

mysql> select * from setup_objects;
+-------------+--------------------+-------------+---------+-------+
| OBJECT_TYPE | OBJECT_SCHEMA      | OBJECT_NAME | ENABLED | TIMED |
+-------------+--------------------+-------------+---------+-------+
| TABLE       | mysql              | %           | NO      | NO    |
| TABLE       | performance_schema | %           | NO      | NO    |
| TABLE       | information_schema | %           | NO      | NO    |
| TABLE       | %                  | %           | YES     | YES   |
+-------------+--------------------+-------------+---------+-------+
4 rows in set (0.00 sec)

(ALL default, also for setup_instruments)
[26 Jun 2014 8:14] Umesh Shastry
Hello Kenny,

Thank you for report and test case.
Verified as described.

Thanks,
Umesh
[26 Jun 2014 8:14] Umesh Shastry
// 5.6.20

mysql> select * from performance_schema.events_statements_summary_by_digest\G
*************************** 1. row ***************************
                SCHEMA_NAME: performance_schema
                     DIGEST: 650c3c70869a592a9c87e5767e5e19fa
                DIGEST_TEXT: TRUNCATE TABLE `performance_schema` . `events_statements_summary_by_digest`
                 COUNT_STAR: 1
             SUM_TIMER_WAIT: 1756175000
             MIN_TIMER_WAIT: 1756175000
             AVG_TIMER_WAIT: 1756175000
             MAX_TIMER_WAIT: 1756175000
              SUM_LOCK_TIME: 251000000
                 SUM_ERRORS: 0
               SUM_WARNINGS: 0
          SUM_ROWS_AFFECTED: 0
              SUM_ROWS_SENT: 0
          SUM_ROWS_EXAMINED: 0
SUM_CREATED_TMP_DISK_TABLES: 0
     SUM_CREATED_TMP_TABLES: 0
       SUM_SELECT_FULL_JOIN: 0
 SUM_SELECT_FULL_RANGE_JOIN: 0
           SUM_SELECT_RANGE: 0
     SUM_SELECT_RANGE_CHECK: 0
            SUM_SELECT_SCAN: 0
      SUM_SORT_MERGE_PASSES: 0
             SUM_SORT_RANGE: 0
              SUM_SORT_ROWS: 0
              SUM_SORT_SCAN: 0
          SUM_NO_INDEX_USED: 0
     SUM_NO_GOOD_INDEX_USED: 0
                 FIRST_SEEN: 2014-06-28 04:20:27
                  LAST_SEEN: 2014-06-28 04:20:27
*************************** 2. row ***************************
                SCHEMA_NAME: performance_schema
                     DIGEST: e32f6c1d89b321dcf58e7448e28320d5
                DIGEST_TEXT: SELECT * FROM `test` . `test`
                 COUNT_STAR: 1
             SUM_TIMER_WAIT: 23323276000
             MIN_TIMER_WAIT: 23323276000
             AVG_TIMER_WAIT: 23323276000
             MAX_TIMER_WAIT: 23323276000
              SUM_LOCK_TIME: 75000000
                 SUM_ERRORS: 0
               SUM_WARNINGS: 0
          SUM_ROWS_AFFECTED: 0
              SUM_ROWS_SENT: 8192
          SUM_ROWS_EXAMINED: 8192
SUM_CREATED_TMP_DISK_TABLES: 0
     SUM_CREATED_TMP_TABLES: 0
       SUM_SELECT_FULL_JOIN: 0
 SUM_SELECT_FULL_RANGE_JOIN: 0
           SUM_SELECT_RANGE: 0
     SUM_SELECT_RANGE_CHECK: 0
            SUM_SELECT_SCAN: 1
      SUM_SORT_MERGE_PASSES: 0
             SUM_SORT_RANGE: 0
              SUM_SORT_ROWS: 0
              SUM_SORT_SCAN: 0
          SUM_NO_INDEX_USED: 1
     SUM_NO_GOOD_INDEX_USED: 0
                 FIRST_SEEN: 2014-06-28 04:20:36
                  LAST_SEEN: 2014-06-28 04:20:36
*************************** 3. row ***************************
                SCHEMA_NAME: performance_schema
                     DIGEST: f26ae4b83451849afb0bfd55e658d6af
                DIGEST_TEXT: CALL `test` . `testing`
                 COUNT_STAR: 1
             SUM_TIMER_WAIT: 23781375000
             MIN_TIMER_WAIT: 23781375000
             AVG_TIMER_WAIT: 23781375000
             MAX_TIMER_WAIT: 23781375000
              SUM_LOCK_TIME: 0
                 SUM_ERRORS: 0
               SUM_WARNINGS: 0
          SUM_ROWS_AFFECTED: 0
              SUM_ROWS_SENT: 0
          SUM_ROWS_EXAMINED: 0
SUM_CREATED_TMP_DISK_TABLES: 0
     SUM_CREATED_TMP_TABLES: 0
       SUM_SELECT_FULL_JOIN: 0
 SUM_SELECT_FULL_RANGE_JOIN: 0
           SUM_SELECT_RANGE: 0
     SUM_SELECT_RANGE_CHECK: 0
            SUM_SELECT_SCAN: 0
      SUM_SORT_MERGE_PASSES: 0
             SUM_SORT_RANGE: 0
              SUM_SORT_ROWS: 0
              SUM_SORT_SCAN: 0
          SUM_NO_INDEX_USED: 0
     SUM_NO_GOOD_INDEX_USED: 0
                 FIRST_SEEN: 2014-06-28 04:20:37
                  LAST_SEEN: 2014-06-28 04:20:37
3 rows in set (0.00 sec)
[23 Feb 2016 15:27] Kenny Gryp
This also happens for views :(
[23 Feb 2016 15:43] Mark Leith
Note that this is the behaviour of events_statements_summary_by_program in 5.7:

mysql> create procedure p1 () select * from t1 limit 100;
Query OK, 0 rows affected (0.01 sec)

mysql> select * from performance_schema.events_statements_summary_by_program;
Empty set (0.00 sec)

mysql> call p1();
+------+
| i    |
+------+
...
+------+
100 rows in set (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

mysql> select * from performance_schema.events_statements_summary_by_program\G
*************************** 1. row ***************************
                OBJECT_TYPE: PROCEDURE
              OBJECT_SCHEMA: test
                OBJECT_NAME: p1
                 COUNT_STAR: 1
             SUM_TIMER_WAIT: 347657000
             MIN_TIMER_WAIT: 0
             AVG_TIMER_WAIT: 347657000
             MAX_TIMER_WAIT: 347657000
           COUNT_STATEMENTS: 1
        SUM_STATEMENTS_WAIT: 311898000
        MIN_STATEMENTS_WAIT: 311898000
        AVG_STATEMENTS_WAIT: 311898000
        MAX_STATEMENTS_WAIT: 311898000
              SUM_LOCK_TIME: 930000000
                 SUM_ERRORS: 0
               SUM_WARNINGS: 0
          SUM_ROWS_AFFECTED: 0
              SUM_ROWS_SENT: 100
          SUM_ROWS_EXAMINED: 100
SUM_CREATED_TMP_DISK_TABLES: 0
     SUM_CREATED_TMP_TABLES: 0
       SUM_SELECT_FULL_JOIN: 0
 SUM_SELECT_FULL_RANGE_JOIN: 0
           SUM_SELECT_RANGE: 0
     SUM_SELECT_RANGE_CHECK: 0
            SUM_SELECT_SCAN: 1
      SUM_SORT_MERGE_PASSES: 0
             SUM_SORT_RANGE: 0
              SUM_SORT_ROWS: 0
              SUM_SORT_SCAN: 0
          SUM_NO_INDEX_USED: 1
     SUM_NO_GOOD_INDEX_USED: 0
[23 Feb 2016 15:52] Kenny Gryp
Thanks for the quick response Mark.  Yes, 5.7 seems the way to go.

Now we need to merge `sys.statement_analysis` to include the `_program` metrics so we can get a proper statement analysis as now it doesn't include any metrics for `PROCEDURE`s and `VIEWS`s