I_S.processlist TIME_MS occasionally shows a truncated BIGINT max value

[Peiran Song]

A customer observed this on PS 5.5.40 that, for slave SQL thread, the I_S.processlist TIME_MS sometimes has a value of 18446744073709552. Also TIME_MS and TIME often are not consistent with each other for the SQL thread.

If the first sample shows TIME and TIME_MS as expected, then the rest showed that the two are not consistent and the last two samples showed the huge number associated with different STATE.

mysql> select * from information_schema.processlist where id = 21588\G
--------------
select * from information_schema.processlist where id = 21588
--------------

*************************** 1. row ***************************
           ID: 21588
         USER: system user
         HOST:
           DB: NULL
      COMMAND: Connect
         TIME: 2
        STATE: Slave has read all relay log; waiting for the slave I/O thread t
         INFO: NULL
      TIME_MS: 1397
    ROWS_SENT: 0
ROWS_EXAMINED: 0
    ROWS_READ: 2
1 row in set (0.08 sec)

mysql> select * from information_schema.processlist where id = 21588\G
--------------
select * from information_schema.processlist where id = 21588
--------------

*************************** 1. row ***************************
           ID: 21588
         USER: system user
         HOST:
           DB: assistly
      COMMAND: Connect
         TIME: 8
        STATE: Searching rows for update
         INFO: UPDATE `ticket_attachments` SET `ticket_id` = 342046622 WHERE `ticket_attachments`.`ticket_id` = 342109693 AND `ticket_attachments`.`site_id` = 146598
      TIME_MS: 161
    ROWS_SENT: 0
ROWS_EXAMINED: 0
    ROWS_READ: 1
1 row in set (0.08 sec)

mysql> select * from information_schema.processlist where id = 21588\G
--------------
select * from information_schema.processlist where id = 21588
--------------

*************************** 1. row ***************************
           ID: 21588
         USER: system user
         HOST:
           DB: assistly
      COMMAND: Connect
         TIME: 11
        STATE: System lock
         INFO: UPDATE sites SET ticket_display_id = LAST_INSERT_ID(COALESCE(`ticket_display_id`,0) + 1) WHERE id = 200559
      TIME_MS: 18446744073709552
    ROWS_SENT: 0
ROWS_EXAMINED: 0
    ROWS_READ: 1
1 row in set (0.09 sec)

mysql> select * from information_schema.processlist where id = 21588\G
--------------
select * from information_schema.processlist where id = 21588
--------------

*************************** 1. row ***************************
           ID: 21588
         USER: system user
         HOST:
           DB: assistly
      COMMAND: Connect
         TIME: 9
        STATE: Updating
         INFO: UPDATE `user_loads` SET `agent_session_id` = 28767527, `updated_at` = '2014-12-15 19:24:11' WHERE `user_loads`.`id` = 145147
      TIME_MS: 18446744073709552
    ROWS_SENT: 0
ROWS_EXAMINED: 0
    ROWS_READ: 1
1 row in set (0.09 sec)

[Nilnandan Joshi (nilnandan-joshi)]

Not getting BIGINT value in TIME_MS with PS 5.6.21 but its true that TIME_MS and TIME often are not consistent with each other for the SQL thread.

mysql> select * from information_schema.processlist where id = 1\G
*************************** 1. row ***************************
           ID: 1
         USER: system user
         HOST:
           DB: test
      COMMAND: Connect
         TIME: 106
        STATE: updating
         INFO: update nil set name = 'nilnandan' where name = 'njoshi'
      TIME_MS: 2175
    ROWS_SENT: 0
ROWS_EXAMINED: 167564
1 row in set (0.00 sec)
...
..mysql> select * from information_schema.processlist where id = 1\G
*************************** 1. row ***************************
           ID: 1
         USER: system user
         HOST:
           DB: test
      COMMAND: Connect
         TIME: 213
        STATE: updating
         INFO: update nil set name = 'nilnandan' where name = 'njoshi'
      TIME_MS: 108743
    ROWS_SENT: 0
ROWS_EXAMINED: 4171262
1 row in set (0.00 sec)

.

[Przemek (pmalkowski)]

Another example of time_ms showing bin int maxvalue:

mysql> SELECT host,db,time,time_ms,state,LEFT(info,100) FROM information_schema.processlist WHERE time=0 AND time_ms>1000 AND command !='Binlog Dump' ORDER BY time DESC LIMIT 100;
+------------------+----------------------+------+-------------------+-------+----------------+
| host | db | time | time_ms | state | LEFT(info,100) |
+------------------+----------------------+------+-------------------+-------+----------------+
| 10.10.1.53:50377 | beanstalk_production | 0 | 18446744073709552 | | NULL |
| 10.10.1.52:55013 | beanstalk_production | 0 | 18446744073709552 | | NULL |
| 10.10.1.73:40279 | dploy_production | 0 | 18446744073709544 | | NULL |
| 10.10.1.78:54975 | dploy_production | 0 | 18446744073709536 | | NULL |
| 10.10.1.78:54795 | dploy_production | 0 | 18446744073709544 | | NULL |
| 10.10.1.13:33716 | beanstalk_production | 0 | 18446744073709540 | | NULL |
+------------------+----------------------+------+-------------------+-------+----------------+
6 rows in set (0.01 sec)

Version | 5.5.44-37.3-log Percona Server (GPL), Release 37.3, Revision 729fbe2