MySQL Bugs: #45791: Agent does not report multi row explain plans

Bug #45791	Agent does not report multi row explain plans
Submitted:	26 Jun 2009 17:23	Modified:	21 Jul 2009 10:34
Reporter:	Diego Medina	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Enterprise Monitor: Agent	Severity:	S3 (Non-critical)
Version:	2.1.0.1067	OS:	Any
Assigned to:	Kay Roepke	CPU Architecture:	Any

Description:
There are cases, where the agent does not report all the rows from an explain plan that has more than one row.

If you go on the UI, you will see information for the first row, but NULL values for the other rows.

How to repeat:
1- Install and start the agent and service manager
2- Configure query analyzer to collect explain queries and set the Threshold to
00:00:00.001
3- Now send these queries through the proxy port

DROP DATABASE IF EXISTS quan_test;
CREATE DATABASE quan_test;
use quan_test;

create table t1 (
dt datetime not null,
primary key (dt)
);

create view v3 as select null union all select null union all select null;
create view v10 as select null from v3 a, v3 b union all select null;
create view v1000 as select null from v10 a, v10 b, v10 c;
set @n = 0;
insert into t1 select now()-interval @n:=@n+1 second from v1000 a,v1000 b;

select t1.* from t1 join t1 b using(dt) limit 10000000,10;

4- Go on the UI->Query Analyzer
5- Once you see the SELECT statement, click on it, and go to the explain tab.
(it may take aabout 1-2 minutes to show an explain plan, but once you see it, the second line will only have null values

This is the explain that you see using the mysql client

explain select t1.* from t1 join t1 b using(dt) limit 10000000,10;
+----+-------------+-------+--------+---------------+---------+---------+-----------------+---------+-------------+
| id | select_type | table | type   | possible_keys | key     | key_len | ref             | rows    | Extra       |
+----+-------------+-------+--------+---------------+---------+---------+-----------------+---------+-------------+
|  1 | SIMPLE      | t1    | index  | PRIMARY       | PRIMARY | 8       | NULL            | 1000000 | Using index | 
|  1 | SIMPLE      | b     | eq_ref | PRIMARY       | PRIMARY | 8       | quan_test.t1.dt |       1 | Using index | 
+----+-------------+-------+--------+---------------+---------+---------+-----------------+---------+-------------+
2 rows in set (0.00 sec)

I'll attach the agent log later

Note the "<error>Hmm, something wasn't ok</error>" line
<doc>
 <agentId>1246032491092.2</agentId>
 <agentUtc>2009-06-26T16:16:55.162Z</agentUtc>
 <hostname>diego-medinas-macbook-pro.local</hostname>
 <uuid>25ac2659-f729-4220-b442-ce3f8224a95f</uuid>
 <version>2.1.0.1067</version>
 <shutdown>false</shutdown>
 <tasks>
  <task>
   <taskId>9223372036854775713</taskId>
   <command>collect_data</command>
   <utc>2009-06-26T16:16:55.162Z</utc>
   <data>
    <datum>
     <target>
      <namespace>mysql</namespace>
      <classname>explain</classname>
      <instance>6c26beb6-04c6-42fc-aaac-c36e7c933e51.quan_test.3c33e438722ace0940a8e555d9db7668.1.1</instance>
      <attribute>key</attribute>
     </target>
     <utc>2009-06-26T16:16:22.275Z</utc>
     <value>PRIMARY</value>
    </datum>
    <datum>
     <target>
      <namespace>mysql</namespace>
      <classname>explain</classname>
      <instance>6c26beb6-04c6-42fc-aaac-c36e7c933e51.quan_test.3c33e438722ace0940a8e555d9db7668.1.1</instance>
      <attribute>key_len</attribute>
     </target>
     <utc>2009-06-26T16:16:22.275Z</utc>
     <value>8</value>
    </datum>
    <datum>
     <target>
      <namespace>mysql</namespace>
      <classname>explain</classname>
      <instance>6c26beb6-04c6-42fc-aaac-c36e7c933e51.quan_test.3c33e438722ace0940a8e555d9db7668.1.1</instance>
      <attribute>possible_keys</attribute>
     </target>
     <utc>2009-06-26T16:16:22.275Z</utc>
     <value>PRIMARY</value>
    </datum>
    <datum>
     <target>
      <namespace>mysql</namespace>
      <classname>explain</classname>
      <instance>6c26beb6-04c6-42fc-aaac-c36e7c933e51.quan_test.3c33e438722ace0940a8e555d9db7668.1.1</instance>
      <attribute>type</attribute>
     </target>
     <utc>2009-06-26T16:16:22.275Z</utc>
     <value>index</value>
    </datum>
    <datum>
     <target>
      <namespace>mysql</namespace>
      <classname>explain</classname>
      <instance>6c26beb6-04c6-42fc-aaac-c36e7c933e51.quan_test.3c33e438722ace0940a8e555d9db7668.1.1</instance>
      <attribute>select_type</attribute>
     </target>
     <utc>2009-06-26T16:16:22.275Z</utc>
     <value>SIMPLE</value>
    </datum>
    <datum>
     <target>
      <namespace>mysql</namespace>
      <classname>explain</classname>
      <instance>6c26beb6-04c6-42fc-aaac-c36e7c933e51.quan_test.3c33e438722ace0940a8e555d9db7668.1.1</instance>
      <attribute>Extra</attribute>
     </target>
     <utc>2009-06-26T16:16:22.275Z</utc>
     <value>Using index</value>
    </datum>
    <datum>
     <target>
      <namespace>mysql</namespace>
      <classname>explain</classname>
      <instance>6c26beb6-04c6-42fc-aaac-c36e7c933e51.quan_test.3c33e438722ace0940a8e555d9db7668.1.1</instance>
      <attribute>table</attribute>
     </target>
     <utc>2009-06-26T16:16:22.275Z</utc>
     <value>t1</value>
    </datum>
    <datum>
     <target>
      <namespace>mysql</namespace>
      <classname>explain</classname>
      <instance>6c26beb6-04c6-42fc-aaac-c36e7c933e51.quan_test.3c33e438722ace0940a8e555d9db7668.1.1</instance>
      <attribute>rows</attribute>
     </target>
     <utc>2009-06-26T16:16:22.275Z</utc>
     <value>1000000</value>
    </datum>
    <datum>
     <target>
      <namespace>mysql</namespace>
      <classname>explain</classname>
      <instance>6c26beb6-04c6-42fc-aaac-c36e7c933e51.quan_test.3c33e438722ace0940a8e555d9db7668.1.1</instance>
      <attribute>id</attribute>
     </target>
     <utc>2009-06-26T16:16:22.275Z</utc>
     <value>1</value>
    </datum>
   </data>
  </task>
  <task>
   <taskId>9223372036854775712</taskId>
   <command>collect_data</command>
   <utc>2009-06-26T16:16:55.162Z</utc>
   <data>
    <exceptions>
     <error>Hmm, something wasn't ok</error>
    </exceptions>
   </data>
  </task>
 </tasks>
</doc>

Diego Medina writes: 
Verified as described.

Is this specific to that query ? 
Does it happen all the time ?

Would this EXPLAIN work ?
root@127.0.0.1 [(none)]> explain SELECT * FROM ( SELECT 1 ) AS a ;
+----+-------------+------------+--------+---------------+------+---------+------+------+----------------+
| id | select_type | table      | type   | possible_keys | key  | key_len | ref  | rows | Extra          |
+----+-------------+------------+--------+---------------+------+---------+------+------+----------------+
|  1 | PRIMARY     | <derived2> | system | NULL          | NULL | NULL    | NULL |    1 |                | 
|  2 | DERIVED     | NULL       | NULL   | NULL          | NULL | NULL    | NULL | NULL | No tables used | 
+----+-------------+------------+--------+---------------+------+---------+------+------+----------------+

Diego Medina writes: 
This query shows the bug

 SELECT *, sleep(1) FROM ( SELECT 1 ) AS a ;

(I added a sleep, otherwise, the agent does not run explain as it runs too fast)

Kay Roepke writes: 
------------------------------------------------------------
revno: 1410
committer: Kay Roepke <kay@sun.com>
branch nick: agent
timestamp: Thu 2009-07-09 16:40:05 +0200
message:
  Bug#45791/EM-3400: delay removal of query information until all explain rows have been collected

Keith Russell writes: 
Patch installed in versions => 2.1.0.1076.

Diego Medina writes: 
Verified fixed on version 2.1.0.1076

An entry was added to the 2.1.0 changelog:

The Agent did not report all the rows from an explain plan where the plan had more than one row. The Dashboard would display information for the first row, but subsequent rows would display NULL.