Bug #23666 strange Innodb_row_lock_time_% values in show status; also millisecs wrong
Submitted: 26 Oct 2006 14:24 Modified: 20 Jun 2010 1:13
Reporter: Shane Bester (Platinum Quality Contributor) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:mysql-noinstall-5.0.21-winx64 OS:Microsoft Windows (win-x64)
Assigned to: Sunny Bains CPU Architecture:Any
Tags: innodb, innodb_row_lock_time, Innodb_row_lock_time_avg, Innodb_row_lock_time_max, STATUS

[26 Oct 2006 14:24] Shane Bester
Description:
I noticed some weird looking values in show global status:

| Innodb_pages_read                 | 131951               |
| Innodb_pages_written              | 1486014              |
| Innodb_row_lock_current_waits     | 0                    |
| Innodb_row_lock_time              | 18446744073709551517 |  <---<-----< 
| Innodb_row_lock_time_avg          | 1561806280           |  <---<-----< 
| Innodb_row_lock_time_max          | 3133607239           |  <---<-----<
| Innodb_row_lock_waits             | 11                   |
| Innodb_rows_deleted               | 617738               |

Note this server was only up for less than an hour, doing some inserts
into innodb tables.  The values are documented as:

http://dev.mysql.com/doc/refman/5.0/en/server-status-variables.html

#Innodb_row_lock_time
The total time spent in acquiring row locks, in milliseconds. Added in MySQL 5.0.3.

#Innodb_row_lock_time_avg
The average time to acquire a row lock, in milliseconds. Added in MySQL 5.0.3.

#Innodb_row_lock_time_max
The maximum time to acquire a row lock, in milliseconds. Added in MySQL 5.0.3.

So, not sure how they can have the shown values..

How to repeat:
not sure.  will see if it happens in 5.0.26 and report back.

Suggested fix:
.
[26 Oct 2006 14:25] Shane Bester
innodb status

Attachment: bug_note.txt (plain/text, text), 6.01 KiB.

[26 Oct 2006 21:30] Shane Bester
Happened on 5.0.26 on win-x64 too.  This isn't available for download afaik, but I'll try come up with a testcase soon. 

Could be after ' Deadlock found when trying to get lock; try restarting transaction: create temporary ta..' error is seen.

I haven't tried on other platforms yet either.

| Innodb_row_lock_time              | 18446744073709546617 |
| Innodb_row_lock_time_avg          | 50528968             |
| Innodb_row_lock_time_max          | 3133602239           |
| Innodb_row_lock_waits             | 85                   |
| Innodb_rows_deleted               | 18590                |
| Innodb_rows_inserted              | 100001               |
| Innodb_rows_read                  | 4549662              |
| Innodb_rows_updated               | 54                   |
+-----------------------------------+----------------------+
44 rows in set (0.01 sec)
[15 Nov 2006 19:22] Heikki Tuuri
Hmm... might be a 64-bit/32-bit variable mismatch.
[21 Nov 2006 15:32] Heikki Tuuri
The bug is that ut_usectime() in ut0ut.c has a wrong definition on Windows.

The bug manifests best on a 64-bit Windows, because there a ulint is 64-bit, and a negative value of diff_time in the code snippet below causes the sum counter srv_n_lock_wait_time to get a wildly wrong value.

Furthermore, in the calculation of the export_vars, we divide by 10000, while we should divide by 1000 to get milliseconds, as stated in the manual!

ut0ut.c in 5.0:

/**************************************************************
Returns system time. */

void
ut_usectime(
/*========*/
        ulint*  sec,    /* out: seconds since the Epoch */
        ulint*  ms)     /* out: microseconds since the Epoch+*sec */
{
#ifdef __WIN__
        SYSTEMTIME st;
        GetLocalTime(&st);
        *sec = (ulint) st.wSecond;
        *ms  = (ulint) st.wMilliseconds;
#else
        struct timeval  tv;
        gettimeofday(&tv,NULL);
        *sec = (ulint) tv.tv_sec;
        *ms  = (ulint) tv.tv_usec;
#endif
}

Microsoft website:

typedef struct _SYSTEMTIME {  WORD wYear;  WORD wMonth;  WORD wDayOfWeek;  WORD wDay;  WORD wHour;  WORD wMinute;  WORD wSecond;  WORD wMilliseconds;
} SYSTEMTIME,  *PSYSTEMTIME;

srv0srv.c in 5.0:

        if (thr->lock_state == QUE_THR_LOCK_ROW) {
                ut_usectime(&sec, &ms);
                finish_time = (ib_longlong)sec * 1000000 + ms;

                diff_time = (ulint) (finish_time - start_time);

                srv_n_lock_wait_current_count--;
                srv_n_lock_wait_time = srv_n_lock_wait_time + diff_time;
                if (diff_time > srv_n_lock_max_wait_time) {
                        srv_n_lock_max_wait_time = diff_time;
                }
        }

...

        export_vars.innodb_row_lock_current_waits= srv_n_lock_wait_current_coun\
t;
        export_vars.innodb_row_lock_time= srv_n_lock_wait_time / 10000;
        if (srv_n_lock_wait_count > 0) {
                export_vars.innodb_row_lock_time_avg = (ulint)
                        (srv_n_lock_wait_time / 10000 / srv_n_lock_wait_count);
        } else {
                export_vars.innodb_row_lock_time_avg = 0;
        }
        export_vars.innodb_row_lock_time_max= srv_n_lock_max_wait_time / 10000;
[21 Nov 2006 15:44] Heikki Tuuri
Assigning this little bug to Marko. Use GetSystemTimeAsFileTime() as the replacement of getttimeofday() on Windows:

http://msdn.microsoft.com/library/default.asp?url=/library/en-us/sysinfo/base/getsystemtim...

Regards,

Heikki
[3 Jan 2007 13:49] Heikki Tuuri
Assigning this little bug to Sunny.
[6 Apr 2007 17:21] Bugs System
Pushed into 5.0.40
[6 Apr 2007 17:23] Bugs System
Pushed into 5.1.18-beta
[11 Apr 2007 2:37] Paul Dubois
Noted in 5.0.40, 5.1.18 changelogs.

The values displayed for the Innodb_row_lock_time,
Innodb_row_lock_time_avg, and Innodb_row_lock_time_max status
variables were incorrect.
[5 May 2010 15:11] Bugs System
Pushed into 5.1.47 (revid:joro@sun.com-20100505145753-ivlt4hclbrjy8eye) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[6 May 2010 2:31] Paul Dubois
Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug. Re-closing.
[28 May 2010 5:48] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100524190136-egaq7e8zgkwb9aqi) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (pib:16)
[28 May 2010 6:18] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100524190941-nuudpx60if25wsvx) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[28 May 2010 6:45] Bugs System
Pushed into 5.5.5-m3 (revid:alik@sun.com-20100524185725-c8k5q7v60i5nix3t) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[29 May 2010 23:15] Paul Dubois
Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.
[17 Jun 2010 11:49] Bugs System
Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[17 Jun 2010 12:26] Bugs System
Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[17 Jun 2010 13:14] Bugs System
Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)