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:
Tags: profiling, udf
Triage: Needs Triage: D3 (Medium)

[27 May 2011 14:33] David Newcomb
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.
[27 May 2011 15:56] Peter Laursen
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).
[27 May 2011 17:37] Valerii Kravchuk
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)
[27 May 2011 18:34] Peter Laursen
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.