How to use profiling to analyze SQL query statement in MySQL
Check to see if profiling is enabled:
Mysql > select @ @ profiling
+-+
| | @ @ profiling |
+-+
| | 0 |
+-+
1 row in set (0.00 sec)
Enable profiling:
Mysql > set profiling=1
Query OK, 0 rows affected (0.00 sec)
Mysql > select @ @ profiling
+-+
| | @ @ profiling |
+-+
| | 1 |
+-+
1 row in set (0.00 sec)
Execute several SQL queries:
Mysql > use mysql
Database changed
Mysql > select database ()
+-+
| | database () |
+-+
| | mysql |
+-+
1 row in set (0.00 sec)
Mysql > select host,user,Password from user limit 10
+-- +
| | host | user | Password | |
+-- +
| | localhost | root | * 6BB4837EB74329105EE4568DDA7DC67ED2CA2AD9 |
| |% | chenfeng | * 716E7D76E850A91A8311F35B6BFB1213B751F230 |
| |% | test@localhost | * 6BB4837EB74329105EE4568DDA7DC67ED2CA2AD9 |
| |% | sa@localhost | * 4D0DD2673C1DE57138354E81A957460B774C4BC2 |
| |% | admin@localhost | * 4ACFE3202A5FF5CF467898FC58AAB1D615029441 |
| | localhost | dsf | * AFED783E50FCEF7B1C89AC89C6E1A0405BD7F313 |
| | localhost | dsf1 | * 98D1D8D997EA32BABDFEEC2EBB62BB6D010036C6 |
| |% | dsf2 | * 0007B182797FAD2A8A37C3F73A011BBD36C49857 |
+-- +
8 rows in set (0.00 sec)
Query the Profiling of the above statement:
Mysql > show profiles
+-+
| | Query_ID | Duration | Query | |
+-+
| | 1 | 0.00012600 | select @ @ profiling |
| | 2 | 0.00018450 | SELECT DATABASE () |
| | 3 | 0.00011950 | select database () |
| | 4 | 0.11296025 | show columns from user |
| | 5 | 0.00038725 | select host,user,Password from user limit 10 |
+-+
14 rows in set (0.00 sec)
Check the Istroke O consumption of the Query_ID=5 statement:
Mysql > show profile block io for query 5
+-+
| | Status | Duration | Block_ops_in | Block_ops_out | |
+-+
| | starting | 0.000018 | NULL | NULL | |
| | Waiting for query cache lock | 0.000003 | NULL | NULL | |
| | checking query cache for query | 0.000077 | NULL | NULL | |
| | checking permissions | 0.000009 | NULL | NULL | |
| | Opening tables | 0.000020 | NULL | NULL | |
| | System lock | 0.000014 | NULL | NULL | |
| | init | 0.000020 | NULL | NULL | |
| | optimizing | 0.000005 | NULL | NULL | |
| | statistics | 0.000011 | NULL | NULL | |
| | preparing | 0.000009 | NULL | NULL | |
| | executing | 0.000003 | NULL | NULL | |
| | Sending data | 0.000071 | NULL | NULL | |
| | end | 0.000004 | NULL | NULL | |
| | query end | 0.000002 | NULL | NULL | |
| | closing tables | 0.000011 | NULL | NULL | |
| | freeing items | 0.000101 | NULL | NULL | |
| | logging slow query | 0.000006 | NULL | NULL | |
| | cleaning up | 0.000004 | NULL | NULL | |
+-+
18 rows in set (0.00 sec)
View the CPU consumption of the Query_ID=5 statement:
Mysql > show profile cpu for query 5
+-+
| | Status | Duration | CPU_user | CPU_system | |
+-+
| | starting | 0.000018 | 0.000000 | 0.000000 | |
| | Waiting for query cache lock | 0.000003 | 0.000000 | 0.000000 | |
| | checking query cache for query | 0.000077 | 0.000000 | 0.000000 | |
| | checking permissions | 0.000009 | 0.000000 | 0.000000 | |
| | Opening tables | 0.000020 | 0.000000 | 0.000000 | |
| | System lock | 0.000014 | 0.000000 | 0.000000 | |
| | init | 0.000020 | 0.000000 | 0.000000 | |
| | optimizing | 0.000005 | 0.000000 | 0.000000 | |
| | statistics | 0.000011 | 0.000000 | 0.000000 | |
| | preparing | 0.000009 | 0.000000 | 0.000000 | |
| | executing | 0.000003 | 0.000000 | 0.000000 | |
| | Sending data | 0.000071 | 0.000000 | 0.000000 | |
| | end | 0.000004 | 0.000000 | 0.000000 | |
| | query end | 0.000002 | 0.000000 | 0.000000 | |
| | closing tables | 0.000011 | 0.000000 | 0.000000 | |
| | freeing items | 0.000101 | 0.000000 | 0.000000 | |
| | logging slow query | 0.000006 | 0.000000 | 0.000000 | |
| | cleaning up | 0.000004 | 0.000000 | 0.000000 | |
+-+
18 rows in set (0.00 sec)
Mysql >
