如何在 mySQL 存储过程中跟踪查询开始时间和结束时间

Question

我有一个存储过程，每天在 cron 作业上执行一次。存储过程由触发的多个 SQL 查询组成，以便根据我们从另一个来源获得的每日更新完成数据协调。

我的目标是捕获存储过程中执行的每个 SQL 查询的 START_TIME 和 END_TIME，以便我可以分析和优化该过程。

CREATE TABLE `SP_LOG` (
    `ID` bigint(20) NOT NULL AUTO_INCREMENT,
    `SP_NAME` varchar(255) NOT NULL,
    `IN_PARAMS` varchar(4000) DEFAULT NULL,
    `START_TIME` timestamp(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6) ON UPDATE CURRENT_TIMESTAMP(6),
    `END_TIME` timestamp(6) NULL DEFAULT NULL,
    PRIMARY KEY (`ID`),
    KEY `IDX.SP_LOG.SP_NAME` (`SP_NAME`)
);

CREATE TABLE `SP_LOG_DETAIL` (
    `ID` bigint(20) NOT NULL AUTO_INCREMENT,
    `SP_ID` bigint(20) NOT NULL,
    `MESSAGE` varchar(255) NOT NULL,
    `START_TIME` timestamp(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6) ON UPDATE CURRENT_TIMESTAMP(6),
    `END_TIME` timestamp(6) NULL DEFAULT NULL,
    PRIMARY KEY (`ID`),
    KEY `IDX.SP_LOG_DETAIL.SP_ID` (`SP_ID`),
    CONSTRAINT `FK.SP_LOG_DETAIL.SP_ID` FOREIGN KEY (`SP_ID`) 
    REFERENCES `SP_LOG` (`ID`) ON DELETE CASCADE ON UPDATE CASCADE
);

DROP PROCEDURE IF EXISTS `SP_PROCESS_USERS`;
DELIMITER //
CREATE PROCEDURE `SP_PROCESS_USERS`(IN spLocation VARCHAR(60))
BEGIN    

    /*
     * -- Handle Exception --
     */

    DECLARE spLogId BIGINT(20);
    DECLARE spLogDetailId BIGINT(20);
    DECLARE EXIT HANDLER FOR SQLEXCEPTION
    BEGIN
        GET DIAGNOSTICS CONDITION 1 @p1 = RETURNED_SQLSTATE, @p2 = MESSAGE_TEXT;

        INSERT INTO SP_LOG(SP_NAME, IN_PARAMS, END_TIME) VALUES ('SP_PROCESS_USERS', spMarket, NOW(6));
        SELECT LAST_INSERT_ID() INTO spLogId;

        INSERT INTO SP_LOG_DETAIL(SP_ID, MESSAGE, END_TIME) VALUES (spLogId, CONCAT('SQLEXCEPTION==>', @p1, ':', @p2), NOW(6));
    END;

    INSERT INTO SP_LOG(SP_NAME, IN_PARAMS) VALUES ('SP_PROCESS_USERS', spLocation);
    SELECT LAST_INSERT_ID() INTO spLogId;

    /*
     * -- Process Users Part 1 --
     */

    INSERT INTO SP_LOG_DETAIL(SP_ID, MESSAGE) VALUES (spLogId, 'Process Users #1');
    SELECT LAST_INSERT_ID() INTO spLogDetailId;

    ... Logic ...

    UPDATE SP_LOG_DETAIL SET END_TIME = NOW(6) WHERE ID = spLogDetailId;


    ... Part 2, 3, ... n

    UPDATE SQ_5G_SP_LOG SET END_TIME = NOW(6) WHERE ID = spLogId;

END //

当我插入日志表时，CURRENT_TIMESTAMP 由表自动生成并获取准确的时间。

当我在进程使用 NOW(6) 完成后尝试使用 CURRENT_TIMESTAMP 更新现有记录时，它总是找到与 START_TIME 捕获的相同的精确值；低至毫秒。

如何找到准确的时间？

Answer 1

感谢这已经超过 6 年了，但我会说出原因，以便任何可能遇到此问题的人受益。

开始日期始终与结束日期匹配的原因是由于创建表语句中的这一行：

START_TIME

时间戳（6）不为空默认CURRENT_TIMESTAMP（6）更新CURRENT_TIMESTAMP（6）

ON UPDATE CURRENT_TIMESTAMP(6) 将更新“Start_Time”列，以匹配在更新语句中更新该行时的结束时间，以获取此行底部附近的结束时间：

更新 SQ_5G_SP_LOG SET END_TIME = NOW(6) WHERE ID = spLogId;

如果删除“ON UPDATE CURRENT_TIMESTAMP(6)”，这将确保运行更新语句时“Start_Time”保留在首次记录的时间点。

有关表结构中时间戳的更多信息： https://dev.mysql.com/doc/refman/8.0/en/timestamp-initialization.html

希望这有帮助:)