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:
None 
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
Description:
in events_statements_summary_by_digest, occasionally a row will exist where SUM_LOCK_TIME > SUM_TIMER_WAIT
it's not a rounding issue, see a few examples:
timer_wait=9949873000, lock_time=10398000000
timer_wait=3111013629000, lock_time=3311884000000
timer_wait=17981554609400000, lock_time=18195426833000000

now, mathematically, if lock_time+unlocked_time=timer_wait, and lock_time and unlocked_time are both >=0, lock_time is guaranteed <=timer_wait.

Seems like a difference in how the data is collected leading to them sometimes being off.  It only pops up in a very small percentage of records.

How to repeat:
run stuff with high lock_time but low actual exec time (so the values are close), some will eventually overlap

Suggested fix:
if the collection methods could be improved so they're in sync, that'd be best.  else, it's really not the end of the world, but it should at least be documented that workarounds are needed (so everyone's not getting confusing "BIGINT UNSIGNED value is out of range in..." errors).
[18 Jul 2017 15:47] Sinisa Milivojevic
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] Sinisa Milivojevic
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] Sinisa Milivojevic
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] Sinisa Milivojevic
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] Sinisa Milivojevic
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".