rows_read is overflowed when changing db
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Percona Server moved to https://jira.percona.com/projects/PS |
Fix Released
|
High
|
Alexey Kopytov | ||
5.1 |
Fix Released
|
High
|
Alexey Kopytov | ||
5.5 |
Fix Released
|
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=
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=
# 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=
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: 184467440737095
# Bytes_sent: 85 Tmp_tables: 1 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=
show tables;
Rows_read: 184467440737095
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=
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=
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=
show tables;
Rows_read from first 'show tables;' differs from later ones
Related branches
- Laurynas Biveinis (community): Approve
- George Ormond Lorch III (community): Approve (g2)
- Vlad Lesin (community): Approve
-
Diff: 163 lines (+80/-13)6 files modifiedPercona-Server/mysql-test/r/percona_bug830286.result (+15/-0)
Percona-Server/mysql-test/r/percona_slow_extended_error_on_quit.result (+6/-6)
Percona-Server/mysql-test/t/percona_bug830286.test (+58/-0)
Percona-Server/sql/log.cc (+1/-1)
Percona-Server/sql/sql_class.cc (+0/-1)
Percona-Server/sql/sql_class.h (+0/-5)
- Laurynas Biveinis (community): Approve
- George Ormond Lorch III (community): Approve (g2)
- Vlad Lesin (community): Approve
-
Diff: 475 lines (+393/-11)8 files modifiedPercona-Server/mysql-test/include/percona_slow_extended_error_on_quit.inc (+50/-0)
Percona-Server/mysql-test/r/percona_bug830286.result (+15/-0)
Percona-Server/mysql-test/r/percona_processlist_row_stats.result (+9/-9)
Percona-Server/mysql-test/r/percona_slow_extended_error_on_quit.result (+172/-0)
Percona-Server/mysql-test/t/percona_bug830286.test (+58/-0)
Percona-Server/mysql-test/t/percona_slow_extended_error_on_quit.test (+87/-0)
Percona-Server/sql/log.cc (+1/-1)
Percona-Server/sql/sql_show.cc (+1/-1)
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) |
Changed in percona-server: | |
status: | Confirmed → In Progress |
Changed in percona-server: | |
assignee: | Oleg Tsarev (tsarev) → nobody |
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 */ row_count= thd->row_count;
2213 thd->orig_
2214
this code set thd->row_count to thd->orig_ row_count, But in
2425 case SQLCOM_SELECT: sqlcom_ select( thd, all_tables);
...
2446 res= execute_
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 1322547307;
# 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=
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 51605 1322547842;
# 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: 184467440737095
# 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=
show tables;
The simple method to fix this bug is compare thd->row_count and thd->orig_ row_count, use lagger-value - less-value. QUERY_LOG: :write" :
I add some codes on "MYSQL_
2399 /* For slow query log */ row_count) {
2400 ha_rows tmp_row_count = 0;
2401 if (thd->row_count >= thd->orig_
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 var.bytes_ sent - thd->bytes_ sent_old) , var.by. ..
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_
TO
2417 ((long) thd->row_count_func > 0 ) ? (ulong) thd->row_count_func : 0,
2418 tmp_row_count,
2419 (ulong) (thd->status_