Percona Server moved to https://jira.percona.com/projects/PS

Incomplete profiling info (a lot of nulls)

  1. Series 5.6
  2. Bug #1397962
Bug #1397962 reported by WoZ
12
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Status tracked in 5.7
5.5
Triaged
Medium
Unassigned
5.6
Triaged
Medium
Unassigned
5.7
Triaged
Medium
Unassigned

Bug Description

There are a lot of null values for extra types in profiler's info. Types with nulls: CPU_user, CPU_system, Context_voluntary, Context_involuntary, Block_ops_in, Block_ops_out, Messages_sent, Messages_received, Page_faults_major, Page_faults_minor, Swaps.

Percona server (built by percona) versions:
Percona-Server-shared-55-5.5.40-rel36.1.el6.x86_64
percona-xtrabackup-20-2.0.8-587.rhel6.x86_64
Percona-Server-client-55-5.5.40-rel36.1.el6.x86_64
percona-toolkit-2.2.11-1.noarch
Percona-Server-server-55-5.5.40-rel36.1.el6.x86_64
Percona-Server-shared-51-5.1.73-rel14.12.624.rhel6.x86_64

OS: Centos, Linux db2 2.6.32-431.29.2.el6.x86_64 #1 SMP Tue Sep 9 21:36:05 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

STR:

mysql> set profiling=1;
mysql> select * from table where user_id='464b15d6794611e48d7bd4bed9a94cc6';
mysql> show profiles;
+----------+------------+-----------------------------------------------------------------------------+
| Query_ID | Duration | Query |
+----------+------------+-----------------------------------------------------------------------------+
| 1 | 0.00021400 | select * from table where user_id='464b15d6794611e48d7bd4bed9a94cc6' |
+----------+------------+-----------------------------------------------------------------------------+

mysql> show profile all for query 1\G
*************************** 1. row ***************************
             Status: starting
           Duration: 0.000027
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: NULL
        Source_file: NULL
        Source_line: NULL
*************************** 2. row ***************************
             Status: checking permissions
           Duration: 0.000003
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: check_access
        Source_file: sql_parse.cc
        Source_line: 4980
*************************** 3. row ***************************
             Status: Opening tables
           Duration: 0.000014
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: open_tables
        Source_file: sql_base.cc
        Source_line: 4949
*************************** 4. row ***************************
             Status: System lock
           Duration: 0.000008
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: mysql_lock_tables
        Source_file: lock.cc
        Source_line: 299
*************************** 5. row ***************************
             Status: init
           Duration: 0.000016
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: mysql_select
        Source_file: sql_select.cc
        Source_line: 2620
*************************** 6. row ***************************
             Status: optimizing
           Duration: 0.000005
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: optimize
        Source_file: sql_select.cc
        Source_line: 887
*************************** 7. row ***************************
             Status: statistics
           Duration: 0.000056
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: optimize
        Source_file: sql_select.cc
        Source_line: 1097
*************************** 8. row ***************************
             Status: preparing
           Duration: 0.000011
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: optimize
        Source_file: sql_select.cc
        Source_line: 1119
*************************** 9. row ***************************
             Status: executing
           Duration: 0.000002
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: exec
        Source_file: sql_select.cc
        Source_line: 1877
*************************** 10. row ***************************
             Status: Sending data
           Duration: 0.000034
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: exec
        Source_file: sql_select.cc
        Source_line: 2421
*************************** 11. row ***************************
             Status: end
           Duration: 0.000004
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: mysql_select
        Source_file: sql_select.cc
        Source_line: 2656
*************************** 12. row ***************************
             Status: query end
           Duration: 0.000003
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: mysql_execute_command
        Source_file: sql_parse.cc
        Source_line: 4669
*************************** 13. row ***************************
             Status: closing tables
           Duration: 0.000006
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: mysql_execute_command
        Source_file: sql_parse.cc
        Source_line: 4721
*************************** 14. row ***************************
             Status: freeing items
           Duration: 0.000021
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: mysql_parse
        Source_file: sql_parse.cc
        Source_line: 5902
*************************** 15. row ***************************
             Status: logging slow query
           Duration: 0.000001
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: log_slow_statement
        Source_file: sql_parse.cc
        Source_line: 1615
*************************** 16. row ***************************
             Status: cleaning up
           Duration: 0.000003
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: dispatch_command
        Source_file: sql_parse.cc
        Source_line: 1467

Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :
Download full text (7.4 KiB)

Verified with 5.5.40 and 5.6.21

nilnandan@Dell-XPS:~/sandboxes/msb_5_5_40$ mysql -uroot -p --socket=/tmp/mysql_sandbox5540.sock
Enter password:
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.5.40-36.1 Percona Server (GPL), Release 36.1, Revision 707

Copyright (c) 2009-2014 Percona LLC and/or its affiliates
Copyright (c) 2000, 2014, 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 * from table where user_id='464b15d6794611e48d7bd4bed9a94cc6';
ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'table where user_id='464b15d6794611e48d7bd4bed9a94cc6'' at line 1
mysql>
mysql> show profiles;
+----------+------------+----------------------------------------------------------------------+
| Query_ID | Duration | Query |
 +----------+------------+----------------------------------------------------------------------+
| 1 | 0.00013175 | select * from table where user_id='464b15d6794611e48d7bd4bed9a94cc6' |
 +----------+------------+----------------------------------------------------------------------+
1 row in set (0.00 sec)

mysql> show profile all for query 1\G
*************************** 1. row ***************************
             Status: starting
           Duration: 0.000091
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: NULL
        Source_file: NULL
        Source_line: NULL
*************************** 2. row ***************************
             Status: freeing items
           Duration: 0.000032
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: mysql_parse
        Source_file: sql_parse.cc
        Source_line: 5931
*************************** 3. row ***************************
             Status: logging slow query
           Duration: 0.000004
           CPU_user: NULL
         CPU_system: NULL
  Context_voluntary: NULL
Context_involuntary: NULL
       Block_ops_in: NULL
      Block_ops_out: NULL
      Messages_sent: NULL
  Messages_received: NULL
  Page_faults_major: NULL
  Page_faults_minor: NULL
              Swaps: NULL
    Source_function: log_slow_statement
        Source_file: sql_parse.cc
        Source_line: 1625
*************************** 4. row ***************************
             Status: ...

Read more...

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Nil, is this an upstream issue?

Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :

Laurynas, No, its not in upstream.

[root@centos65 ~]# mysql -uroot -p
Enter password:
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.6.21 MySQL Community Server (GPL)

Copyright (c) 2000, 2014, 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, 1 warning (0.00 sec)

mysql> select * from table where user_id='464b15d6794611e48d7bd4bed9a94cc6';
ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'table where user_id='464b15d6794611e48d7bd4bed9a94cc6'' at line 1
mysql>
mysql> show profiles;
+----------+------------+----------------------------------------------------------------------+
| Query_ID | Duration | Query |
 +----------+------------+----------------------------------------------------------------------+
| 1 | 0.00391050 | select * from table where user_id='464b15d6794611e48d7bd4bed9a94cc6' |
 +----------+------------+----------------------------------------------------------------------+
1 row in set, 1 warning (0.00 sec)

mysql> show profile all for query 1\G
*************************** 1. row ***************************
             Status: starting
           Duration: 0.003781
           CPU_user: 0.000000
         CPU_system: 0.000000
  Context_voluntary: 1
Context_involuntary: 0
       Block_ops_in: 56
      Block_ops_out: 0
      Messages_sent: 0
  Messages_received: 0
  Page_faults_major: 1
  Page_faults_minor: 5
              Swaps: 0
    Source_function: NULL
        Source_file: NULL
        Source_line: NULL
*************************** 2. row ***************************
             Status: freeing items
           Duration: 0.000092
           CPU_user: 0.000000
         CPU_system: 0.000000
  Context_voluntary: 0
Context_involuntary: 0
       Block_ops_in: 0
      Block_ops_out: 0
      Messages_sent: 0
  Messages_received: 0
  Page_faults_major: 0
  Page_faults_minor: 0
              Swaps: 0
    Source_function: mysql_parse
        Source_file: sql_parse.cc
        Source_line: 6292
*************************** 3. row ***************************
             Status: cleaning up
           Duration: 0.000038
           CPU_user: 0.000000
         CPU_system: 0.000000
  Context_voluntary: 0
Context_involuntary: 0
       Block_ops_in: 0
      Block_ops_out: 0
      Messages_sent: 0
  Messages_received: 0
  Page_faults_major: 0
  Page_faults_minor: 0
              Swaps: 0
    Source_function: dispatch_command
        Source_file: sql_parse.cc
        Source_line: 1772
3 rows in set, 1 warning (0.00 sec)

mysql>

Revision history for this message
WoZ (d-menshikov) wrote :

up

Revision history for this message
redguy (mateusz-kijowski) wrote :

bump :-)

Revision history for this message
Teodor Milkov (tm-del) wrote :

Bug still present in percona 5.6.27-75.0.

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1591

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.