MySQL Bugs: #61328: SET profiling = 1 does not profile queries with stored functions

Bug #61328	SET profiling = 1 does not profile queries with stored functions
Submitted:	27 May 2011 14:33	Modified:	27 May 2011 17:37
Reporter:	David Newcomb (OCA)	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Stored Routines	Severity:	S3 (Non-critical)
Version:	5.5.11, 5.5.14	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	profiling, udf

Description:
Switching on profiling doesn't profile user defined functions.
They are missing from the show profiles list.

How to repeat:
SET profiling = 1;

DROP TABLE IF EXISTS profiler_bug;

CREATE TABLE `profiler_bug` (
  `i` int(11) DEFAULT NULL
);

INSERT INTO profiler_bug VALUES (1);
INSERT INTO profiler_bug VALUES (2);
INSERT INTO profiler_bug VALUES (3);
SELECT * FROM profiler_bug;

DROP FUNCTION IF EXISTS adder;

DELIMITER |

CREATE FUNCTION adder(x INT) RETURNS INT DETERMINISTIC
BEGIN
  RETURN x + 1;
END|

DELIMITER ;

SHOW PROFILES;

SELECT adder(i) FROM profiler_bug;
SHOW PROFILES;

SELECT adder(i) FROM profiler_bug;
SHOW PROFILES;

Suggested fix:
Either do the profiling or document somewhere that it is not supported.

It looks like this is about 'Stored Functions (routines)' and not 'User Defined Functions'. Refer http://dev.mysql.com/doc/refman/5.1/en/adding-functions.html

Peter
(not a MySQL person).

Thank you for the bug report. Verified with current mysql-5.5 from bzr on Mac OS X:

macbook-pro:5.1 openxs$ bin/mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 30
Server version: 5.5.14-debug Source distribution

Copyright (c) 2000, 2010, Oracle and/or its affiliates. All rights reserved.
This software comes with ABSOLUTELY NO WARRANTY. This is free software,
and you are welcome to modify and redistribute it under the GPL v2 license

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> SET profiling = 1;
Query OK, 0 rows affected (0.00 sec)

mysql> 
mysql> DROP TABLE IF EXISTS profiler_bug;
Query OK, 0 rows affected, 1 warning (0.05 sec)

mysql> 
mysql> CREATE TABLE `profiler_bug` (
    ->   `i` int(11) DEFAULT NULL
    -> );
Query OK, 0 rows affected (0.12 sec)

mysql> 
mysql> INSERT INTO profiler_bug VALUES (1);
Query OK, 1 row affected (0.01 sec)

mysql> INSERT INTO profiler_bug VALUES (2);
Query OK, 1 row affected (0.01 sec)

mysql> INSERT INTO profiler_bug VALUES (3);
Query OK, 1 row affected (0.00 sec)

mysql> SELECT * FROM profiler_bug;
+------+
| i    |
+------+
|    1 |
|    2 |
|    3 |
+------+
3 rows in set (0.00 sec)

mysql> 
mysql> DROP FUNCTION IF EXISTS adder;
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> 
mysql> DELIMITER |
mysql> 
mysql> CREATE FUNCTION adder(x INT) RETURNS INT DETERMINISTIC
    -> BEGIN
    ->   RETURN x + 1;
    -> END|
Query OK, 0 rows affected (0.08 sec)

mysql> 
mysql> DELIMITER ;
mysql> 
mysql> SHOW PROFILES;
+----------+------------+----------------------------------------------------------------------------------+
| Query_ID | Duration   | Query                                                                            |
+----------+------------+----------------------------------------------------------------------------------+
|        1 | 0.03493800 | DROP TABLE IF EXISTS profiler_bug                                                |
|        2 | 0.12399900 | CREATE TABLE `profiler_bug` (
  `i` int(11) DEFAULT NULL
)                       |
|        3 | 0.01634100 | INSERT INTO profiler_bug VALUES (1)                                              |
|        4 | 0.00240800 | INSERT INTO profiler_bug VALUES (2)                                              |
|        5 | 0.00109900 | INSERT INTO profiler_bug VALUES (3)                                              |
|        6 | 0.00058300 | SELECT * FROM profiler_bug                                                       |
|        7 | 0.00022000 | DROP FUNCTION IF EXISTS adder                                                    |
|        8 | 0.08775000 | CREATE FUNCTION adder(x INT) RETURNS INT DETERMINISTIC
BEGIN
  RETURN x + 1;
END |
+----------+------------+----------------------------------------------------------------------------------+
8 rows in set (0.00 sec)

mysql> 
mysql> SELECT adder(i) FROM profiler_bug;
+----------+
| adder(i) |
+----------+
|        2 |
|        3 |
|        4 |
+----------+
3 rows in set (0.04 sec)

mysql> SHOW PROFILES;
+----------+------------+----------------------------------------------------------------------------------+
| Query_ID | Duration   | Query                                                                            |
+----------+------------+----------------------------------------------------------------------------------+
|        1 | 0.03493800 | DROP TABLE IF EXISTS profiler_bug                                                |
|        2 | 0.12399900 | CREATE TABLE `profiler_bug` (
  `i` int(11) DEFAULT NULL
)                       |
|        3 | 0.01634100 | INSERT INTO profiler_bug VALUES (1)                                              |
|        4 | 0.00240800 | INSERT INTO profiler_bug VALUES (2)                                              |
|        5 | 0.00109900 | INSERT INTO profiler_bug VALUES (3)                                              |
|        6 | 0.00058300 | SELECT * FROM profiler_bug                                                       |
|        7 | 0.00022000 | DROP FUNCTION IF EXISTS adder                                                    |
|        8 | 0.08775000 | CREATE FUNCTION adder(x INT) RETURNS INT DETERMINISTIC
BEGIN
  RETURN x + 1;
END |
+----------+------------+----------------------------------------------------------------------------------+
8 rows in set (0.00 sec)

We have been aware of this for some time - refer http://code.google.com/p/sqlyog/issues/detail?id=1569 - but did not report it. Maybe we should have done.

You may find the statement "MySQL returns query id = 0 (with SEELCT FROM I_S..) for such" useful.