MySQL中找到SQL耗时瓶颈，(利刀SHOW PROFILE)

最近做的数据量上升了，部分表到了上千条的数据，那个速度真是惨不忍睹啊，一个字“慢”！
分析下SQL的问题吧！手动分析，只能看到网上说的那些优化方法。但是瓶颈在那里呢？可以使用explain 的方式解决，但是还是感觉explain  不够详细。

MySQL5.0.37版本以上支持了，profiling ，据说是Jeremy Cole捐献给MySQL社区版本，呵呵。就说说他的使用吧！

profiling 功能可以了解到sql语句消耗资源的更详细的信息。

show profile 的格式如下：

SHOW PROFILE [type [, type] … ]
    [FOR QUERY n]
    [LIMIT row_count [OFFSET offset]]

type:
    ALL
  | BLOCK IO
  | CONTEXT SWITCHES
  | CPU
  | IPC
  | MEMORY
  | PAGE FAULTS
  | SOURCE
  | SWAPS

该方式默认是关闭的。
可以通过以下语句查看
mysql>select @@profiling;
+————-+
| @@profiling |
+————-+
|           0 |
+————-+
1 row in set (0.00 sec)

打开功能

mysql>set profiling=1;

执行需要测试的sql 语句：

 select inet_ntoa(visit_net) visit_net,sum(totalbytes) as totalbytes,sum(inbytes) as inbytes,sum(totalbytes)-sum(inbytes) as outbytes from
      ( select * from businessflow where userid=9 ) aa
  group by visit_net order by totalbytes DESC limit 0,3

mysql> show profiles\G;

通过指定的Query_ID 来查询指定的sql语句的执行信息：

mysql> show profile for query 1;

+——————————–+———-+
| Status                         | Duration |
+——————————–+———-+
| starting                       | 0.000021 |
| checking query cache for query | 0.000085 |
| Opening tables                 | 0.000036 |
| System lock                    | 0.000007 |
| Table lock                     | 0.000071 |
| optimizing                     | 0.000012 |
| statistics                     | 0.000013 |
| preparing                      | 0.000013 |
| executing                      | 0.000005 |
| Sending data                   | 0.592819 |
| converting HEAP to MyISAM      | 0.026474 |
| Sending data                   | 0.215715 |
| init                           | 0.000029 |
| storing result in query cache  | 0.000012 |
| optimizing                     | 0.000005 |
| statistics                     | 0.000011 |
| preparing                      | 0.000008 |
| Creating tmp table             | 0.000038 |
| executing                      | 0.000004 |
| Copying to tmp table           | 0.235759 |
| converting HEAP to MyISAM      | 1.020230 |
| Copying to tmp table on disk   | 0.166174 |
| Sorting result                 | 0.056304 |
| Sending data                   | 0.000053 |
| end                            | 0.000004 |
| removing tmp table             | 0.003539 |
| end                            | 0.000008 |
| query end                      | 0.000004 |
| freeing items                  | 0.000036 |
| removing tmp table             | 0.004107 |
| closing tables                 | 0.000009 |
| logging slow query             | 0.000004 |
| cleaning up                    | 0.000004 |
+——————————–+———-+
33 rows in set (0.00 sec)
mysql> show profile cpu for query 1;
+——————————–+———-+———-+————+
| Status                         | Duration | CPU_user | CPU_system |
+——————————–+———-+———-+————+
| starting                       | 0.000021 | 0.000000 |   0.000000 |
| checking query cache for query | 0.000085 | 0.000000 |   0.000000 |
| Opening tables                 | 0.000036 | 0.000000 |   0.000000 |
| System lock                    | 0.000007 | 0.000000 |   0.000000 |
| Table lock                     | 0.000071 | 0.000000 |   0.000000 |
| optimizing                     | 0.000012 | 0.000000 |   0.000000 |
| statistics                     | 0.000013 | 0.000000 |   0.000000 |
| preparing                      | 0.000013 | 0.000000 |   0.000000 |
| executing                      | 0.000005 | 0.000000 |   0.000000 |
| Sending data                   | 0.592819 | 0.592037 |   0.000000 |
| converting HEAP to MyISAM      | 0.026474 | 0.000000 |   0.020002 |
| Sending data                   | 0.215715 | 0.212014 |   0.008000 |
| init                           | 0.000029 | 0.000000 |   0.000000 |
| storing result in query cache  | 0.000012 | 0.000000 |   0.000000 |
| optimizing                     | 0.000005 | 0.000000 |   0.000000 |
| statistics                     | 0.000011 | 0.000000 |   0.000000 |
| preparing                      | 0.000008 | 0.000000 |   0.000000 |
| Creating tmp table             | 0.000038 | 0.000000 |   0.000000 |
| executing                      | 0.000004 | 0.000000 |   0.000000 |
| Copying to tmp table           | 0.235759 | 0.240015 |   0.000000 |
| converting HEAP to MyISAM      | 1.020230 | 0.988061 |   0.032002 |
| Copying to tmp table on disk   | 0.166174 | 0.160010 |   0.000000 |
| Sorting result                 | 0.056304 | 0.052004 |   0.008001 |
| Sending data                   | 0.000053 | 0.000000 |   0.000000 |
| end                            | 0.000004 | 0.000000 |   0.000000 |
| removing tmp table             | 0.003539 | 0.000000 |   0.000000 |
| end                            | 0.000008 | 0.000000 |   0.000000 |
| query end                      | 0.000004 | 0.000000 |   0.000000 |
| freeing items                  | 0.000036 | 0.000000 |   0.000000 |
| removing tmp table             | 0.004107 | 0.000000 |   0.008000 |
| closing tables                 | 0.000009 | 0.000000 |   0.000000 |
| logging slow query             | 0.000004 | 0.000000 |   0.000000 |
| cleaning up                    | 0.000004 | 0.000000 |   0.000000 |
+——————————–+———-+———-+————+
33 rows in set (0.00 sec)

从上上面可以看到，

| Sending data                   | 0.592819 |
| converting HEAP to MyISAM      | 0.026474 |
| Sending data                   | 0.215715 |

| Copying to tmp table           | 0.235759 |
| converting HEAP to MyISAM      | 1.020230 |
| Copying to tmp table on disk   | 0.166174 |

以上几项 耗时较长，所以考虑把该表转换为MyISAM 以供查询提高速度。并且提高的值

测试完毕以后 ，关闭参数：

mysql> set profiling=0

再次打开程序，发现等待速度降低。问题有所好转。OK！
参考：http://dev.mysql.com/doc/refman/5.0/en/show-profiles.html