Bug #59273 show profile source doesn't show Source_function or truncates Source_file
Submitted: 4 Jan 2011 10:14 Modified: 1 Mar 2011 1:34
Reporter: Shane Bester (Platinum Quality Contributor) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: General Severity:S3 (Non-critical)
Version:5.1.54, 5.5.8 OS:Any
Assigned to: Tor Didriksen CPU Architecture:Any
Triage: Triaged: D3 (Medium)

[4 Jan 2011 10:14] Shane Bester
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 |
+------------------+---------------+-------------+

5.5.8 output on linux x64 (trimmed to not wrap):
+-----------------------+----------------------+-------------+
| Source_function       | Source_file          | Source_line |
+-----------------------+----------------------+-------------+
| NULL                  | NULL                 |        NULL |
| check_access          | /export/home/pb2/bui |        4613 |
| open_tables           | /export/home/pb2/bui |        4732 |
| mysql_select          | /export/home/pb2/bui |        2545 |
| optimize              | /export/home/pb2/bui |         858 |
| exec                  | /export/home/pb2/bui |        1818 |
| mysql_select          | /export/home/pb2/bui |        2581 |
| mysql_execute_command | /export/home/pb2/bui |        4310 |
| mysql_execute_command | /export/home/pb2/bui |        4362 |
| mysql_parse           | /export/home/pb2/bui |        5509 |
| log_slow_statement    | /export/home/pb2/bui |        1444 |
| dispatch_command      | /export/home/pb2/bui |        1400 |
+-----------------------+----------------------+-------------+

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

Suggested fix:
for 5.5, we don't want the entire path in the source_file. Only a relative path should be used so that server dependent paths are left out.

for 5.1, we want the function name included.
[4 Jan 2011 10:18] Shane Bester
full output attached to avoid wrapping.

Attachment: bug59273_full_uncut_output.txt (text/plain), 3.92 KiB.

[4 Jan 2011 10:22] Marc Alff
Analysis
========

Looks related to how the build is done with CMAKE, which uses:
- absolute file names (/path/to/code.cc)
- instead of relative file names (code.cc),
which in turn affects __FILE__
[12 Jan 2011 13:48] Daniël van Eeden
In 5.5.8 the SHOW ENGINE INNODB output shows full paths in the SEMAPHORES section. It makes the output less readable. Is this also related to the switch from autotools to cmake?

----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 2720, signal count 2710
--Thread 2836126576 has waited at /export/home/pb2/build/sb_0-2629600-1291401802.22/mysqlcom-pro-5.5.8/storage/innobase/log/log0log.c line 2026 for 1.00 seconds the semaphore:
S-lock on RW-latch at 0x9a082b8 created in file /export/home/pb2/build/sb_0-2629600-1291401802.22/mysqlcom-pro-5.5.8/storage/innobase/log/log0log.c line 832
a writer (thread id 2836126576) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file /export/home/pb2/build/sb_0-2629600-1291401802.22/mysqlcom-pro-5.5.8/storage/innobase/log/log0log.c line 2049
Last time write locked in file /export/home/pb2/build/sb_0-2629600-1291401802.22/mysqlcom-pro-5.5.8/storage/innobase/log/log0log.c line 1846
--Thread 2813647728 has waited at /export/home/pb2/build/sb_0-2629600-1291401802.22/mysqlcom-pro-5.5.8/storage/innobase/include/log0log.ic line 405 for 1.00 seconds the semaphore:
Mutex at 0x9a08194 created file /export/home/pb2/build/sb_0-2629600-1291401802.22/mysqlcom-pro-5.5.8/storage/innobase/log/log0log.c line 771, lock var 1
waiters flag 1
Mutex spin waits 205506, rounds 342214, OS waits 1764
RW-shared spins 723, rounds 18436, OS waits 611
RW-excl spins 254, rounds 5388, OS waits 169
Spin rounds per wait: 1.67 mutex, 25.50 RW-shared, 21.21 RW-excl
[12 Jan 2011 13:57] Daniël van Eeden
And the full path is also used for this assertion failure in buf0lru.c:892

110112 14:53:02  InnoDB: ERROR: over 95 percent of the buffer pool is occupied by
InnoDB: lock heaps or the adaptive hash index! Check that your
InnoDB: transactions do not set too many row locks.
InnoDB: Your buffer pool size is 127 MB. Maybe you should make
InnoDB: the buffer pool bigger?
InnoDB: We intentionally generate a seg fault to print a stack trace
InnoDB: on Linux!
110112 14:53:02  InnoDB: Assertion failure in thread 2836126576 in file /export/home/pb2/build/sb_0-2629600-1291401802.22/mysqlcom-pro-5.5.8/storage/innobase/buf/buf0lru.c line 892
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
InnoDB: about forcing recovery.
[12 Jan 2011 14:59] Daniël van Eeden
And it is also affecting 'SHOW ENGINE INNODB MUTEX'

mysql> SHOW ENGINE INNODB MUTEX;
+--------+------------------------------------------------------------------------------------------------------------------+---------------+
| Type   | Name                                                                                                             | Status        |
+--------+------------------------------------------------------------------------------------------------------------------+---------------+
| InnoDB | /export/home/pb2/build/sb_0-2629600-1291401802.22/mysqlcom-pro-5.5.8/storage/innobase/log/log0log.c:771          | os_waits=1418 |
| InnoDB | /export/home/pb2/build/sb_0-2629600-1291401802.22/mysqlcom-pro-5.5.8/storage/innobase/buf/buf0buf.c:1243         | os_waits=7    |
| InnoDB | /export/home/pb2/build/sb_0-2629600-1291401802.22/mysqlcom-pro-5.5.8/storage/innobase/buf/buf0buf.c:1208         | os_waits=789  |
| InnoDB | /export/home/pb2/build/sb_0-2629600-1291401802.22/mysqlcom-pro-5.5.8/storage/innobase/fil/fil0fil.c:1559         | os_waits=50   |
| InnoDB | /export/home/pb2/build/sb_0-2629600-1291401802.22/mysqlcom-pro-5.5.8/storage/innobase/srv/srv0srv.c:996          | os_waits=194  |
| InnoDB | combined /export/home/pb2/build/sb_0-2629600-1291401802.22/mysqlcom-pro-5.5.8/storage/innobase/buf/buf0buf.c:898 | os_waits=2    |
| InnoDB | /export/home/pb2/build/sb_0-2629600-1291401802.22/mysqlcom-pro-5.5.8/storage/innobase/log/log0log.c:832          | os_waits=162  |
| InnoDB | combined /export/home/pb2/build/sb_0-2629600-1291401802.22/mysqlcom-pro-5.5.8/storage/innobase/buf/buf0buf.c:898 | os_waits=1667 |
+--------+------------------------------------------------------------------------------------------------------------------+---------------+
8 rows in set (0.00 sec)
[18 Jan 2011 15:28] Tor Didriksen
http://www.cmake.org/cmake/help/cmake-2-8-docs.html#variable:CMAKE_USE_RELATIVE_PATHS
#  CMAKE_USE_RELATIVE_PATHS: Use relative paths (May not work!).

Cmake documentation warns against using relative paths.

So I guess we have to resort to doing base_name(__FILE__) on things that are user-facing. We do not want the overhead of base_name whenever __FILE__ is stored (in e.g. in rw_lock_struct), so it should be done before presenting
results to the user.

For SHOW ENGINE INNODB MUTEX;
this patch should work (but there are lots more places...)

=== modified file 'storage/innobase/handler/ha_innodb.cc'
--- storage/innobase/handler/ha_innodb.cc       2011-01-13 07:33:03 +0000
+++ storage/innobase/handler/ha_innodb.cc       2011-01-18 15:07:08 +0000
@@ -9731,7 +9731,7 @@
                }
 
                buf1len = my_snprintf(buf1, sizeof buf1, "%s:%lu",
-                                    lock->cfile_name, (ulong) lock->cline);
+                                     base_name(lock->cfile_name), (ulong) lock->cline);
                buf2len = my_snprintf(buf2, sizeof buf2, "os_waits=%lu",
                                      (ulong) lock->count_os_wait);
[19 Jan 2011 7:46] Roel Van de Paar
See bug #58999
[20 Jan 2011 15:09] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/129288

3271 Tor Didriksen	2011-01-20
      Bug #59273 show profile source doesn't show Source_function or truncates Source_file
      
      Fixed the 'show profile source' part of the bug.
      Leaving SHOW ENGINE INNODB MUTEX to a separate patch.
     @ sql/sql_class.cc
        Use base_name(calling_file) for dbug trace and profiling.
[27 Jan 2011 13:25] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/129760

3280 Tor Didriksen	2011-01-27
      Bug #59273 show profile source doesn't show Source_function or truncates Source_file
      
      Fixed the 'show profile source' part of the bug.
      Leaving SHOW ENGINE INNODB MUTEX to a separate patch.
     @ sql/sql_class.cc
        Use base_name(calling_file) for dbug trace and profiling.
[27 Jan 2011 13:47] Bugs System
Pushed into mysql-trunk 5.6.2 (revid:tor.didriksen@oracle.com-20110127134628-9cakw9celrequj4i) (version source revid:tor.didriksen@oracle.com-20110127134628-9cakw9celrequj4i) (merge vers: 5.6.2) (pib:24)
[27 Jan 2011 13:47] Bugs System
Pushed into mysql-5.5 5.5.10 (revid:tor.didriksen@oracle.com-20110127132527-w0so1o5tzi9o6vlz) (version source revid:tor.didriksen@oracle.com-20110127132527-w0so1o5tzi9o6vlz) (merge vers: 5.5.10) (pib:24)
[1 Mar 2011 1:34] Paul Dubois
Noted in 5.5.10, 5.6.2 changelogs.

SHOW PROFILE could truncate source file names or fail to show
function names. 

CHANGESET - http://lists.mysql.com/commits/129760
[1 Mar 2011 9:28] Daniël van Eeden
As far as I know it's fixed only for 5.5 and 5.6, not for 5.1 which was also requested.
[1 Mar 2011 9:29] Daniël van Eeden
I also believe that the SHOW ENGINE INNODB MUTEX output is not fixed?
[1 Mar 2011 11:14] Davi Arnaut
The problem does not exist in 5.1. The InnoDB issue is a separate one.
[14 Jul 2011 18:41] Shane Bester
The fix for this leads us to:

Defect #12756017 PROFILING: SET_THD_PROC_INFO DOES NOT NEED TO CALL DIRNAME_LENGTH EACH TIME