慢日志问题：使用临时表的存储过程调用未被记录

我在MySQL 5.7.30中已开启慢日志，设置了2秒的耗时阈值，但发现部分存储过程（SP）调用明明耗时远超阈值，却未被慢日志记录。排查后确认涉及临时表的存储过程存在该问题——比如下面这条耗时30秒的语句所属的存储过程就完全没出现在慢日志里：

INSERT INTO temp_media(pacs_media_id, pacs_users_id)
    SELECT p.id, pu.id
    FROM media p
    INNER JOIN users pu ON pu.token_client_id=p.token_client_id
                AND pu.token_location_id=p.token_location_id
                AND pu.user_ref_id=p.entity_ref_id
                -- AND pu.token_client_id IN (812,525, 141,44,69) -- 1104
    INNER JOIN clients pc ON pc.token_client_id=pu.token_client_id
                AND pc.is_active=1
                -- AND pc.process_id=p_process_id
                AND FIND_IN_SET(pu.user_type, pc.user_types)
                AND pu.user_type IS NOT NULL
    WHERE   p.entity_name_id=1 -- 1: users
        AND p.is_processed=0
        -- AND p.id % p_thread_total=p_thread_no
    LIMIT 100

问题根源 #

MySQL 5.7默认不会记录存储过程内部的语句执行情况，且涉及临时表的操作时，临时表的创建、写入等开销可能未被纳入慢日志的整体计时逻辑，导致即使存储过程实际耗时很长，也不会触发慢日志记录。

解决措施 #

1. 开启存储过程内部语句的慢日志记录 #

修改MySQL配置文件（my.cnf/my.ini），添加或调整以下参数：

slow_query_log = 1
long_query_time = 2
log_slow_admin_statements = 1
log_slow_slave_statements = 1
# 核心参数：开启存储过程内部语句的慢日志记录
log_slow_sp_statements = 1

修改完成后重启MySQL服务，即可让存储过程内部的慢语句被记录。

2. 排查临时表的实际开销 #

可以通过PROFILE工具分析存储过程的执行细节，确认临时表操作的耗时：

SET profiling = 1;
CALL 你的存储过程名();
SHOW PROFILE FOR QUERY 1;

通过结果可以看到每个步骤的耗时，定位临时表相关操作的瓶颈。

3. 优化目标语句性能 #

针对示例中的语句，可通过添加索引降低耗时，从根源上减少慢语句出现：

• 给media表添加联合索引：ALTER TABLE media ADD INDEX idx_entity_processed (entity_name_id, is_processed);
• 给users表添加联合索引：ALTER TABLE users ADD INDEX idx_token_ref (token_client_id, token_location_id, user_ref_id);
• 针对FIND_IN_SET的低效问题，建议将clients.user_types的逗号分隔格式重构为关联表；若暂时无法重构，可给clients表添加索引：ALTER TABLE clients ADD INDEX idx_client_active (token_client_id, is_active);

内容的提问来源于stack exchange，提问作者Irfi