MariaDB [(none)]> select version();
+--------------------+
| version() |
+--------------------+
| 10.3.8-MariaDB-log |
+--------------------+
1 row in set (0.015 sec)
profile功能默认是关闭需要通过session设置,此参数是会话级别的。
--查看profiling系统变量
MariaDB [sbtest]> show variables like '%profil%';
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| have_profiling | YES |
| profiling | OFF |
| profiling_history_size | 15 |
+------------------------+-------+
3 rows in set (0.002 sec)
have_profiling:只读变量,用于控制是否由系统变量开启或禁用profiling
profiling:开启SQL语句剖析功能
profiling_history_size:设置保留profiling的数目,缺省为15,范围为0至100,为0时将禁用profiling
--获取帮助信息:
MariaDB [sbtest]> help show profile
Name: 'SHOW PROFILE'
Description:
Syntax:
SHOW PROFILE [type [, type] ... ]
[FOR QUERY n]
[LIMIT row_count [OFFSET offset]]
type:
ALL --显示所有的开销信息
| BLOCK IO --显示块IO相关开销
| CONTEXT SWITCHES --上下文切换相关开销
| CPU --显示CPU相关开销信息
| IPC --显示发送和接收相关开销信息
| MEMORY --显示内存相关开销信息
| PAGE FAULTS --显示页面错误相关开销信息
| SOURCE --显示和Source_function,Source_file,Source_line相关的开销信息
| SWAPS --显示交换次数相关开销的信息
也可以通过查询information_schema.PROFILING查询相关信息:
MariaDB [sbtest]> desc INFORMATION_SCHEMA.PROFILING;
+---------------------+--------------+------+-----+----------+-------+
| Field | Type | Null | Key | Default | Extra |
+---------------------+--------------+------+-----+----------+-------+
| QUERY_ID | int(20) | NO | | 0 | |
| SEQ | int(20) | NO | | 0 | |
| STATE | varchar(30) | NO | | | |
| DURATION | decimal(9,6) | NO | | 0.000000 | |
| CPU_USER | decimal(9,6) | YES | | NULL | |
| CPU_SYSTEM | decimal(9,6) | YES | | NULL | |
| CONTEXT_VOLUNTARY | int(20) | YES | | NULL | |
| CONTEXT_INVOLUNTARY | int(20) | YES | | NULL | |
| BLOCK_OPS_IN | int(20) | YES | | NULL | |
| BLOCK_OPS_OUT | int(20) | YES | | NULL | |
| MESSAGES_SENT | int(20) | YES | | NULL | |
| MESSAGES_RECEIVED | int(20) | YES | | NULL | |
| PAGE_FAULTS_MAJOR | int(20) | YES | | NULL | |
| PAGE_FAULTS_MINOR | int(20) | YES | | NULL | |
| SWAPS | int(20) | YES | | NULL | |
| SOURCE_FUNCTION | varchar(30) | YES | | NULL | |
| SOURCE_FILE | varchar(20) | YES | | NULL | |
| SOURCE_LINE | int(20) | YES | | NULL | |
+---------------------+--------------+------+-----+----------+-------+
18 rows in set (0.002 sec)
MariaDB [sbtest]> SELECT @@profiling;
+-------------+
| @@profiling |
+-------------+
| 0 |
+-------------+
1 row in set (0.000 sec)
--开启profile:
MariaDB [sbtest]> set session profiling = 1;
Query OK, 0 rows affected (0.000 sec)
MariaDB [sbtest]> SELECT @@profiling;
+-------------+
| @@profiling |
+-------------+
| 1 |
+-------------+
1 row in set (0.000 sec)
MariaDB [sbtest]> select count(1) from sbtest1 ;
+-----------+
| count(1) |
+-----------+
| 100000000 |
+-----------+
1 row in set (4 min 49.209 sec)
MariaDB [sbtest]> show profiles;
+----------+--------------+--------------------------------------+
| Query_ID | Duration | Query |
+----------+--------------+--------------------------------------+
| 1 | 0.00032802 | SELECT @@profiling |
| 2 | 0.00100349 | show tables |
| 3 | 289.20878779 | select count(1) from sbtest1 |
+----------+--------------+--------------------------------------+
3 rows in set (0.001 sec)
通过查询ID(query_id)查看每个操作具体的资源消耗:
MariaDB [sbtest]> show profile for query 3;
+------------------------+------------+
| Status | Duration |
+------------------------+------------+
| Starting | 0.000131 |
| Checking permissions | 0.000022 |
| Opening tables | 0.000134 |
| After opening tables | 0.000014 |
| System lock | 0.000010 |
| Table lock | 0.000017 |
| Init | 0.000032 |
| Optimizing | 0.000046 |
| Statistics | 0.000032 |
| Preparing | 0.000041 |
| Executing | 0.000011 |
| Sending data | 289.208012 |
| End of update loop | 0.000035 |
| Query end | 0.000009 |
| Commit | 0.000026 |
| Closing tables | 0.000010 |
| Unlocking tables | 0.000007 |
| Closing tables | 0.000043 |
| Starting cleanup | 0.000009 |
| Freeing items | 0.000013 |
| Updating status | 0.000033 |
| Logging slow query | 0.000091 |
| Reset for next command | 0.000009 |
+------------------------+------------+
23 rows in set (0.071 sec)
通过上面的查询可以看到第三个查询语句的资源消耗时间在哪里。
通过下面的语句可以查看CPU、内存等资源的消耗:
MariaDB [sbtest]> show profile cpu,block io,memory,swaps,context switches,source for query 3;
+------------------------+------------+-----------+------------+-------------------+---------------------+--------------+---------------+-------+-----------------+---------------+-------------+
| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Swaps | Source_function | Source_file | Source_line |
+------------------------+------------+-----------+------------+-------------------+---------------------+--------------+---------------+-------+-----------------+---------------+-------------+
| Starting | 0.000131 | 0.000110 | 0.000011 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL |
| Checking permissions | 0.000022 | 0.000024 | 0.000002 | 0 | 0 | 0 | 0 | 0 | <unknown> | sql_parse.cc | 6754 |
| Opening tables | 0.000134 | 0.000000 | 0.000128 | 0 | 0 | 0 | 0 | 0 | <unknown> | sql_base.cc | 3998 |
| After opening tables | 0.000014 | 0.000000 | 0.000012 | 0 | 0 | 0 | 0 | 0 | <unknown> | sql_base.cc | 4245 |
| System lock | 0.000010 | 0.000000 | 0.000011 | 0 | 0 | 0 | 0 | 0 | <unknown> | lock.cc | 340 |
| Table lock | 0.000017 | 0.000000 | 0.000017 | 0 | 0 | 0 | 0 | 0 | <unknown> | lock.cc | 345 |
| Init | 0.000032 | 0.000000 | 0.000033 | 0 | 0 | 0 | 0 | 0 | <unknown> | sql_select.cc | 4196 |
| Optimizing | 0.000046 | 0.000000 | 0.000046 | 0 | 0 | 0 | 0 | 0 | <unknown> | sql_select.cc | 1512 |
| Statistics | 0.000032 | 0.000000 | 0.000032 | 0 | 0 | 0 | 0 | 0 | <unknown> | sql_select.cc | 1879 |
| Preparing | 0.000041 | 0.000000 | 0.000041 | 0 | 0 | 0 | 0 | 0 | <unknown> | sql_select.cc | 1951 |
| Executing | 0.000011 | 0.000000 | 0.000011 | 0 | 0 | 0 | 0 | 0 | <unknown> | sql_select.cc | 3833 |
| Sending data | 289.208012 | 62.238655 | 6.767475 | 100008 | 53 | 2974248 | 80 | 0 | <unknown> | sql_select.cc | 4015 |
| End of update loop | 0.000035 | 0.000020 | 0.000002 | 0 | 0 | 0 | 0 | 0 | <unknown> | sql_select.cc | 4231 |
| Query end | 0.000009 | 0.000008 | 0.000000 | 0 | 0 | 0 | 0 | 0 | <unknown> | sql_parse.cc | 6290 |
| Commit | 0.000026 | 0.000024 | 0.000003 | 0 | 0 | 0 | 0 | 0 | <unknown> | sql_parse.cc | 6352 |
| Closing tables | 0.000010 | 0.000009 | 0.000000 | 0 | 0 | 0 | 0 | 0 | <unknown> | sql_base.cc | 718 |
| Unlocking tables | 0.000007 | 0.000006 | 0.000001 | 0 | 0 | 0 | 0 | 0 | <unknown> | lock.cc | 431 |
| Closing tables | 0.000043 | 0.000040 | 0.000004 | 0 | 0 | 0 | 0 | 0 | <unknown> | lock.cc | 444 |
| Starting cleanup | 0.000009 | 0.000008 | 0.000000 | 0 | 0 | 0 | 0 | 0 | <unknown> | sql_parse.cc | 6424 |
| Freeing items | 0.000013 | 0.000012 | 0.000001 | 0 | 0 | 0 | 0 | 0 | <unknown> | sql_parse.cc | 8090 |
| Updating status | 0.000033 | 0.000030 | 0.000003 | 0 | 0 | 0 | 0 | 0 | <unknown> | sql_parse.cc | 2398 |
| Logging slow query | 0.000091 | 0.000083 | 0.000008 | 0 | 0 | 0 | 8 | 0 | <unknown> | sql_parse.cc | 2510 |
| Reset for next command | 0.000009 | 0.000008 | 0.000001 | 0 | 0 | 0 | 0 | 0 | <unknown> | sql_parse.cc | 2422 |
+------------------------+------------+-----------+------------+-------------------+---------------------+--------------+---------------+-------+-----------------+---------------+-------------+
23 rows in set (0.001 sec)
profile是分析SQL语句的利器。