Percona Server with XtraDB

rows_read is overflowed when changing db

Reported by Valentine Gostev on 2011-08-20
48
This bug affects 6 people
Affects Status Importance Assigned to Milestone
Percona Server
High
Alexey Kopytov
5.1
High
Alexey Kopytov
5.5
High
Alexey Kopytov

Bug Description

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

Related branches

lp:~akopytov/percona-server/bug830286-5.1
Merged into lp:percona-server/5.1 at revision 503
Laurynas Biveinis: Approve on 2012-11-29
George Ormond Lorch III: Approve (g2) on 2012-11-27
Vlad Lesin: Approve on 2012-11-21
lp:~akopytov/percona-server/bug830286-5.5
Merged into lp:percona-server/5.5 at revision 369
Laurynas Biveinis: Approve on 2012-11-30
George Ormond Lorch III: Approve (g2) on 2012-11-27
Vlad Lesin: Approve on 2012-11-21
tags: added: slow-extended
Changed in percona-server:
assignee: nobody → Valentine Gostev (longbow)
importance: Undecided → High
description: updated
Changed in percona-server:
status: New → Confirmed
assignee: Valentine Gostev (longbow) → Oleg Tsarev (tsarev)
Lixun Peng (P.Linux) (plx) wrote :
Download full text (4.2 KiB)

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...

Read more...

Oleg Tsarev (tsarev) on 2012-01-03
Changed in percona-server:
status: Confirmed → In Progress
Oleg Tsarev (tsarev) wrote :

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

Changed in percona-server:
status: In Progress → Invalid
Alexey Kopytov (akopytov) wrote :

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

Changed in percona-server:
status: Invalid → Confirmed
Oleg Tsarev (tsarev) wrote :

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".

Changed in percona-server:
status: Confirmed → Incomplete
Oleg Tsarev (tsarev) wrote :

s/Incomplete/Invalid

Changed in percona-server:
status: Incomplete → Invalid
Lixun Peng (P.Linux) (plx) wrote :

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) wrote :

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

Changed in percona-server:
status: Invalid → Confirmed
Oleg Tsarev (tsarev) wrote :

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

Alexey Kopytov (akopytov) wrote :

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

Stewart Smith (stewart) on 2012-03-27
Changed in percona-server:
assignee: Oleg Tsarev (tsarev) → nobody
Stewart Smith (stewart) wrote :

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

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers