zoukankan      html  css  js  c++  java
  • Profiling MySQL queries from Performance Schema

    转自:http://www.percona.com/blog/2015/04/16/profiling-mysql-queries-from-performance-schema/

    When optimizing queries and investigating performance issues, MySQL comes with built in support for profiling queries aka SET profiling = 1; . This is already awesome and simple to use, but why the PERFORMANCE_SCHEMA alternative?

    Because profiling will be removed soon (already deprecated on MySQL 5.6 ad 5.7); the built-in profiling capability can only be enabled per session. This means that you cannot capture profiling information for queries running from other connections. If you are using Percona Server, the profiling option for log_slow_verbosity is a nice alternative, unfortunately, not everyone is using Percona Server.

    Now, for a quick demo: I execute a simple query and profile it below. Note that all of these commands are executed from a single session to my test instance.

    mysql> SHOW PROFILES;
    +----------+------------+----------------------------------------+
    | Query_ID | Duration   | Query                                  |
    +----------+------------+----------------------------------------+
    |        1 | 0.00011150 | SELECT * FROM sysbench.sbtest1 LIMIT 1 |
    +----------+------------+----------------------------------------+
    1 row in set, 1 warning (0.00 sec)
    mysql> SHOW PROFILE SOURCE FOR QUERY 1;
    +----------------------+----------+-----------------------+------------------+-------------+
    | Status               | Duration | Source_function       | Source_file      | Source_line |
    +----------------------+----------+-----------------------+------------------+-------------+
    | starting             | 0.000017 | NULL                  | NULL             |        NULL |
    | checking permissions | 0.000003 | check_access          | sql_parse.cc     |        5797 |
    | Opening tables       | 0.000021 | open_tables           | sql_base.cc      |        5156 |
    | init                 | 0.000009 | mysql_prepare_select  | sql_select.cc    |        1050 |
    | System lock          | 0.000005 | mysql_lock_tables     | lock.cc          |         306 |
    | optimizing           | 0.000002 | optimize              | sql_optimizer.cc |         138 |
    | statistics           | 0.000006 | optimize              | sql_optimizer.cc |         381 |
    | preparing            | 0.000005 | optimize              | sql_optimizer.cc |         504 |
    | executing            | 0.000001 | exec                  | sql_executor.cc  |         110 |
    | Sending data         | 0.000025 | exec                  | sql_executor.cc  |         190 |
    | end                  | 0.000002 | mysql_execute_select  | sql_select.cc    |        1105 |
    | query end            | 0.000003 | mysql_execute_command | sql_parse.cc     |        5465 |
    | closing tables       | 0.000004 | mysql_execute_command | sql_parse.cc     |        5544 |
    | freeing items        | 0.000005 | mysql_parse           | sql_parse.cc     |        6969 |
    | cleaning up          | 0.000006 | dispatch_command      | sql_parse.cc     |        1874 |
    +----------------------+----------+-----------------------+------------------+-------------+
    15 rows in set, 1 warning (0.00 sec)

    To demonstrate how we can achieve the same with Performance Schema, we first identify our current connection id. In the real world, you might want to get the connection/processlist id of the thread you want to watch i.e. from SHOW PROCESSLIST .

    mysql> SELECT THREAD_ID INTO @my_thread_id
        -> FROM threads WHERE PROCESSLIST_ID = CONNECTION_ID();
    Query OK, 1 row affected (0.00 sec)

    Next, we identify the bounding EVENT_IDs for the statement stages. We will look for the statement we wanted to profile using the query below from the events_statements_history_long table. Your LIMIT clause may vary depending on how much queries the server might be getting.

    mysql> SELECT THREAD_ID, EVENT_ID, END_EVENT_ID, SQL_TEXT, NESTING_EVENT_ID
        -> FROM events_statements_history_long
        -> WHERE THREAD_ID = @my_thread_id
        ->   AND EVENT_NAME = 'statement/sql/select'
        -> ORDER BY EVENT_ID DESC LIMIT 3 G
    *************************** 1. row ***************************
           THREAD_ID: 13848
            EVENT_ID: 419
        END_EVENT_ID: 434
            SQL_TEXT: SELECT THREAD_ID INTO @my_thread_id
    FROM threads WHERE PROCESSLIST_ID = CONNECTION_ID()
    NESTING_EVENT_ID: NULL
    *************************** 2. row ***************************
           THREAD_ID: 13848
            EVENT_ID: 374
        END_EVENT_ID: 392
            SQL_TEXT: SELECT * FROM sysbench.sbtest1 LIMIT 1
    NESTING_EVENT_ID: NULL
    *************************** 3. row ***************************
           THREAD_ID: 13848
            EVENT_ID: 353
        END_EVENT_ID: 364
            SQL_TEXT: select @@version_comment limit 1
    NESTING_EVENT_ID: NULL
    3 rows in set (0.02 sec)

    From the results above, we are mostly interested with the EVENT_ID and END_EVENT_ID values from the second row, this will give us the stage events of this particular query from the events_stages_history_long table.

    mysql> SELECT EVENT_NAME, SOURCE, (TIMER_END-TIMER_START)/1000000000 as 'DURATION (ms)'
        -> FROM events_stages_history_long
        -> WHERE THREAD_ID = @my_thread_id AND EVENT_ID BETWEEN 374 AND 392;
    +--------------------------------+----------------------+---------------+
    | EVENT_NAME                     | SOURCE               | DURATION (ms) |
    +--------------------------------+----------------------+---------------+
    | stage/sql/init                 | mysqld.cc:998        |        0.0214 |
    | stage/sql/checking permissions | sql_parse.cc:5797    |        0.0023 |
    | stage/sql/Opening tables       | sql_base.cc:5156     |        0.0205 |
    | stage/sql/init                 | sql_select.cc:1050   |        0.0089 |
    | stage/sql/System lock          | lock.cc:306          |        0.0047 |
    | stage/sql/optimizing           | sql_optimizer.cc:138 |        0.0016 |
    | stage/sql/statistics           | sql_optimizer.cc:381 |        0.0058 |
    | stage/sql/preparing            | sql_optimizer.cc:504 |        0.0044 |
    | stage/sql/executing            | sql_executor.cc:110  |        0.0008 |
    | stage/sql/Sending data         | sql_executor.cc:190  |        0.0251 |
    | stage/sql/end                  | sql_select.cc:1105   |        0.0017 |
    | stage/sql/query end            | sql_parse.cc:5465    |        0.0031 |
    | stage/sql/closing tables       | sql_parse.cc:5544    |        0.0037 |
    | stage/sql/freeing items        | sql_parse.cc:6969    |        0.0056 |
    | stage/sql/cleaning up          | sql_parse.cc:1874    |        0.0006 |
    +--------------------------------+----------------------+---------------+
    15 rows in set (0.01 sec)

    As you can see the results are pretty close, not exactly the same but close. SHOW PROFILE shows Duration in seconds, while the results above is in milliseconds.

    Some limitations to this method though:

    • As we’ve seen it takes a few hoops to dish out the information we need. Because we have to identify the statement we have to profile manually, this procedure may not be easy to port into tools like the sys schema or pstop.
    • Only possible if Performance Schema is enabled (by default its enabled since MySQL 5.6.6, yay!)
    • Does not cover all metrics compared to the native profiling i.e. CONTEXT SWITCHES, BLOCK IO, SWAPS
    • Depending on how busy the server you are running the tests, the sizes of the history tables may be too small, as such you either have to increase or loose the history to early i.e. performance_schema_events_stages_history_long_size variable. Using ps_history might help in this case though with a little modification to the queries.
    • The resulting Duration per event may vary, I would think this may be due to the additional as described on performance_timers table. In any case we hope to get this cleared up as result when this bug is fixed.
  • 相关阅读:
    经典矩阵快速幂之一-----poj3233(矩阵套矩阵
    hdu 2588(简单的欧拉
    新能源汽车无线充电管理网站1
    结对项目:黄金点游戏(何珠&赵艳)
    WC项目,实现一个统计程序
    简单四则运算
    在一周之内,快速看完整部教材,列出你不懂的5-10个问题。
    博客作业——创建个人技术博客(建议在cnblogs.com上创建),并写一个自我介绍,列出你对这门课的希望和自己的目标。同时具体列出你计划每周花多少时间在这门课上(包括上课时间)。
    能自动生成小学四则运算题目
    在一周之内,快速看完整部教材,列出你不懂的5-10个问题。
  • 原文地址:https://www.cnblogs.com/digdeep/p/4470081.html
Copyright © 2011-2022 走看看