MySQL5.7 Profile 的使用

MySQL Profile对于分析执行计划的开销来说,还是有一定的帮助,至少在分析一些性能问题的时候有很多的参考依据。
我在5.6, 5.7版本中进行了测试,没发现差别,还是以5.7为例进行演示吧。

mysql> status;
--------------
MYSQL  Ver 14.14 Distrib 5.7.17, for macos10.12 (x86_64) using  EditLine wrapper

Connection id:      5
Current database:   performance_schema
Current user:       root@localhost
SSL:            Not in use
Current pager:      stdout
Using outfile:      ''
Using delimiter:    ;
Server version:     5.7.17 MySQL Community Server (GPL)
Protocol version:   10
Connection:     Localhost via UNIX socket
Server characterset:    latin1
Db     characterset:    utf8
Client characterset:    utf8
Conn.  characterset:    utf8
UNIX socket:        /tmp/mysql.sock
Uptime:         8 hours 26 min 58 sec

传统的使用Profile都是使用show profile这样的命令方式,这个功能默认是关闭的,通过 have_profiling 参数查看当前 MySQL是否支持 profile。

mysql> select @@have_profiling;
+------------------+
| @@have_profiling |
+------------------+
| YES              |
+------------------+
1 row in set, 1 warning (0.00 sec)

可以看到有一个警告,我们看看是什么警告。

mysql> show warnings;
+---------+------+--------------------------------------------------------------------------------------------------------------+
| Level  | Code | Message                                                                                                      |
+---------+------+--------------------------------------------------------------------------------------------------------------+
| Warning | 1287 | 'SHOW PROFILES' is deprecated and will be removed in a future release. Please use Performance Schema instead |
+---------+------+--------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

原来这种方式已经过期,新的功能是在performance_schema中开放。当然在5.6, 5.7版本中还是暂时可用,我们先简单了解一下,再来看performance_schema怎么用。

profile相关的几个参数如下:

mysql> show variables like '%profil%';
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| have_profiling        | YES  |
| profiling              | OFF  |
| profiling_history_size | 15    |
+------------------------+-------+
3 rows in set (0.00 sec)

可以看到Profileing为OFF,当前默认值为0,代表的是一个意思。

mysql> SELECT @@profiling;
+-------------+
| @@profiling |
+-------------+
|          0 |
+-------------+
1 row in set, 1 warning (0.00 sec)

have_profiling 用于控制是否开启或者禁用Profiling
profiling_history_size是保留Profiling的数目

当然本质上,Profile的内容还是来自于information_schema数据库的 profiling 表。

mysql> select * from information_schema.profiling\G
Empty set, 1 warning (0.00 sec)

这个地方还是有一个警告,还是过期的提示。

mysql> show warnings;
+---------+------+-----------------------------------------------------------------------------------------------------------------------------+
| Level  | Code | Message                                                                                                                    |
+---------+------+-----------------------------------------------------------------------------------------------------------------------------+
| Warning | 1287 | 'INFORMATION_SCHEMA.PROFILING' is deprecated and will be removed in a future release. Please use Performance Schema instead |
+---------+------+-----------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

接下来开启profiling

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

查看所有的profiles

mysql> show profiles;
+----------+------------+---------------+
| Query_ID | Duration  | Query        |
+----------+------------+---------------+
|        1 | 0.00018200 | show warnings |
+----------+------------+---------------+
1 row in set, 1 warning (0.00 sec)

我们顺便运行一条SQL

mysql> select count(*)from information_schema.columns;
+----------+
| count(*) |
+----------+
|    3077 |
+----------+
1 row in set (0.07 sec)

然后再次查看,就会看到query_ID会得到刚刚运行的语句。

mysql> show profiles;
+----------+------------+------------------------------------------------+
| Query_ID | Duration  | Query                                          |
+----------+------------+------------------------------------------------+
|        1 | 0.00018200 | show warnings                                  |
|        2 | 0.06627200 | select count(*)from information_schema.columns |
+----------+------------+------------------------------------------------+
2 rows in set, 1 warning (0.00 sec)

可以使用如下的方式来查看profile的信息,比如涉及CPU的明细信息。

mysql> show profile cpu for query 2;
+----------------------+----------+----------+------------+
| Status              | Duration | CPU_user | CPU_system |
+----------------------+----------+----------+------------+
| checking permissions | 0.000004 | 0.000000 |  0.000000 |
| checking permissions | 0.000053 | 0.000999 |  0.000000 |
| checking permissions | 0.000014 | 0.000000 |  0.000000 |
| checking permissions | 0.000006 | 0.000000 |  0.000000 |
。。。。。
| closing tables      | 0.000005 | 0.000000 |  0.000000 |
| freeing items        | 0.000052 | 0.000000 |  0.000000 |
| cleaning up          | 0.000023 | 0.000000 |  0.000000 |
+----------------------+----------+----------+------------+
100 rows in set, 1 warning (0.00 sec)

除此之外,还有其他选项all、cpu、block、io、context、switch、page faults 等用来查看 MySQL在使用什么资源时浪费了过高的时间。

上面的内容已经过期即将在未来版本中删除,那么我们来看看新版本中推荐的performace_schema如何使用。先切换到performance_schema下,这是MySQL新增的性能优化引擎,在5.6以前是关闭的,5.6, 5.7中是默认开启的,5.7切换的时候还会有一句提示:

mysql> use performance_schema;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed

提示我们在连接 MySQL 的时候可以使用-A 参数预读数据库。

使用profile涉及几个表,setup_actors、setup_instruments、setup_consumers。默认表setup_actors的内容如下:

mysql> SELECT * FROM setup_actors;
+------+------+------+---------+---------+
| HOST | USER | ROLE | ENABLED | HISTORY |
+------+------+------+---------+---------+
| %    | %    | %    | YES    | YES    |
+------+------+------+---------+---------+
1 row in set (0.00 sec)

按照官方的建议,默认是启用,可以根据需求禁用。

mysql> UPDATE performance_schema.setup_actors
    -> SET enabled = 'no',history = 'no'
    -> WHERE host = '%' AND user = '%';
Query OK, 1 row affected (0.04 sec)
Rows matched: 1  Changed: 1  Warnings: 0

禁用后的内容如下:

mysql> select * from setup_actors;
+------+------+------+---------+---------+
| HOST | USER | ROLE | ENABLED | HISTORY |
+------+------+------+---------+---------+
| %    | %    | %    | NO      | NO      |
+------+------+------+---------+---------+
1 row in set (0.00 sec)

然后加入指定的用户

mysql> INSERT INTO performance_schema.setup_actors
    -> (HOST,USER,ROLE,ENABLED,HISTORY)
    -> VALUES('localhost','root','%','YES','YES');
Query OK, 1 row affected (0.03 sec)

加入成功后的数据内容如下:

mysql> select * from setup_actors;
+-----------+------+------+---------+---------+
| HOST      | USER | ROLE | ENABLED | HISTORY |
+-----------+------+------+---------+---------+
| %         | %    | %    | NO      | NO      |
| localhost | root | %    | YES     | YES     |
+-----------+------+------+---------+---------+
2 rows in set (0.00 sec)

好了,setup_actors 的配置就这样,另外两个表的内容修改也是大同小异。

表 setup_consumers 描述各种事件,
表setup_instruments 描述这个数据库下的表名以及是否开启监控。

我统计了一下,两个表的默认数据还不少。
setup_instruments 1006 rows
setup_consumers 15 rows

我们按照官方的建议来修改,可以看到修改的不是一行,而是相关的很多行。

mysql> UPDATE performance_schema.setup_instruments 
    -> SET ENABLED = 'YES', TIMED = 'YES'
    -> WHERE NAME LIKE '%statement/%';
Query OK, 0 rows affected (0.00 sec)
Rows matched: 193  Changed: 0  Warnings: 0

mysql> UPDATE performance_schema.setup_instruments
    -> SET ENABLED = 'YES', TIMED = 'YES'
    -> WHERE NAME LIKE '%stage/%';
Query OK, 120 rows affected (0.00 sec)
Rows matched: 129  Changed: 120  Warnings: 0

mysql> UPDATE performance_schema.setup_consumers
    -> SET ENABLED = 'YES'
    -> WHERE NAME LIKE '%events_statements_%';
Query OK, 1 row affected (0.00 sec)
Rows matched: 3  Changed: 1  Warnings: 0

mysql> UPDATE performance_schema.setup_consumers
    -> SET ENABLED = 'YES'
    -> WHERE NAME LIKE '%events_stages_%'; 
Query OK, 3 rows affected (0.00 sec)
Rows matched: 3  Changed: 3  Warnings: 0

OK,配置完成,我们来看一下怎么用。创建一个test数据库。

mysql> create database test;
Query OK, 1 row affected (0.00 sec)

切换到test数据库

mysql> use test
Database changed

创建一个测试表test_profile,插入几行数据。

mysql> create table test_profile as select * from information_schema.columns limit 1,5;
Query OK, 5 rows affected (0.10 sec)
Records: 5  Duplicates: 0  Warnings: 0 

运行语句来得到一些详细的统计信息。

mysql> select * from test.test_profile limit 1,2 \G
*************************** 1. row ***************************
           TABLE_CATALOG: def
            TABLE_SCHEMA: information_schema
              TABLE_NAME: CHARACTER_SETS
             COLUMN_NAME: DESCRIPTION
        ORDINAL_POSITION: 3
          COLUMN_DEFAULT: 
             IS_NULLABLE: NO
               DATA_TYPE: varchar
CHARACTER_MAXIMUM_LENGTH: 60
  CHARACTER_OCTET_LENGTH: 180
       NUMERIC_PRECISION: NULL
           NUMERIC_SCALE: NULL
      DATETIME_PRECISION: NULL
      CHARACTER_SET_NAME: utf8
          COLLATION_NAME: utf8_general_ci
             COLUMN_TYPE: varchar(60)
              COLUMN_KEY: 
                   EXTRA: 
              PRIVILEGES: select
          COLUMN_COMMENT: 
   GENERATION_EXPRESSION: 
*************************** 2. row ***************************
           TABLE_CATALOG: def
            TABLE_SCHEMA: information_schema
              TABLE_NAME: CHARACTER_SETS
             COLUMN_NAME: MAXLEN
        ORDINAL_POSITION: 4
          COLUMN_DEFAULT: 0
             IS_NULLABLE: NO
               DATA_TYPE: bigint
CHARACTER_MAXIMUM_LENGTH: NULL
  CHARACTER_OCTET_LENGTH: NULL
       NUMERIC_PRECISION: 19
           NUMERIC_SCALE: 0
      DATETIME_PRECISION: NULL
      CHARACTER_SET_NAME: NULL
          COLLATION_NAME: NULL
             COLUMN_TYPE: bigint(3)
              COLUMN_KEY: 
                   EXTRA: 
              PRIVILEGES: select
          COLUMN_COMMENT: 
   GENERATION_EXPRESSION: 
2 rows in set (0.00 sec)

根据下面的语句查询一个历史表,从表名可以看出是和事件相关的,感觉越来越像Oracle了。。。

mysql> SELECT EVENT_ID, TRUNCATE(TIMER_WAIT/1000000000000,6) as Duration, SQL_TEXT
    -> FROM performance_schema.events_statements_history_long
    -> WHERE SQL_TEXT like '%limit 1,2%';
+----------+----------+-------------------------------------------+
| EVENT_ID | Duration | SQL_TEXT                                  |
+----------+----------+-------------------------------------------+
|     4571 | 0.000196 | select * from test.test_profile limit 1,2 |
|     4587 | 0.000214 | select * from test.test_profile limit 1,2 |
|     4603 | 0.000211 | select * from test.test_profile limit 1,2 |
+----------+----------+-------------------------------------------+
3 rows in set (0.04 sec)

我们通过上面的语句可以得到一个概览,对应的事件和执行时间。然后到stage相关的历史表中查看事件的详细信息,这就是我们期望的性能数据。如此一来应该就明白上面的配置表中所要做的工作是什么意思了。

mysql> SELECT event_name AS Stage, TRUNCATE(TIMER_WAIT/1000000000000,6) AS Duration
    -> FROM performance_schema.events_stages_history_long 
    -> WHERE NESTING_EVENT_ID=4603;
+--------------------------------+----------+
| Stage                          | Duration |
+--------------------------------+----------+
| stage/sql/starting             | 0.000064 |
| stage/sql/checking permissions | 0.000004 |
| stage/sql/Opening tables       | 0.000023 |
| stage/sql/init                 | 0.000023 |
| stage/sql/System lock          | 0.000005 |
| stage/sql/optimizing           | 0.000002 |
| stage/sql/statistics           | 0.000007 |
| stage/sql/preparing            | 0.000006 |
| stage/sql/executing            | 0.000001 |
| stage/sql/Sending data         | 0.000046 |
| stage/sql/end                  | 0.000002 |
| stage/sql/query end            | 0.000003 |
| stage/sql/closing tables       | 0.000005 |
| stage/sql/freeing items        | 0.000012 |
| stage/sql/cleaning up          | 0.000000 |
+--------------------------------+----------+
15 rows in set (0.01 sec)

整体来看,看到这个特性的输出,十分类似于Oracle中的Datapump,输出实在是太像了,很有条理。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 215,133评论 6 497
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 91,682评论 3 390
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 160,784评论 0 350
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 57,508评论 1 288
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 66,603评论 6 386
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 50,607评论 1 293
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,604评论 3 415
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 38,359评论 0 270
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,805评论 1 307
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,121评论 2 330
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,280评论 1 344
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,959评论 5 339
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,588评论 3 322
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,206评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,442评论 1 268
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 47,193评论 2 367
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,144评论 2 352

推荐阅读更多精彩内容