Bug #60291 function name not included in SHOW PROFILE SOURCE output
Submitted: 1 Mar 2011 12:29 Modified: 1 Mar 2011 16:58
Reporter: Daniël van Eeden Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: General Severity:S3 (Non-critical)
Version:5.1.54, 5.1.55 OS:Any (Mac OS X, Linux)
Assigned to: CPU Architecture:Any
Triage: Needs Triage: D3 (Medium)

[1 Mar 2011 12:29] Daniël van Eeden
Description:
5.1.54 output on linux x64 (trimmed to not wrap):
mysql> show profile source for query 1;
+------------------+---------------+-------------+
| Source_function  | Source_file   | Source_line |
+------------------+---------------+-------------+
| NULL             | NULL          |        NULL |
| unknown function | sql_parse.cc  |        5291 |
| unknown function | sql_base.cc   |        4515 |
| unknown function | sql_select.cc |        2519 |
| unknown function | sql_select.cc |         828 |
| unknown function | sql_select.cc |        1775 |
| unknown function | sql_select.cc |        2565 |
| unknown function | sql_parse.cc  |        5055 |
| unknown function | sql_parse.cc  |        6086 |
| unknown function | sql_parse.cc  |        1709 |
| unknown function | sql_parse.cc  |        1677 |
+------------------+---------------+-------------+

Original bug report: Bug #59273

How to repeat:
set profiling=1;
select now();
show profile source for query 1;

Suggested fix:
The Source_function column should contain the actual function names.
[1 Mar 2011 13:05] Miguel Solorzano
Thank you for the bug report. I was able to repeat for server 5.5 but not with 5.1 (on Windows). Which exactly version  are you using?. Thanks in advance.

C:\DBS>c:\dbs\5.1\bin\mysql -uroot --port=3306 --prompt="mysql 5.1 >"
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.1.57-Win X64-log 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 5.1 >set profiling=1;
Query OK, 0 rows affected (0.00 sec)

mysql 5.1 >select now();
+---------------------+
| now()               |
+---------------------+
| 2011-03-01 10:02:57 |
+---------------------+
1 row in set (0.00 sec)

mysql 5.1 >show profile source for query 1;
+----------------------+----------+-----------------------+-----------------+-------------+
| Status               | Duration | Source_function       | Source_file     | Source_line |
+----------------------+----------+-----------------------+-----------------+-------------+
| starting             | 0.000055 | NULL                  | NULL            |        NULL |
| checking permissions | 0.000005 | check_access          | .\sql_parse.cc  |        5318 |
| Opening tables       | 0.000012 | open_tables           | .\sql_base.cc   |        4520 |
| init                 | 0.000030 | mysql_select          | .\sql_select.cc |        2524 |
| optimizing           | 0.000004 | JOIN::optimize        | .\sql_select.cc |         833 |
| executing            | 0.000357 | JOIN::exec            | .\sql_select.cc |        1780 |
| end                  | 0.000005 | mysql_select          | .\sql_select.cc |        2570 |
| query end            | 0.000004 | mysql_execute_command | .\sql_parse.cc  |        5082 |
| freeing items        | 0.000107 | mysql_parse           | .\sql_parse.cc  |        6106 |
| logging slow query   | 0.000003 | log_slow_statement    | .\sql_parse.cc  |        1722 |
| cleaning up          | 0.000004 | dispatch_command      | .\sql_parse.cc  |        1690 |
+----------------------+----------+-----------------------+-----------------+-------------+
11 rows in set (0.00 sec)
[1 Mar 2011 14:02] Daniël van Eeden
I've just tested it with 5.1.55 on 64-bit Linux (Download: mysql-5.1.55-linux-x86_64-glibc23.tar.gz)

mysql [localhost] {msandbox} ((none)) > set profiling=1;
Query OK, 0 rows affected (0.00 sec)

mysql [localhost] {msandbox} ((none)) > select now();
+---------------------+
| now()               |
+---------------------+
| 2011-03-01 13:59:58 |
+---------------------+
1 row in set (0.00 sec)

mysql [localhost] {msandbox} ((none)) > show profile source for query 1;
+----------------------+----------+------------------+---------------+-------------+
| Status               | Duration | Source_function  | Source_file   | Source_line |
+----------------------+----------+------------------+---------------+-------------+
| starting             | 0.000134 | NULL             | NULL          |        NULL |
| checking permissions | 0.000012 | unknown function | sql_parse.cc  |        5305 |
| Opening tables       | 0.000013 | unknown function | sql_base.cc   |        4520 |
| init                 | 0.000040 | unknown function | sql_select.cc |        2520 |
| optimizing           | 0.000008 | unknown function | sql_select.cc |         829 |
| executing            | 0.000025 | unknown function | sql_select.cc |        1776 |
| end                  | 0.000009 | unknown function | sql_select.cc |        2566 |
| query end            | 0.000002 | unknown function | sql_parse.cc  |        5069 |
| freeing items        | 0.000023 | unknown function | sql_parse.cc  |        6093 |
| logging slow query   | 0.000001 | unknown function | sql_parse.cc  |        1709 |
| cleaning up          | 0.000002 | unknown function | sql_parse.cc  |        1677 |
+----------------------+----------+------------------+---------------+-------------+
11 rows in set (0.00 sec)

mysql [localhost] {msandbox} ((none)) > select version();
+-----------+
| version() |
+-----------+
| 5.1.55    |
+-----------+
1 row in set (0.00 sec)
[1 Mar 2011 14:04] Daniël van Eeden
Reading your output there also seems to be a bug with the Source file name on Windows. (The .\ shouldn't be there). Should I create another bug report for that?
[1 Mar 2011 14:43] Valeriy Kravchuk
Looks like it depends on compilation options. With 5.1.57 on Linux (compiled using old BUILD/compile-pentium-valgrind-max-no-ndb script) I see the same problem as reported initially. On the other hand, even 5.1.54 does not demonstrate any problem (besides .\ before the file names):

mysql> exit
Bye

C:\Program Files\MySQL\MySQL Server 5.5\bin>mysql -uroot -proot -P3310 test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 3
Server version: 5.1.54-community MySQL Community Server (GPL)

Copyright (c) 2000, 2010, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

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

mysql> set profiling = 1;
Query OK, 0 rows affected (0.08 sec)

mysql> select 1;
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (0.00 sec)

mysql> show profile source for query 1;
+--------------------------------+----------+--------------------------------+--
---------------+-------------+
| Status                         | Duration | Source_function                | S
ource_file     | Source_line |
+--------------------------------+----------+--------------------------------+--
---------------+-------------+
| starting                       | 0.000049 | NULL                           | N
ULL            |        NULL |
| checking query cache for query | 0.000056 | Query_cache::send_result_to_cl | .
\sql_cache.cc  |        1497 |
| checking permissions           | 0.000039 | check_access                   | .
\sql_parse.cc  |        5291 |
| Opening tables                 | 0.000027 | open_tables                    | .
\sql_base.cc   |        4515 |
| init                           | 0.000018 | mysql_select                   | .
\sql_select.cc |        2519 |
| optimizing                     | 0.000007 | JOIN::optimize                 | .
\sql_select.cc |         828 |
| executing                      | 0.000018 | JOIN::exec                     | .
\sql_select.cc |        1775 |
| end                            | 0.000008 | mysql_select                   | .
\sql_select.cc |        2565 |
| query end                      | 0.000006 | mysql_execute_command          | .
\sql_parse.cc  |        5055 |
| freeing items                  | 0.000412 | mysql_parse                    | .
\sql_parse.cc  |        6086 |
| logging slow query             | 0.000004 | log_slow_statement             | .
\sql_parse.cc  |        1709 |
| cleaning up                    | 0.000003 | dispatch_command               | .
\sql_parse.cc  |        1677 |
+--------------------------------+----------+--------------------------------+--
---------------+-------------+
12 rows in set (0.06 sec)
[1 Mar 2011 16:58] Valeriy Kravchuk
Similar script to build (BUILD/compile-pentium-debug-max), current mysql-5.5, Mac OS X, and everything works as expected:

macbook-pro:5.5 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 53
Server version: 5.5.11-debug-log Source distribution

Copyright (c) 2000, 2010, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

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> select now();
+---------------------+
| now()               |
+---------------------+
| 2011-03-01 18:51:42 |
+---------------------+
1 row in set (0.12 sec)

mysql> show profile source for query 1;
+----------------------+----------+-----------------------+---------------+-------------+
| Status               | Duration | Source_function       | Source_file   | Source_line |
+----------------------+----------+-----------------------+---------------+-------------+
| starting             | 0.022098 | NULL                  | NULL          |        NULL |
| checking permissions | 0.000035 | check_access          | sql_parse.cc  |        4619 |
| Opening tables       | 0.000036 | open_tables           | sql_base.cc   |        4737 |
| init                 | 0.070469 | mysql_select          | sql_select.cc |        2550 |
| optimizing           | 0.000026 | optimize              | sql_select.cc |         863 |
| executing            | 0.007701 | exec                  | sql_select.cc |        1823 |
| end                  | 0.000027 | mysql_select          | sql_select.cc |        2586 |
| query end            | 0.000012 | mysql_execute_command | sql_parse.cc  |        4316 |
| closing tables       | 0.000020 | mysql_execute_command | sql_parse.cc  |        4368 |
| freeing items        | 0.000078 | mysql_parse           | sql_parse.cc  |        5508 |
| logging slow query   | 0.000012 | log_slow_statement    | sql_parse.cc  |        1450 |
| cleaning up          | 0.000013 | dispatch_command      | sql_parse.cc  |        1406 |
+----------------------+----------+-----------------------+---------------+-------------+
12 rows in set (0.04 sec)

But(!) official 5.1.55 binaries show the problem:

macbook-pro:mysql-5.1.55-osx10.5-x86_64 openxs$ bin/mysql -uroot testWelcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.1.55 MySQL Community Server (GPL)

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> select now();
+---------------------+
| now()               |
+---------------------+
| 2011-03-01 18:55:48 |
+---------------------+
1 row in set (0.00 sec)

mysql> show profile source for query 1;
+----------------------+----------+------------------+---------------+-------------+
| Status               | Duration | Source_function  | Source_file   | Source_line |
+----------------------+----------+------------------+---------------+-------------+
| starting             | 0.000085 | NULL             | NULL          |        NULL |
| checking permissions | 0.000006 | unknown function | sql_parse.cc  |        5305 |
| Opening tables       | 0.000008 | unknown function | sql_base.cc   |        4520 |
| init                 | 0.000039 | unknown function | sql_select.cc |        2520 |
| optimizing           | 0.000003 | unknown function | sql_select.cc |         829 |
| executing            | 0.000018 | unknown function | sql_select.cc |        1776 |
| end                  | 0.000004 | unknown function | sql_select.cc |        2566 |
| query end            | 0.000002 | unknown function | sql_parse.cc  |        5069 |
| freeing items        | 0.000022 | unknown function | sql_parse.cc  |        6093 |
| logging slow query   | 0.000002 | unknown function | sql_parse.cc  |        1709 |
| cleaning up          | 0.000003 | unknown function | sql_parse.cc  |        1677 |
+----------------------+----------+------------------+---------------+-------------+
11 rows in set (0.00 sec)

So, there is definitely some bug in the process of building official binaries.