| 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: | |
| 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: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]
MySQL Verification Team
Hello Kenny, Thank you for report and test case. Verified as described. Thanks, Umesh
[26 Jun 2014 8:14]
MySQL Verification Team
// 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
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