MySQL调优三部曲（三）PROFILE

分析SQL执行带来的开销是优化SQL的重要手段，MySQL可以通过设置profiling参数，将SQL语句的资源开销，如IO、上下文切换、CPU、Memory等记录下来

查看profiling系统变量

mysql> show variables like '%profil%'; 
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| have_profiling         | YES   |
| profiling              | OFF   |
| profiling_history_size | 15    |
+------------------------+-------+
  • have_profiling： 当前版本是否支持profiling功能
  • profiling： 是否开启profiling功能
  • profiling_history_size： 保留profiling的数目，默认是15，范围为0~100，为0时代表禁用profiling

开启profiling

启用session级别的profile 
mysql> set profiling=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
验证修改后的结果
mysql> show variables like '%profil%'; 
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| have_profiling         | YES   |
| profiling              | ON    |
| profiling_history_size | 15    |
+------------------------+-------+

进行profile分析

1. 进行Query操作
mysql> select count(*) from ttkk_user;
+----------+
| count(*) |
+----------+
|       55 |
+----------+
2. 查看当前session产生的profile 
mysql> show profiles;
+----------+------------+--------------------------------+
| Query_ID | Duration   | Query                          |
+----------+------------+--------------------------------+
|        1 | 0.00051550 | show variables like '%profil%' |
|        2 | 0.00016350 | select count(*) from ttkk_user |
+----------+------------+--------------------------------+
3. 获取指定查询的开销
mysql> show profile for query 2;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000053 |
| checking permissions | 0.000007 |
| Opening tables       | 0.000019 |
| init                 | 0.000013 |
| System lock          | 0.000008 |
| optimizing           | 0.000008 |
| executing            | 0.000009 |
| end                  | 0.000004 |
| query end            | 0.000003 |
| closing tables       | 0.000008 |
| freeing items        | 0.000020 |
| cleaning up          | 0.000013 |
+----------------------+----------+
12 rows in set, 1 warning (0.00 sec)
当查到最耗时的线程状态时，可以进一步选择all或者cpu、block io等明细类型来查看mysql在每个线程状态中使用什么资源上耗费了过高的时间
mysql>  show profile block io,cpu for query 2; 
+----------------------+----------+----------+------------+--------------+---------------+
| Status               | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting             | 0.000053 | 0.000022 |   0.000026 |            0 |             0 |
| checking permissions | 0.000007 | 0.000003 |   0.000004 |            0 |             0 |
| Opening tables       | 0.000019 | 0.000008 |   0.000010 |            0 |             0 |
| init                 | 0.000013 | 0.000006 |   0.000008 |            0 |             0 |
| System lock          | 0.000008 | 0.000004 |   0.000004 |            0 |             0 |
| optimizing           | 0.000008 | 0.000003 |   0.000004 |            0 |             0 |
| executing            | 0.000009 | 0.000004 |   0.000005 |            0 |             0 |
| end                  | 0.000004 | 0.000002 |   0.000002 |            0 |             0 |
| query end            | 0.000003 | 0.000001 |   0.000001 |            0 |             0 |
| closing tables       | 0.000008 | 0.000003 |   0.000005 |            0 |             0 |
| freeing items        | 0.000020 | 0.000010 |   0.000011 |            0 |             0 |
| cleaning up          | 0.000013 | 0.000005 |   0.000007 |            0 |             0 |
+----------------------+----------+----------+------------+--------------+---------------+
12 rows in set, 1 warning (0.00 sec)
一条query每个阶段的资源开销可以从information_schema.profiling表查询
mysql> select * from profiling where query_id = 2;
+----------+-----+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
| QUERY_ID | SEQ | STATE                | 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 |
+----------+-----+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
|        2 |   2 | starting             | 0.000053 | 0.000022 |   0.000026 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | NULL                  | NULL             |        NULL |
|        2 |   3 | checking permissions | 0.000007 | 0.000003 |   0.000004 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | check_access          | sql_parse.cc     |        5350 |
|        2 |   4 | Opening tables       | 0.000019 | 0.000008 |   0.000010 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | open_tables           | sql_base.cc      |        5095 |
|        2 |   5 | init                 | 0.000013 | 0.000006 |   0.000008 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_prepare_select  | sql_select.cc    |        1051 |
|        2 |   6 | System lock          | 0.000008 | 0.000004 |   0.000004 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_lock_tables     | lock.cc          |         304 |
|        2 |   7 | optimizing           | 0.000008 | 0.000003 |   0.000004 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | optimize              | sql_optimizer.cc |         139 |
|        2 |   8 | executing            | 0.000009 | 0.000004 |   0.000005 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | exec                  | sql_executor.cc  |         110 |
|        2 |   9 | end                  | 0.000004 | 0.000002 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_select  | sql_select.cc    |        1106 |
|        2 |  10 | query end            | 0.000003 | 0.000001 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command | sql_parse.cc     |        5049 |
|        2 |  11 | closing tables       | 0.000008 | 0.000003 |   0.000005 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command | sql_parse.cc     |        5097 |
|        2 |  12 | freeing items        | 0.000020 | 0.000010 |   0.000011 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_parse           | sql_parse.cc     |        6486 |
|        2 |  13 | cleaning up          | 0.000013 | 0.000005 |   0.000007 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | dispatch_command      | sql_parse.cc     |        1815 |
+----------+-----+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
information_schema.profiling表主要字段含义
  • state : 当前query所在的阶段
  • CPU_user : CPU用户
  • CPU_system : CPU系统
  • 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 : 源代码行
©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 158,736评论 4赞 362
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 67,167评论 1赞 291
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 108,442评论 0赞 243
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 43,902评论 0赞 204
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 52,302评论 3赞 287
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 40,573评论 1赞 216
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 31,847评论 2赞 312
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 30,562评论 0赞 197
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 34,260评论 1赞 241
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 30,531评论 2赞 245
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 32,021评论 1赞 258
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 28,367评论 2赞 253
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 33,016评论 3赞 235
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 26,068评论 0赞 8
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,827评论 0赞 194
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 35,610评论 2赞 274
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 35,514评论 2赞 269

推荐阅读更多精彩内容