MySQL-慢查询

参考文献

• 高性能MySQL(第三版)
• MySQL实战45讲
• MySQL技术内幕 InnoDB存储引擎

慢查询

慢查询日志(slow query log)

• 慢查询日志可以帮助定位存在问题的SQL语句,从而进行SQL语句层面的优化.在MySQL启动时,设置一个阈值,将运行超过这个值的所有SQL语句都会记录到慢查询日志文件中.该阈值可以通过参数long_query_time来设置,默认值为10,单位为秒.

  mysql> show variables like 'long_query_time';
  +-----------------+-----------+
  | Variable_name   | Value     |
  +-----------------+-----------+
  | long_query_time | 10.000000 |
  +-----------------+-----------+
  1 row in set (0.01 sec)
  
  mysql> show variables like 'slow_query_log';
  +----------------+-------+
  | Variable_name  | Value |
  +----------------+-------+
  | slow_query_log | OFF   |
  +----------------+-------+
  1 row in set (0.00 sec)
  
  mysql> show variables like 'slow_query_log_file';
  +---------------------+------------------------------------+
  | Variable_name       | Value                              |
  +---------------------+------------------------------------+
  | slow_query_log_file | /usr/local/mysql/data/192-slow.log |
  +---------------------+------------------------------------+
  1 row in set (0.03 sec)

  • 需要注意的是:设置long_query_time这个阈值后,MySQL数据库会记录运行时间超过该值的所有SQL语句,但运行时间正好等于long_query_time的情况并不会被记录下来.也就是说,源码中判断的是大于long_query_time,而非大于等于.其次,从MySQL5.1开始以微妙记录SQL运行的时间.

• 另一个和慢查询日志有关的参数是log_queries_not_using_indexes,如果运行的SQL语句没有使用索引,则MySQL数据库同样会将这条SQL记录到慢查询日志文件.

mysql> show variables like 'log_queries_not_using_indexes';
+-------------------------------+-------+
| Variable_name                 | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | OFF   |
+-------------------------------+-------+
1 row in set (0.00 sec)

• MySQL5.6.5版本开始新增了一个参数log_throttle_queries_not_using_indexes,用来表示每分钟允许记录到slow log的且未使用索引的SQL语句次数,该值默认为0.表示没有限制.在生产环境下,若没有使用索引,此类SQL语句会频繁地被记录到slow log,从而导致slow log文件的大小不断增加,故DBA可通过此参数进行配置.

慢查询相关参数

• slow_query_log:是否启用慢查询日志,默认为0,可设置为0或1,1表示开启.
• slow_query_log_file:指定慢查询日志位置及名称,默认值为host_name-slow.log,可指定绝对路径.
• long_query_time:慢查询执行时间阈值,超过此时间会记录,默认为10,单位为s.
• log_output:慢查询日志输出目标,默认为file,即输出到文件[FILE|TABLE|NONE].
• log_timestamps:主要是控制error log、slow log、genera log日志文件中的显示时区,默认使用UTC时区,建议改为SYSTEM系统时区.
• log_queries_not_using_indexes:是否记录所有未使用索引的查询语句,默认为off.
• min_examined_row_limit:对于查询扫描行数小于此参数的SQL,将不会记录到慢查询日志中,默认为0.
• log_slow_admin_statements:慢速管理语句是否写入慢日志中,管理语句包含alter table、create index等,默认为off即不写入.

开启慢查询日志

set global slow_query_log=on;

设置慢查询阈值

# 设置全局
set global long_query_time=1;

# 设置当前Session
set long_query_time=1;

# 修改my.cnf文件,重启mysql
slow_query_log = 1
long_query_time = 1
log-slow-queries = /var/log/mysql/log-slow-queries.log
log_queries_not_using_indexes = 0

• 阈值的默认值是10s,自行设置,只要SQL的实际执行时间超过了这个阈值,就会被记录到慢查询的日志里面,线上业务一般建议把long_query_time设置为1s,如果某个业务的MySQL要求比较高的QPS,可设置慢查询为0.1s.
• 一般测试环境建议long_query_time设置的阀值比生产环境的小,比如生产环境是1s,则测试环境建议配置成0.5s.便于在测试环境及时发现一些效率的SQL.

查看慢查询日志

• 确定文件位置

  mysql> show global variables like 'slow_query_log_file';
  +---------------------+-----------------------------------------------------+
  | Variable_name       | Value                                               |
  +---------------------+-----------------------------------------------------+
  | slow_query_log_file | /usr/local/mysql/data/HoleLindeMacBook-Pro-slow.log |
  +---------------------+-----------------------------------------------------+
  1 row in set (0.02 sec)

• 查看日志

  sh-3.2# cat HoleLindeMacBook-Pro-slow.log
  /usr/local/mysql/bin/mysqld, Version: 8.0.26 (MySQL Community Server - GPL). started with:
  Tcp port: 3306  Unix socket: /tmp/mysql.sock
  Time                 Id Command    Argument
  # Time: 2023-03-24T06:27:53.041724Z
  # User@Host: root[root] @ localhost []  Id:  1642
  # Query_time: 2.005254  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 1
  use dicom;
  SET timestamp=1679639271;
  select sleep(2);

  • Time:慢查询发生的时间
  • Query_time:查询时间
  • Lock_time:等待锁表的时间
  • Rows_sent:语句返回的行数
  • Rows_exanined:语句执行期间从存储引擎读取的行数（重点关注提前优化）

在线清除慢查询日志内容

# 备份原来慢查询日志文件
mv slow.log slow.log.2024.06.01

# 在MySQL命令行中执行
mysql> flush slow logs;

慢查询分析

使用EXPLAIN

• MySQL(十六)-Explain用法说明

使用PROFILE

 -- 查看是否开启,开启后可以让MySQL收集在SQL执行时所使用的资源情况
 SELECT @@profiling;
 -- 0代表关闭,1代表打开 
 SET profiling=1;
 
 -- 保证想要查看的 PROFILE 结果还保存着,因此可以用如下操作来增加  PROFILE 的队列大小
 SET session profiling_history_size = 50;

 show profiles;
  
mysql> show profile for query 1;
+---------------+----------+
| Status        | Duration |
+---------------+----------+
| starting      | 0.000697 |
| freeing items | 0.000060 |
| cleaning up   | 0.000021 |
+---------------+----------+
3 rows in set, 1 warning (0.00 sec)

mysql> show profile block io,cpu,memory,source for query 1;
+---------------+----------+----------+------------+--------------+---------------+----------------------+--------------+-------------+
| Status        | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | Source_function      | Source_file  | Source_line |
+---------------+----------+----------+------------+--------------+---------------+----------------------+--------------+-------------+
| starting      | 0.000697 | 0.000075 |   0.000414 |            0 |             0 | NULL                 | NULL         |        NULL |
| freeing items | 0.000060 | 0.000023 |   0.000038 |            0 |             0 | dispatch_sql_command | sql_parse.cc |        5075 |
| cleaning up   | 0.000021 | 0.000007 |   0.000014 |            0 |             0 | dispatch_command     | sql_parse.cc |        2276 |
+---------------+----------+----------+------------+--------------+---------------+----------------------+--------------+-------------+
3 rows in set, 1 warning (0.00 sec)

使用optimizer_trace

-- 打开开关
SET session optimizer_trace='enabled=on';
-- 查看执行计划
select * from information_schema.optimizer_trace\G

  {
  "steps": [
    {
      # 第一步: perpare准备阶段
      "join_preparation": {
        "select#": 1,
        "steps": [
          {
      			# 进行SQL语句格式化操作
            "expanded_query": "/* select#1 */ select `dicom_image_info`.`id` AS `id`,`dicom_image_info`.`patient_id` AS `patient_id`,`dicom_image_info`.`study_instance_uid` AS `study_instance_uid`,`dicom_image_info`.`series_instance_uid` AS `series_instance_uid`,`dicom_image_info`.`sop_instance_uid` AS `sop_instance_uid`,`dicom_image_info`.`instance_number` AS `instance_number`,`dicom_image_info`.`created_time` AS `created_time`,`dicom_image_info`.`updated_time` AS `updated_time` from `dicom_image_info` where (`dicom_image_info`.`patient_id` = '3583925')"
          }
        ]
      }
    },
    {
      # 第二步: SQL优化阶段
      "join_optimization": {
        "select#": 1,
        "steps": [
          {
          	# 判断条件优化
            "condition_processing": {
      				# 条件类型是where条件类型,也可能是having条件类型
              "condition": "WHERE",
       				# original_condition是原始条件类型
              "original_condition": "(`dicom_image_info`.`patient_id` = '3583925')",
              "steps": [
                {
      						# 第一步优化: 等值优化
                  "transformation": "equality_propagation",
      						# 优化之后的输出结果
                  "resulting_condition": "multiple equal('3583925', `dicom_image_info`.`patient_id`)"
                },
                {
                  # 第二步优化: 常量比较优化
                  "transformation": "constant_propagation",
                  # 优化之后的输出结果
                  "resulting_condition": "multiple equal('3583925', `dicom_image_info`.`patient_id`)"
                },
                {
                  # 第三步优化: 条件移除优化,去挑一些不必要的条件
                  "transformation": "trivial_condition_removal",
                  "resulting_condition": "multiple equal('3583925', `dicom_image_info`.`patient_id`)"
                }
              ]
            }
          },
          {
            "substitute_generated_columns": {
            }
          },
          {
            # 表依赖分析
            "table_dependencies": [
              {
            		# 表名
                "table": "`dicom_image_info`",
            		# 判断行记录是否有可能为空, 在left join 连接的被驱动表上会显示为true
                "row_may_be_null": false,
		            # 当前的记录位: 0
                "map_bit": 0,
	            	# 依赖的前置记录位
                "depends_on_map_bits": [
                ]
              }
            ]
          },
          {
            # 使用的优化的索引
            "ref_optimizer_key_uses": [
              {
                "table": "`dicom_image_info`",
                "field": "patient_id",
                "equals": "'3583925'",
                "null_rejecting": true
              }
            ]
          },
          {
            # 扫描表的行记录的一个性能评估
            "rows_estimation": [
              {
                "table": "`dicom_image_info`",
		            # 数据扫描分析
                "range_analysis": {
                  "table_scan": {
				            # 扫描的记录数
                    "rows": 6474,
				            # cost的成本值
                    "cost": 673.75
                  },
									# 表的索引分析
                  "potential_range_indexes": [
                    {
                      # 主键索引
                      "index": "PRIMARY",
                      "usable": false,
                      "cause": "not_applicable"
                    },
                    {
                      # 普通索引
                      "index": "patient_id",
                      "usable": true,
                       # 索引的部分
                      "key_parts": [
                        "patient_id",
                        "study_instance_uid",
                        "series_instance_uid",
                        "sop_instance_uid"
                      ]
                    }
                  ],
                  "setup_range_conditions": [
                  ],
									# 分组索引范围
                  "group_index_range": {
                    "chosen": false,
                    # 没有分组和去重操作
                    "cause": "not_group_by_or_distinct"
                  },
                  "skip_scan_range": {
                    "potential_skip_scan_indexes": [
                      {
                        "index": "patient_id",
                        "usable": false,
                        "cause": "query_references_nonkey_column"
                      }
                    ]
                  },
									# 分析索引的使用成本
                  "analyzing_range_alternatives": {
                    # range 扫描分析
                    "range_scan_alternatives": [
                      {
		                    # 索引名称
                        "index": "patient_id",
                    	  # 扫描范围
                        "ranges": [
                          "3583925 <= patient_id <= 3583925"
                        ],
												# 选择一种计算更准确的方式
                        "index_dives_for_eq_ranges": true,
												# rowId是否有序
                        "rowid_ordered": false,
												# 是否使用了mrr优化
                        "using_mrr": false,
												# 是否只查询索引数据 
                        "index_only": false,
												# 返回的行数
                        "rows": 2388,
												# 预估的成本
                        "cost": 836.06,
												# 是否选择
                        "chosen": false,
                        "cause": "cost"
                      }
                    ],
										# 分析是否使用了索引合并
                    "analyzing_roworder_intersect": {
                      "usable": false,
                      "cause": "too_few_roworder_scans"
                    }
                  }
                }
              }
            ]
          },
          {
            # 最后的索引选择方案
            "considered_execution_plans": [
              {
            		# 前置的依赖执行计划
                "plan_prefix": [
                ],
                "table": "`dicom_image_info`",
								# 最优的访问路径
                "best_access_path": {
                  "considered_access_paths": [
                    {
                      # 使用索引的方式
                      "access_type": "ref",
                      "index": "patient_id",
                      "rows": 2388,
                      "cost": 311.55,
                      "chosen": true
                    },
                    {
                      # 扫描表的方式
                      "rows_to_scan": 6474,
                      "filtering_effect": [
                      ],
                      "final_filtering_effect": 0.36886,
                      "access_type": "scan",
                      "resulting_rows": 2388,
                      "cost": 671.65,
                      "chosen": false
                    }
                  ]
                },
								# 最终选择的方案
                "condition_filtering_pct": 100,
                "rows_for_plan": 2388,
                "cost_for_plan": 311.55,
                "chosen": true
              }
            ]
          },
          {
            # 优化原来的where条件
            "attaching_conditions_to_tables": {
              "original_condition": "(`dicom_image_info`.`patient_id` = '3583925')",
              "attached_conditions_computation": [
              ],
              "attached_conditions_summary": [
                {
                  "table": "`dicom_image_info`",
                  "attached": "(`dicom_image_info`.`patient_id` = '3583925')"
                }
              ]
            }
          },
          {
            "finalizing_table_conditions": [
              {
                "table": "`dicom_image_info`",
                "original_table_condition": "(`dicom_image_info`.`patient_id` = '3583925')",
                "final_table_condition   ": null
              }
            ]
          },
          {
            # 改善执行计划
            "refine_plan": [
              {
                "table": "`dicom_image_info`"
              }
            ]
          }
        ]
      }
    },
    {
      "join_explain": {
        "select#": 1,
        "steps": [
        ]
      }
    }
  ]
}