show profile

MYSQL从5.0.37版本开始增加了对 show profiles 和 show profile 语句的支持。通过 having_profiling 参数，能够看到当前MySQL是否支持
通过profile，我们能够更清楚的了解SQL执行的资源使用情况。

mysql> SELECT @@have_profiling;
+------------------+
| @@have_profiling |
+------------------+
| YES              |
+------------------+
1 ROW IN SET, 1 warning (0.00 sec)

• 默认profiling是关闭的。可以通过select @@profiling;来查询profiling的状态

mysql> SELECT @@profiling;
+-------------+
| @@profiling |
+-------------+
|           0 |
+-------------+
1 ROW IN SET, 1 warning (0.00 sec)

• 默认profiling是关闭的，可以通过 set profiling=1; 来开启

mysql> SET profiling=1;
Query OK, 0 ROWS affected, 1 warning (0.00 sec)
 
mysql> SELECT @@profiling;
+-------------+
| @@profiling |
+-------------+
|           1 |
+-------------+
1 ROW IN SET, 1 warning (0.00 sec)

• 执行一条SQL之后，可以通过profile查看到SQL执行的情况

mysql> SELECT COUNT(1) FROM reminder_report;
+----------+
| COUNT(1) |
+----------+
|  1634003 |
+----------+
1 ROW IN SET (0.23 sec)
 
mysql> 
mysql> SHOW profiles;
+----------+------------+--------------------------------------+
| Query_ID | Duration   | Query                                |
+----------+------------+--------------------------------------+
|        1 | 0.00022900 | SELECT @@profiling                   |
|        2 | 0.00024350 | SELECT DATABASE()                    |
|        3 | 0.00083075 | SHOW DATABASES                       |
|        4 | 0.00111625 | SHOW TABLES                          |
|        5 | 0.00160925 | SHOW TABLES                          |
|        6 | 0.22778725 | SELECT COUNT(1) FROM reminder_report |
+----------+------------+--------------------------------------+
7 ROWS IN SET, 1 warning (0.00 sec)

• 可以看到刚刚SQL的query_id是6.我我们可以通过 show profile for query 来显示线程在不同状态下的耗时情况

mysql> SHOW profile FOR query 6;
+----------------------+----------+
| STATUS               | Duration |
+----------------------+----------+
| starting             | 0.000155 |
| checking permissions | 0.000017 |
| Opening TABLES       | 0.000032 |
| init                 | 0.000033 |
| System LOCK          | 0.000020 |
| optimizing           | 0.456723 |
| executing            | 0.000027 |
| END                  | 0.000005 |
| query END            | 0.000007 |
| closing TABLES       | 0.000008 |
| freeing items        | 0.000243 |
| cleaning up          | 0.000013 |
+----------------------+----------+
12 ROWS IN SET, 1 warning (0.00 sec)

• 可以通过show profile查看SQL执行线程每一个步骤的资源消耗情况
• 比如，想了解每一个步骤CPU的消耗情况。则可以通过show profile cpu for query 来查看

mysql> SHOW profile cpu FOR query 6;
+----------------------+----------+----------+------------+
| STATUS               | Duration | CPU_user | CPU_system |
+----------------------+----------+----------+------------+
| starting             | 0.000155 | 0.000000 |   0.000000 |
| checking permissions | 0.000017 | 0.000000 |   0.000000 |
| Opening TABLES       | 0.000032 | 0.000000 |   0.000000 |
| init                 | 0.000033 | 0.000000 |   0.000000 |
| System LOCK          | 0.000020 | 0.000000 |   0.000000 |
| optimizing           | 0.456723 | 0.014997 |   0.007999 |
| executing            | 0.000027 | 0.000000 |   0.000000 |
| END                  | 0.000005 | 0.000000 |   0.000000 |
| query END            | 0.000007 | 0.000000 |   0.000000 |
| closing TABLES       | 0.000008 | 0.000000 |   0.000000 |
| freeing items        | 0.000243 | 0.001000 |   0.000000 |
| cleaning up          | 0.000013 | 0.000000 |   0.000000 |
+----------------------+----------+----------+------------+
12 ROWS IN SET, 1 warning (0.00 sec)

• 想了解每一个步骤memory的消耗情况。则可以通过show profile memory for query 来查看

mysql> SHOW profile memory FOR query 6;
+----------------------+----------+
| STATUS               | Duration |
+----------------------+----------+
| starting             | 0.000155 |
| checking permissions | 0.000017 |
| Opening TABLES       | 0.000032 |
| init                 | 0.000033 |
| System LOCK          | 0.000020 |
| optimizing           | 0.456723 |
| executing            | 0.000027 |
| END                  | 0.000005 |
| query END            | 0.000007 |
| closing TABLES       | 0.000008 |
| freeing items        | 0.000243 |
| cleaning up          | 0.000013 |
+----------------------+----------+
12 ROWS IN SET, 1 warning (0.00 sec)

• 想了解所有资源的消耗情况。则可以通过show profile all for query 来查看

mysql> SHOW  profile ALL  FOR query 6;
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
| STATUS               | Duration | 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 | Source_function       | Source_file          | Source_line |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
| starting             | 0.000155 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | NULL                  | NULL                 |        NULL |
| checking permissions | 0.000017 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | check_access          | sql_authorization.cc |         835 |
| Opening TABLES       | 0.000032 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | open_tables           | sql_base.cc          |        5648 |
| init                 | 0.000033 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | handle_query          | sql_select.cc        |         121 |
| System LOCK          | 0.000020 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_lock_tables     | LOCK.cc              |         321 |
| optimizing           | 0.456723 | 0.014997 |   0.007999 |                81 |                  25 |            0 |           256 |             0 |                 0 |                 0 |                 0 |     0 | OPTIMIZE              | sql_optimizer.cc     |         151 |
| executing            | 0.000027 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | EXEC                  | sql_executor.cc      |         119 |
| END                  | 0.000005 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | handle_query          | sql_select.cc        |         199 |
| query END            | 0.000007 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command | sql_parse.cc         |        4952 |
| closing TABLES       | 0.000008 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command | sql_parse.cc         |        5004 |
| freeing items        | 0.000243 | 0.001000 |   0.000000 |                 0 |                   3 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_parse           | sql_parse.cc         |        5578 |
| cleaning up          | 0.000013 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | dispatch_command      | sql_parse.cc         |        1864 |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
12 ROWS IN SET, 1 warning (0.00 sec)

• 如果想了解执行过程中每个步骤对应的源码的文件、函数名称以及具体的源文件行数，可以通过 show profile source for query 来查看

mysql> SHOW  profile SOURCE FOR query 6;
+----------------------+----------+-----------------------+----------------------+-------------+
| STATUS               | Duration | Source_function       | Source_file          | Source_line |
+----------------------+----------+-----------------------+----------------------+-------------+
| starting             | 0.000155 | NULL                  | NULL                 |        NULL |
| checking permissions | 0.000017 | check_access          | sql_authorization.cc |         835 |
| Opening TABLES       | 0.000032 | open_tables           | sql_base.cc          |        5648 |
| init                 | 0.000033 | handle_query          | sql_select.cc        |         121 |
| System LOCK          | 0.000020 | mysql_lock_tables     | LOCK.cc              |         321 |
| optimizing           | 0.456723 | OPTIMIZE              | sql_optimizer.cc     |         151 |
| executing            | 0.000027 | EXEC                  | sql_executor.cc      |         119 |
| END                  | 0.000005 | handle_query          | sql_select.cc        |         199 |
| query END            | 0.000007 | mysql_execute_command | sql_parse.cc         |        4952 |
| closing TABLES       | 0.000008 | mysql_execute_command | sql_parse.cc         |        5004 |
| freeing items        | 0.000243 | mysql_parse           | sql_parse.cc         |        5578 |
| cleaning up          | 0.000013 | dispatch_command      | sql_parse.cc         |        1864 |
+----------------------+----------+-----------------------+----------------------+-------------+
12 ROWS IN SET, 1 warning (0.00 sec)

show profile for query的数据存放在库information_schema的profiling表中可以通过查询这张表，获取SQL在不同阶段的执行明细，包括cpu、block io、contect switch、page faults等

mysql> SELECT * FROM information_schema.profiling WHERE query_id = 6\G
*************************** 1. ROW ***************************
           QUERY_ID: 1
                SEQ: 2
              STATE: starting
           DURATION: 0.000155
           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: NULL
        SOURCE_FILE: NULL
        SOURCE_LINE: NULL
*************************** 2. ROW ***************************
           QUERY_ID: 1
                SEQ: 3
              STATE: checking permissions
           DURATION: 0.000017
           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: check_access
        SOURCE_FILE: sql_authorization.cc
        SOURCE_LINE: 835
*************************** 3. ROW ***************************
           QUERY_ID: 1
                SEQ: 4
              STATE: Opening TABLES
           DURATION: 0.000032
           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: open_tables
        SOURCE_FILE: sql_base.cc
        SOURCE_LINE: 5648
*************************** 4. ROW ***************************
           QUERY_ID: 1
                SEQ: 5
              STATE: init
           DURATION: 0.000033
           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: handle_query
        SOURCE_FILE: sql_select.cc
        SOURCE_LINE: 121
*************************** 5. ROW ***************************
           QUERY_ID: 1
                SEQ: 6
              STATE: System LOCK
           DURATION: 0.000020
           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_lock_tables
        SOURCE_FILE: LOCK.cc
        SOURCE_LINE: 321
*************************** 6. ROW ***************************
           QUERY_ID: 1
                SEQ: 7
              STATE: optimizing
           DURATION: 0.456723
           CPU_USER: 0.014997
         CPU_SYSTEM: 0.007999
  CONTEXT_VOLUNTARY: 81
CONTEXT_INVOLUNTARY: 25
       BLOCK_OPS_IN: 0
      BLOCK_OPS_OUT: 256
      MESSAGES_SENT: 0
  MESSAGES_RECEIVED: 0
  PAGE_FAULTS_MAJOR: 0
  PAGE_FAULTS_MINOR: 0
              SWAPS: 0
    SOURCE_FUNCTION: OPTIMIZE
        SOURCE_FILE: sql_optimizer.cc
        SOURCE_LINE: 151
*************************** 7. ROW ***************************
           QUERY_ID: 1
                SEQ: 8
              STATE: executing
           DURATION: 0.000027
           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: EXEC
        SOURCE_FILE: sql_executor.cc
        SOURCE_LINE: 119
*************************** 8. ROW ***************************
           QUERY_ID: 1
                SEQ: 9
              STATE: END
           DURATION: 0.000005
           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: handle_query
        SOURCE_FILE: sql_select.cc
        SOURCE_LINE: 199
*************************** 9. ROW ***************************
           QUERY_ID: 1
                SEQ: 10
              STATE: query END
           DURATION: 0.000007
           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_execute_command
        SOURCE_FILE: sql_parse.cc
        SOURCE_LINE: 4952
*************************** 10. ROW ***************************
           QUERY_ID: 1
                SEQ: 11
              STATE: closing TABLES
           DURATION: 0.000008
           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_execute_command
        SOURCE_FILE: sql_parse.cc
        SOURCE_LINE: 5004
*************************** 11. ROW ***************************
           QUERY_ID: 1
                SEQ: 12
              STATE: freeing items
           DURATION: 0.000243
           CPU_USER: 0.001000
         CPU_SYSTEM: 0.000000
  CONTEXT_VOLUNTARY: 0
CONTEXT_INVOLUNTARY: 3
       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: 5578
*************************** 12. ROW ***************************
           QUERY_ID: 1
                SEQ: 13
              STATE: cleaning up
           DURATION: 0.000013
           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: 1864
12 ROWS IN SET, 1 warning (0.00 sec)

• 官方文档