innodb_row_lock_current_waits spikes to 18446744073709551615

[Roel Van de Paar]

From error log (using fprintf on innodb_row_lock_current_waits):

innodb_row_lock_current_waits = 118
innodb_row_lock_current_waits = 118
innodb_row_lock_current_waits = 119
innodb_row_lock_current_waits = 117
innodb_row_lock_current_waits = 117
innodb_row_lock_current_waits = 115
innodb_row_lock_current_waits = 91
innodb_row_lock_current_waits = 91
innodb_row_lock_current_waits = 89
innodb_row_lock_current_waits = 18446744073709551615 <--------------- (!)
innodb_row_lock_current_waits = 18446744073709551615
innodb_row_lock_current_waits = 18446744073709551615
innodb_row_lock_current_waits = 18446744073709551615
innodb_row_lock_current_waits = 18446744073709551615
innodb_row_lock_current_waits = 18446744073709551615
innodb_row_lock_current_waits = 18446744073709551615
innodb_row_lock_current_waits = 18446744073709551615
innodb_row_lock_current_waits = 18446744073709551615
innodb_row_lock_current_waits = 18446744073709551615
innodb_row_lock_current_waits = 18446744073709551615
innodb_row_lock_current_waits = 18446744073709551615
innodb_row_lock_current_waits = 18446744073709551615
innodb_row_lock_current_waits = 18446744073709551615
innodb_row_lock_current_waits = 18446744073709551615
innodb_row_lock_current_waits = 26
innodb_row_lock_current_waits = 29
innodb_row_lock_current_waits = 34
innodb_row_lock_current_waits = 36
innodb_row_lock_current_waits = 38
innodb_row_lock_current_waits = 39
innodb_row_lock_current_waits = 48
innodb_row_lock_current_waits = 48

Observed first by PZ during a sysbench run with PCT monitoring. Sysbench run may have been interrupted at that point. This can be reproduced with kill -9 sysbench regularly.

Testcase is exactly as described here; https://bugs.launchpad.net/percona-server/+bug/1395249/comments/1 with one additional script in a seperate shell;

$ cat sysbenchnew_scripts/5
while (true);do
  clear
  grep "Innodb_row_lock_current_waits" 2.log | sed 's|[A-Za-z_ \t]\+||' | sort -n | tail -n10
  echo "---------------------------------------------------------------------------------"
  grep "Questions" 2.log | sed 's|[A-Za-z_ \t]\+||' | sort -n | tail -n30
  sleep 1
done

This will refresh the screen and at the top (above the line) show the top 10 Innodb_row_lock_current_waits - not as recorded by the error log (the patch there is not strictly needed) but as recorded by script 2 (as noted in point 6 at the above URL) started like this; $ ./2 | tee 2.log - all this just allows you to observe when the bug happened (i.e. is the counter < ~200 or 18446744073709551615?).

Interestingly, PZ's value jumped to 18446744073709551607, so there may be a small delta against the actual value.

[Roel Van de Paar (roel11)]

I will try and add to an assert on outside-of-range innodb_row_lock_current_waits and add a coredump. It may not be the best location to catch info in the code though. Still, thd info will be available, and it will be at a point where the var has such a high value.

$ bzr diff # Patch used
=== modified file 'storage/innobase/srv/srv0srv.cc'
--- storage/innobase/srv/srv0srv.cc 2014-09-25 14:16:07 +0000
+++ storage/innobase/srv/srv0srv.cc 2014-11-12 09:40:50 +0000
@@ -1808,6 +1808,8 @@
        export_vars.innodb_row_lock_current_waits =
                srv_stats.n_lock_wait_current_count;

+fprintf(stderr, "innodb_row_lock_current_waits = %lu\n", (ulong) srv_stats.n_lock_wait_current_count);
+
        export_vars.innodb_row_lock_time = srv_stats.n_lock_wait_time / 1000;

        if (srv_stats.n_lock_wait_count > 0) {

[Roel Van de Paar (roel11)]

Likely a sister bug of bug 1319006 - Innodb_current_row_locks shows very high

[Roel Van de Paar (roel11)]

Added handy scripts here: https://bugs.launchpad.net/percona-server/+bug/1395249/comments/2

[Roel Van de Paar (roel11)]

See https://bugs.launchpad.net/percona-server/+bug/1395249/comments/3 + original bug report above to match setup.

[AlexLin (122683636-6)]

excuse every partner , this blug how to solve?

[Roel Van de Paar (roel11)]

This bug has a testcase.

AlexeyLin, what issue are you seeing?

[Laurynas Biveinis (laurynas-biveinis)]

The testcase, being some sort of script, needs confirming first.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1588