MySQL Bugs: #43626: Profiling information is wrong

Bug #43626	Profiling information is wrong
Submitted:	13 Mar 2009 9:42	Modified:	30 Apr 2009 16:21
Reporter:	Cyril SCETBON	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Documentation	Severity:	S3 (Non-critical)
Version:	5.0.77	OS:	Linux (debian etch)
Assigned to:	Paul DuBois	CPU Architecture:	Any
Tags:	error, profiling

Description:
I'm profiling a request and getting the information that the request is taking the whole time sending the data whereas there's no information returned. 
http://dev.mysql.com/doc/refman/5.0/en/general-thread-states.html says that "Sending data" means sending data to the client, but it does not seem to be the case.

How to repeat:
mysql> explain SELECT  ocp_id, ocp_nom, map_mach_id, mach_nom, map_dretr  FROM  tkn_occupations JOIN sys_machines_pfs on map_ocp_id = ocp_id JOIN mat_machines on map_mach_id = mach_id LEFT JOIN com_occupations_par_agregats on ocpagr_ocp_id = map_ocp_id WHERE (map_dretr >= '2009-02-28' Or map_dretr Is Null) AND ocpagr_ocp_id Is Null;
+----+-------------+------------------------------+--------+------------------------+-------------+---------+-----------------------------------------------+
-------+--------------------------------------+
| id | select_type | table                        | type   | possible_keys          | key         | key_len | ref                                           | rows  | Extra                                |
+----+-------------+------------------------------+--------+------------------------+-------------+---------+-----------------------------------------------+-------+--------------------------------------+
|  1 | SIMPLE      | mat_machines                 | ALL    | PRIMARY                | NULL        | NULL    | NULL                                          | 13492 |                                      |
|  1 | SIMPLE      | sys_machines_pfs             | ref    | map_mach_id,map_ocp_id | map_mach_id | 5       | hebex_dwh_preprod.mat_machines.mach_id        |     1 | Using where                          |
|  1 | SIMPLE      | tkn_occupations              | eq_ref | PRIMARY                | PRIMARY     | 2       | hebex_dwh_preprod.sys_machines_pfs.map_ocp_id |     1 | Using where                          |
|  1 | SIMPLE      | com_occupations_par_agregats | index  | NULL                   | PRIMARY     | 4       | NULL                                          |  1683 | Using where; Using index; Not exists |
+----+-------------+------------------------------+--------+------------------------+-------------+---------+-----------------------------------------------+-------+--------------------------------------+
4 rows in set (0.00 sec)

mysql> set profiling=1;                                                                                          Query OK, 0 rows affected (0.00 sec)                                                                                                                          
mysql> SELECT  ocp_id, ocp_nom, map_mach_id, mach_nom, map_dretr  FROM  tkn_occupations JOIN sys_machines_pfs on map_ocp_id = ocp_id JOIN mat_machines on map_mach_id = mach_id LEFT JOIN com_occupations_par_agregats on ocpagr_ocp_id = map_ocp_id WHERE (map_dretr >= '2009-02-28' Or map_dretr Is Null) AND ocpagr_ocp_id Is Null;
Empty set (2.22 sec)

mysql> show profile;
+--------------------+----------+
| Status             | Duration |
+--------------------+----------+
| starting           | 0.000241 |
| Opening tables     | 0.000040 |
| System lock        | 0.000014 |
| Table lock         | 0.000025 |
| init               | 0.000092 |
| optimizing         | 0.000041 |
| statistics         | 0.000090 |
| preparing          | 0.000047 |
| executing          | 0.000011 |
| Sending data       | 2.230029 |
| end                | 0.000026 |
| end                | 0.000010 |
| query end          | 0.000013 |
| freeing items      | 0.000035 |
| closing tables     | 0.000018 |
| logging slow query | 0.000019 |
| cleaning up        | 0.000013 |
+--------------------+----------+
17 rows in set (0.00 sec)

Sorry, but I can't provide you the data used

Sorry, but what is the problem from your point of view? Statement running for 2.22 seconds while 2.23 seconds were spent "Sending data" or something else?

As the Server is returning 0 rows to the client, why does it takes 2.23s to Send data ??
I think that should be 2.23s in executing, and if it's really in "Sending data" what's happening ?

http://dev.mysql.com/doc/refman/5.0/en/general-thread-states.html says:

"- Sending data

The thread is processing rows for a SELECT statement and also is sending data to the client."

Why do you take last part into account but not the first one? The thread was processing rows, and based on EXPLAIN results it had to process a lot of rows to find out than none of them satify the query. Even waiting for a row lock for InnoDB table will be a part of "Sending data". I think this is not a bug.

"- Sending data

The thread is processing rows for a SELECT statement and also is
sending data to the client."

When I read this, I understand it must satisfy both conditions :
- processing rows
AND
- sending data

If you're right and processing rows which are not sent is included in "Sending data" statistics, what's the counter executing ? processing with functions ? or something else ?

For exact information of what "Executing" and "Sending data" means, please, look at the code of sql/sql_select.cc. 

As far as I can see, "executing" state thread enters in JOIN::exec() function, that is, at the beginning of query execution. Then it can change state to "Sending data", "Copying to temp table" etc, depending on the execution path. Indeed, all these should be documented in much more details for SHOW PROFILE and/or SHOW PROCESSLIST. This is a valid documentation request.

good.

Thank you for your bug report. This issue has been addressed in the documentation. The updated documentation will appear on our website shortly, and will be included in the next release of the relevant products.

I don't see that there's much to do here, except add "executing" to the list of thread states.