存储过程嵌套调用及异常处理：时间戳与日志执行问题求助

原存储过程代码 #

日志存储过程 #

CREATE PROCEDURE logging(name TEXT, message TEXT) 
BEGIN  
    INSERT INTO log_table
    SELECT NOW(), name,  message;
END

调用日志的业务存储过程 #

CREATE PROCEDURE my_proc()
BEGIN
   CALL logging('my_proc', 'start');
   
   insert into myTable
   select * from another_table;
   
   CALL logging('my_proc', 'end');
   EXCEPTION WHEN OTHERS THEN
     CALL logging('my_proc',SQLSTATE || ' - ' ||SQLERRM );
END 

遇到的问题 #

问题一：日志时间戳无差异 #

无异常执行时，start和end日志的时间戳完全相同，哪怕中间的INSERT操作耗时很久：

• "2022-11-16 15:11:01.322317" "my_proc" "start"
• "2022-11-16 15:11:01.322317" "my_proc" "end"
  就算改成通过参数传入时间戳，问题依然存在。

问题二：异常时起始日志丢失 #

一旦发生异常，只有异常块内的日志能写入，之前的start日志会被回滚消失，只能看到错误日志，无法追踪流程起始节点。

解决方案 #

解决时间戳不准确的问题 #

核心原因是事务一致性机制：同一条事务中，NOW()返回的是事务启动时间，而非语句执行的实时时间。要获取真实执行时间，需改用数据库提供的实时时间函数：

分数据库修改方案

• PostgreSQL：使用CURRENT_TIMESTAMP(6)（保留6位精度到毫秒级），它会返回函数执行时的真实时间：

  CREATE PROCEDURE logging(name TEXT, message TEXT) 
  BEGIN  
      INSERT INTO log_table
      SELECT CURRENT_TIMESTAMP(6), name, message;
  END
  

• MySQL：替换为SYSDATE(6)，因为NOW()取事务启动时间，SYSDATE()才是实时执行时间：

  CREATE PROCEDURE logging(name TEXT, message TEXT) 
  BEGIN  
      INSERT INTO log_table
      SELECT SYSDATE(6), name, message;
  END
  

如果要通过参数传递时间戳，需在调用logging前提前生成实时时间，而非依赖事务启动时间：

CREATE PROCEDURE my_proc()
BEGIN
   DECLARE start_time TIMESTAMP(6);
   SET start_time = CURRENT_TIMESTAMP(6); -- 提前获取实时时间
   CALL logging('my_proc', 'start', start_time); -- 给日志存储过程新增时间参数
   
   insert into myTable
   select * from another_table;
   
   CALL logging('my_proc', 'end', CURRENT_TIMESTAMP(6));
   EXCEPTION WHEN OTHERS THEN
     CALL logging('my_proc',SQLSTATE || ' - ' ||SQLERRM, CURRENT_TIMESTAMP(6));
END 

对应的日志存储过程需修改为接受时间参数：

CREATE PROCEDURE logging(name TEXT, message TEXT, log_time TIMESTAMP(6)) 
BEGIN  
    INSERT INTO log_table
    SELECT log_time, name, message;
END

解决异常时起始日志丢失的问题 #

问题根源是事务回滚：存储过程触发异常时，整个事务会被回滚，包括异常前写入的start日志。要避免日志被回滚，需让日志操作在独立事务中执行：

PostgreSQL 实现方式

在日志存储过程中显式提交，或临时开启自动提交：

CREATE PROCEDURE logging(name TEXT, message TEXT) 
BEGIN  
    INSERT INTO log_table
    SELECT CURRENT_TIMESTAMP(6), name, message;
    COMMIT; -- 单独提交日志，不随外层事务回滚
END

或通过配置临时切换自动提交：

CREATE PROCEDURE logging(name TEXT, message TEXT) 
BEGIN  
    PERFORM pg_catalog.set_config('autocommit', 'on', true);
    INSERT INTO log_table
    SELECT CURRENT_TIMESTAMP(6), name, message;
    PERFORM pg_catalog.set_config('autocommit', 'off', true);
END

MySQL 实现方式

使用AUTONOMOUS_TRANSACTION特性（MySQL 8.0+支持），或手动切换自动提交：

DELIMITER //
CREATE PROCEDURE logging(name TEXT, message TEXT) 
BEGIN  
    DECLARE EXIT HANDLER FOR SQLEXCEPTION ROLLBACK;
    START TRANSACTION;
    INSERT INTO log_table
    SELECT SYSDATE(6), name, message;
    COMMIT;
END //
DELIMITER ;

或在业务存储过程中临时切换自动提交状态：

DELIMITER //
CREATE PROCEDURE my_proc()
BEGIN
   SET @old_autocommit = @@autocommit;
   SET @@autocommit = 1;
   CALL logging('my_proc', 'start');
   SET @@autocommit = @old_autocommit;
   
   insert into myTable
   select * from another_table;
   
   SET @@autocommit = 1;
   CALL logging('my_proc', 'end');
   SET @@autocommit = @old_autocommit;
   EXCEPTION WHEN OTHERS THEN
     SET @@autocommit = 1;
     CALL logging('my_proc',SQLSTATE || ' - ' ||SQLERRM );
     SET @@autocommit = @old_autocommit;
END //
DELIMITER ;

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