rows_read is overflowed when changing db

[Valentine Gostev]

rows_read is being overflowed while changing database (exactly on 'show tables' query)

mysql> use test3

results in

# Time: 110821 2:49:18
# User@Host: root[root] @ localhost []
# Thread_id: 1 Schema: test Last_errno: 0 Killed: 0
# Query_time: 0.000093 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 68 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1313880558;
SELECT DATABASE();
# Time: 110821 2:49:18
# User@Host: root[root] @ localhost []
# Thread_id: 1 Schema: test3 Last_errno: 0 Killed: 0
# Query_time: 0.000042 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 79 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
use test3;
SET timestamp=1313880558;
# administrator command: Init DB;
# Time: 110821 2:49:18
# User@Host: root[root] @ localhost []
# Thread_id: 1 Schema: test3 Last_errno: 0 Killed: 0
# Query_time: 0.000296 Lock_time: 0.000071 Rows_sent: 5 Rows_examined: 5 Rows_affected: 0 Rows_read: 5
# Bytes_sent: 138 Tmp_tables: 1 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1313880558;
show databases;
# Time: 110821 2:49:18
# User@Host: root[root] @ localhost []
# Thread_id: 1 Schema: test3 Last_errno: 0 Killed: 0
# Query_time: 0.000119 Lock_time: 0.000044 Rows_sent: 0 Rows_examined: 0 Rows_affected: 0 Rows_read: 18446744073709551612
# Bytes_sent: 85 Tmp_tables: 1 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1313880558;
show tables;

Rows_read: 18446744073709551612

After changing DB and running show tables results in:
mysql> show tables;
mysql> show tables;
mysql> show tables;

# Time: 110821 3:39:48
# User@Host: root[root] @ localhost []
# Thread_id: 1 Schema: test Last_errno: 0 Killed: 0
# Query_time: 0.000249 Lock_time: 0.000091 Rows_sent: 1 Rows_examined: 1 Rows_affected: 0 Rows_read: 2
# Bytes_sent: 92 Tmp_tables: 1 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1313883588;
show tables;
# Time: 110821 3:39:49
# User@Host: root[root] @ localhost []
# Thread_id: 1 Schema: test Last_errno: 0 Killed: 0
# Query_time: 0.000230 Lock_time: 0.000083 Rows_sent: 1 Rows_examined: 1 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 92 Tmp_tables: 1 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1313883589;
show tables;
# Time: 110821 3:39:49
# User@Host: root[root] @ localhost []
# Thread_id: 1 Schema: test Last_errno: 0 Killed: 0
# Query_time: 0.000178 Lock_time: 0.000056 Rows_sent: 1 Rows_examined: 1 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 92 Tmp_tables: 1 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1313883589;
show tables;

Rows_read from first 'show tables;' differs from later ones

[Lixun Peng (P.Linux) (plx)]

I encountered this bug, too.
I debuged source code about thd->row_count, I found some clue.

In function mysql_execute_command(THD *thd),

2212 /* Save the original row_count value for extended stats in slow query log */
2213 thd->orig_row_count= thd->row_count;
2214

this code set thd->row_count to thd->orig_row_count, But in

2425 case SQLCOM_SELECT:
...
2446 res= execute_sqlcom_select(thd, all_tables);
2447 break;
...

In function "execute_sqlcom_select(thd, all_tables)" thd->row_count will be set 0.

Then, in fcuntion "MYSQL_QUERY_LOG::write", "thd->row_count - thd->orig_row_count + 1" will be overflow becase thd->row_count=0 and thd->orig_row_count>0.

Why thd->orig_row_count>0 (in our case this value > 10) and thd->row_count = 0 ?

I found that when I type "use test", thd->row_count will be set 11 or 12, and the slowlog logged 'show databases' or 'SELECT DATABASE()' automatic like this:

# Time: 111129 14:15:07
# User@Host: root[root] @ localhost []
# Thread_id: 1 Schema: plx Last_errno: 0 Killed: 0
# Query_time: 105.847380 Lock_time: 14.356633 Rows_sent: 12 Rows_examined: 12 Rows_affected: 0 Rows_read: 13
# Bytes_sent: 218 Tmp_tables: 1 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# QC_Hit: No Full_scan: Yes Full_join: No Tmp_table: Yes Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# No InnoDB statistics available for this query
use plx;
SET timestamp=1322547307;
show databases;

Then I type "show tables", thd->orig_row_count set to 11 by "thd->orig_row_count= thd->row_count;", and code step into "case SQLCOM_SELECT" after "res= execute_sqlcom_select(thd, all_tables);", thd->row_count set to 0.
So, "thd->row_count - thd->orig_row_count + 1" overflow.

# Time: 111129 14:24:02
# User@Host: root[root] @ localhost []
# Thread_id: 1 Schema: plx Last_errno: 0 Killed: 0
# Query_time: 499.288054 Lock_time: 180.632754 Rows_sent: 0 Rows_examined: 0 Rows_affected: 0 Rows_read: 18446744073709551605
# Bytes_sent: 83 Tmp_tables: 1 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# QC_Hit: No Full_scan: Yes Full_join: No Tmp_table: Yes Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# No InnoDB statistics available for this query
SET timestamp=1322547842;
show tables;

The simple method to fix this bug is compare thd->row_count and thd->orig_row_count, use lagger-value - less-value.
I add some codes on "MYSQL_QUERY_LOG::write":

2399 /* For slow query log */
2400 ha_rows tmp_row_count = 0;
2401 if (thd->row_count >= thd->orig_row_count) {
2402 tmp_row_count = thd->row_count - thd->orig_row_count + 1;
2403 } else {
2404 tmp_row_count = thd->orig_row_count - thd->row_count + 1;
2405 }

And change
2411 ((long) thd->row_count_func > 0 ) ? (ulong) thd->row_count_func : 0,
2412 thd->row_count - thd->orig_row_count + 1,
2413 (ulong) (thd->status_var.bytes_sent - thd->bytes_sent_old),
TO
2417 ((long) thd->row_count_func > 0 ) ? (ulong) thd->row_count_func : 0,
2418 tmp_row_count,
2419 (ulong) (thd->status_var.by...

[Lixun Peng (P.Linux) (plx)]

overflow fix patch

[Oleg Tsarev (tsarev)]

I think this bug already fixed by #716210
Please reopen bug if bug reproduced on the last version of Percona-Server

[Alexey Kopytov (akopytov)]

It is not fixed by the patch for bug #716210, as there is absolutely nothing in that fix that addressed this problem.

[Oleg Tsarev (tsarev)]

Alexey,

I think problem related to uninitialized variable thd->sent_row_count. In fix for bug #716210 I changed the initialisation, update and processing of this variable.
From this point of view I think problem Is fixed.

You are welcome to provide test-case which reproduce described problem or code analyze where problem will be actual.
While we don't receive any feedback about this problem on new version, I change status to "Incomplete".

[Oleg Tsarev (tsarev)]

s/Incomplete/Invalid

[Lixun Peng (P.Linux) (plx)]

I debuged this problem on Percona Server 5.1.59-13.0, I'm very sure this bug is still in 5.1.59-13.0.

my comment on 2011-11-29, is debug no 5.1.59-13.0

[Alexey Kopytov (akopytov)]

I could reproduce it on 5.1.61 using the test case described in the original report...

[Oleg Tsarev (tsarev)]

Alexey, last version of lp:percona-server/5.1 based on 5.1.60
Do you mean MySQL upstream version?

[Alexey Kopytov (akopytov)]

No, I meant 5.1.60-13.1, that was a typo.

[Stewart Smith (stewart)]

Marking as incomplete as Alexey was unable to reproduce with recent Percona Server.

[Shahriyar Rzayev (rzayev-sehriyar)]

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