MySQL Slow Query Lock_time = years?

Question

I have seen a lot of slow query logs, but never one like this:

    /usr/sbin/mysqld, Version: 5.1.46-log (SUSE MySQL RPM). started with:
    Tcp port: 3306  Unix socket: /var/run/mysql/mysql.sock
    Time                 Id Command    Argument
    # Time: 160627  9:10:05
    # User@Host: sysop[sysop] @  [127.0.0.1]
    # Query_time: 3.768728  Lock_time: 0.034402 Rows_sent: 734  Rows_examined: 734
    use asterisk;
    SET timestamp=1467033005;
    select PostID, lead_id, list_id from vdlist_temp where Posted is null;
    # Time: 160627 10:35:11
    # User@Host: sysop[sysop] @  [192.168.0.248]
    # Query_time: 35.563521  Lock_time: 0.000054 Rows_sent: 1222017  Rows_examined: 2444034
    SET timestamp=1467038111;
    SELECT `vicidial_list`.`lead_id`, `vicidial_list`.`source_id` FROM  `vicidial_list` ORDER BY `vicidial_list`.`source_id`;
    # User@Host: sysop[sysop] @  [127.0.0.1]
    # Query_time: 0.000095  Lock_time: 18446744073699.406250 Rows_sent: 2  Rows_examined: 1
    SET timestamp=1467038111;
    call spUpdate_VDList_from_temp(0, 0, 1324903);
    # Time: 160627 10:35:12
    # User@Host: sysop[sysop] @  [127.0.0.1]
    # Query_time: 0.000055  Lock_time: 18446744073699.359375 Rows_sent: 0  Rows_examined: 0
    SET timestamp=1467038112;
    call spMoveXDrop(10376163);
    # Time: 160627 11:26:14
    # User@Host: sysop[sysop] @  [127.0.0.1]
    # Query_time: 0.000057  Lock_time: 18446744073697.218750 Rows_sent: 3  Rows_examined: 0
    SET timestamp=1467041174;
    call spUpdate_VDList_from_temp(10795520, 616062301, 1955758);

This seems to show I have queries waiting over 500,000 years for a lock. (I wrote the stored procedure and I'm not quite that old!) Somehow I don't think that's right. These are all MyISAM tables. (Not my choice.) I did a mysqldump and restore of the database, rebooted the server and I'm still getting seeing lock times like this.

Can anyone give me a clue where to look for the problem? (Server times are all good.)

EDIT:This MySql Version: 5.1.46-log that comes with an OpenSource project Vicidial. It seems clear that the Lock_time is a bug. Problem is that I'm looking at the slow query log to track down user complaints of slow web server response. I was hoping someone would know what triggers this bug to help me locate the actual problem. As you can see from the log, most slow queries have sane Lock_times. Both stored procedures and PHP generated queries generate the insane Lock_time. The only thing I see in common is they all select or update from the table vicidial_list. I dumped, dropped and recreated that table to no avail.

Answer 1

Sometimes the clock seems to run backwards. This has been a problem for more than a decade. It seems to be harmless. Ignore it as a bogus value.

Note that if a -1 is stored in a BIGINT UNSIGNED, you get a value very similar to the 18446744073699.406250 that you are seeing.