How to Track Query Start Time and End Time within a mySQL Stored Procedure

Question

I have a Stored Procedure that is executed once a day on a cron job. The Stored Procedure consists of multiple SQL queries firing in order to complete the data reconciliation based on a daily update we get from another source.

My goal is to capture the START_TIME and END_TIME of every SQL query that is executed within the Stored Procedure so that I can analyze and optimize the process.

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 //

When I INSERT INTO the log tables the CURRENT_TIMESTAMP is generated by the table automatically and getting the accurate time.

When I try to update the existing record with the CURRENT_TIMESTAMP after the process finishes using NOW(6) it's always finding the same exact value that the START_TIME has captured; down to the milliseconds.

How can I find the accurate time?

Answer 1

appreciate this is over 6 years old but I'll put the reason for the benefit of anyone who might come across this.

The reason the start date is always matching the end date it due to this line within the create table statement:

START_TIME timestamp(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6) ON UPDATE CURRENT_TIMESTAMP(6)

ON UPDATE CURRENT_TIMESTAMP(6) will update the 'Start_Time' column to match the end time when that row is updated in your update statement for the end time near the bottom on this line:

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

If you remove 'ON UPDATE CURRENT_TIMESTAMP(6)' this will ensure the 'Start_Time' persists at the point of first being logged when the update statement is ran.

Further info on timestamps within table structure: https://dev.mysql.com/doc/refman/8.0/en/timestamp-initialization.html

Hope this helps :)