slow_extended in 5.5 always shows identical values for Rows_sent and Rows_read

Alexey,

Can we get the bug report which shows it ? I know there are cases then
these data are different.

I think the problem was for some update queries rows examined are not
showing up but rows read does.

On Fri, Feb 18, 2011 at 2:22 AM, Alexey Kopytov
<email address hidden>wrote:

> Public bug reported:
>
> slow_extended in 5.5 uses the same variable (thd->sent_row_count) to
> print both Rows_sent and Rows_read in the extended slow query log stats.
> This can be verified by examining MYSQL_QUERY_LOG::write() in log.cc.
>
> The bug was introduced when porting slow_extended.patch to 5.5.
>
> On the other hand, I don't understand the meaning of Rows_read. What
> information is it supposed to reflect? Should we really have it in the
> slow log?
>
> ** Affects: percona-server
> Importance: Undecided
> Status: New
>
> --
> You received this bug notification because you are a member of Percona
> developers, which is the registrant for Percona Server.
> https://bugs.launchpad.net/bugs/721176
>
> Title:
> slow_extended in 5.5 always shows identical values for Rows_sent and
> Rows_read
>
> Status in Percona Server with XtraDB:
> New
>
> Bug description:
> slow_extended in 5.5 uses the same variable (thd->sent_row_count) to
> print both Rows_sent and Rows_read in the extended slow query log
> stats. This can be verified by examining MYSQL_QUERY_LOG::write() in
> log.cc.
>
> The bug was introduced when porting slow_extended.patch to 5.5.
>
> On the other hand, I don't understand the meaning of Rows_read. What
> information is it supposed to reflect? Should we really have it in the
> slow log?
>

--
Peter Zaitsev, CEO, Percona Inc.
Tel: +1 888 401 3401 ext 501 Skype: peter_zaitsev
24/7 Emergency Line +1 888 401 3401 ext 911

Join us for Percona Live Event, San Francisco, Feb 16
http://www.percona.com/events/percona-live-san-francisco-2011/

Peter,

In 5.5 Rows_read and Rows_sent are always the same simply because the same value is used for both due to a bug in porting slow_extended.

I'm not sure how to demonstrate "always", but here's just one example:

create table t1(a int);
insert into t1 values(1),(2),(3),(4);
set @@min_examined_row_limit=1;

select * from t1;
# Query_time: 0.000413 Lock_time: 0.000152 Rows_sent: 4 Rows_examined: 4 Rows_affected: 0 Rows_read: 4
select * from t1 where a=1;
# Query_time: 0.000607 Lock_time: 0.000299 Rows_sent: 1 Rows_examined: 4 Rows_affected: 0 Rows_read: 1
select * from t1 where a=5;
# Query_time: 0.000460 Lock_time: 0.000170 Rows_sent: 0 Rows_examined: 4 Rows_affected: 0 Rows_read: 0

Which raises 2 questions:

1. Why is Rows_read different in all three cases?
2. What is Rows_read really supposed to mean?

Alexey,

What I mean is we need a test case in Percona Server 5.1 which would cover
when these values are different.
In this case I assume such test case would have been ported to Percona
Server 5.5 and would have broken when
patch was not ported correctly.

On Fri, Feb 18, 2011 at 10:52 AM, Alexey Kopytov <<email address hidden>
> wrote:

> Peter,
>
> In 5.5 Rows_read and Rows_sent are always the same simply because the
> same value is used for both due to a bug in porting slow_extended.
>
> I'm not sure how to demonstrate "always", but here's just one example:
>
> create table t1(a int);
> insert into t1 values(1),(2),(3),(4);
> set @@min_examined_row_limit=1;
>
> select * from t1;
> # Query_time: 0.000413 Lock_time: 0.000152 Rows_sent: 4 Rows_examined: 4
> Rows_affected: 0 Rows_read: 4
> select * from t1 where a=1;
> # Query_time: 0.000607 Lock_time: 0.000299 Rows_sent: 1 Rows_examined: 4
> Rows_affected: 0 Rows_read: 1
> select * from t1 where a=5;
> # Query_time: 0.000460 Lock_time: 0.000170 Rows_sent: 0 Rows_examined: 4
> Rows_affected: 0 Rows_read: 0
>
> Which raises 2 questions:
>
> 1. Why is Rows_read different in all three cases?
> 2. What is Rows_read really supposed to mean?
>
> --
> You received this bug notification because you are a member of Percona
> developers, which is the registrant for Percona Server.
> https://bugs.launchpad.net/bugs/721176
>
> Title:
> slow_extended in 5.5 always shows identical values for Rows_sent and
> Rows_read
>
> Status in Percona Server with XtraDB:
> New
>
> Bug description:
> slow_extended in 5.5 uses the same variable (thd->sent_row_count) to
> print both Rows_sent and Rows_read in the extended slow query log
> stats. This can be verified by examining MYSQL_QUERY_LOG::write() in
> log.cc.
>
> The bug was introduced when porting slow_extended.patch to 5.5.
>
> On the other hand, I don't understand the meaning of Rows_read. What
> information is it supposed to reflect? Should we really have it in the
> slow log?
>

--
Peter Zaitsev, CEO, Percona Inc.
Tel: +1 888 401 3401 ext 501 Skype: peter_zaitsev
24/7 Emergency Line +1 888 401 3401 ext 911

Join us for Percona Live Event, San Francisco, Feb 16
http://www.percona.com/events/percona-live-san-francisco-2011/

Here's the diff of the patch.

--- /tmp/a 2011-05-19 11:20:20.367198182 +1000
+++ /tmp/b 2011-05-19 11:20:40.877376218 +1000
@@ -7,8 +7,8 @@
                      (ulong) thd->sent_row_count,
 - (ulong) thd->examined_row_count) == (uint) -1)
 + (ulong) thd->examined_row_count,
-+ ((long) thd->row_count_func > 0 ) ? (ulong) thd->row_count_func : 0,
-+ thd->row_count - thd->orig_row_count + 1,
++ ((long) thd->get_row_count_func() > 0 ) ? (ulong) thd->get_row_count_func() : 0,
++ (ulong) thd->sent_row_count,
 + (ulong) (thd->status_var.bytes_sent - thd->bytes_sent_old),
 + (ulong) thd->tmp_tables_used,
 + (ulong) thd->tmp_tables_disk_used,

As discussed with Oleg f2f we planned to remove rows_read from log. Keeping bug assigned to Oleg

https://code.launchpad.net/~tsarev/percona-server/bug721176

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