Bug #86188 | performance schema reports lock time > total time | ||
---|---|---|---|
Submitted: | 4 May 2017 19:39 | Modified: | 12 Oct 2017 18:14 |
Reporter: | Trey Raymond | Email Updates: | |
Status: | No Feedback | Impact on me: | |
Category: | MySQL Server: Performance Schema | Severity: | S3 (Non-critical) |
Version: | 5.6.34 | OS: | Any |
Assigned to: | CPU Architecture: | Any |
[4 May 2017 19:39]
Trey Raymond
[18 Jul 2017 15:47]
MySQL Verification Team
Hi! It is hard to conclude anything based on the values of two columns. Could you please send us the full output of that digest table, when lock time is greater then timer_wait. More importantly, our manual clearly states that TIMER_WAIT=TIMER_END - TIMER_START. Could you point us to the exact paragraph in our 5.6 Reference Manual where we state that timer_wait = lock_time + unlock_time. Event could start only after lock is released .....
[18 Jul 2017 16:23]
Trey Raymond
That's incorrect, at least in 5.6/5.7. Example, an alter on an empty table (8ms), locked for a ~18s beforehand: mysql> select * from events_statements_history_long where event_id=5587\G *************************** 1. row *************************** THREAD_ID: 1361324 EVENT_ID: 5587 END_EVENT_ID: 7377 EVENT_NAME: statement/sql/alter_table SOURCE: socket_connection.cc:95 TIMER_START: 8879846467003413000 TIMER_END: 8879865185718863000 TIMER_WAIT: 18718715450000 LOCK_TIME: 18710372000000 SQL_TEXT: alter table t force DIGEST: 5af04fa6e38d7a83ce7f5ed75ab895d2 DIGEST_TEXT: ALTER TABLE `t` FORCE CURRENT_SCHEMA: s1 OBJECT_TYPE: NULL OBJECT_SCHEMA: NULL OBJECT_NAME: NULL OBJECT_INSTANCE_BEGIN: NULL MYSQL_ERRNO: 0 RETURNED_SQLSTATE: 00000 MESSAGE_TEXT: Records: 0 Duplicates: 0 Warnings: 0 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 NESTING_EVENT_LEVEL: 0 1 row in set (0.69 sec) end-start=wait 8879865185718863000-8879846467003413000=18718715450000 wait-lock=exec 18718715450000-18710372000000=8343450000
[19 Jul 2017 12:52]
MySQL Verification Team
Hi! Would you be so kind as to tell me which storage engine was used for the table that you were altering and also, if it was InnoDB SE, whether it was ONLINE ALTER or the ALTER which was locking the table. Many thanks in advance.
[7 Aug 2017 18:42]
Trey Raymond
innodb, online alter, i just forced a metadata lock to demonstrate the calculations
[8 Aug 2017 15:07]
MySQL Verification Team
Hi! In your previous example, from July 18th, total time is greater then lock time: Total time is 18718715450000 and lock _time is 18710372000000. Hence, where is the bug ???
[8 Aug 2017 17:33]
Trey Raymond
Please read the entire ticket.
[9 Aug 2017 13:19]
MySQL Verification Team
Hi Mr. Raymond, Yes, I have read all your entries. However, only the last entry contains enough info to reproduce the behaviour. The previous ones are just data that we do not know where did they come off. Hence, we would like to verify this bug, but in order to be able to do that, we need a fully repeatable test case. That means all the server arguments and server configuration, with exact set of SQL statements that will in the end show that lock time is greater then total time. Many thanks in advance.
[10 Sep 2017 1:00]
Bugs System
No feedback was provided for this bug for over a month, so it is being suspended automatically. If you are able to provide the information that was originally requested, please do so and change the status of the bug back to "Open".
[11 Sep 2017 14:42]
Trey Raymond
Let me summarize the thread for those who didn't bother to read up. - Some unexpected behavior is occurring which makes the p_s numbers not match up. Difficult to deterministically reproduce, but very clear in the numbers. - The initial claim was that calculations are performed differently than expected and such behavior is a consequence. - An example was provided disproving that, showing that calculations are normally done as defined in the documentation, and reaffirming that the initial report showed a discrepancy occurring. - The bug was closed with no action, ignoring that.
[12 Sep 2017 18:14]
MySQL Verification Team
Hi! Closing of the bug is automatic after a certain period of time has passed and feedback is not provided. We have tried to repeat the bug, but we could not repeat the behaviour. Bug can be verified only if we have a fully repeatable test case. That is a rule for all the bugs.
[13 Oct 2017 1:00]
Bugs System
No feedback was provided for this bug for over a month, so it is being suspended automatically. If you are able to provide the information that was originally requested, please do so and change the status of the bug back to "Open".