Details
-
Bug
-
Status: Open (View Workflow)
-
Major
-
Resolution: Unresolved
-
11.6.2
-
None
-
Ubuntu 22.04
Description
When I tried to use a trigger to log the modification of a write statement, I found an unexpected behavior.
As in the example below, I defined a trigger of type AFTER. In my opinion, it should be executed after the write statement is executed. However, when this statement is blocked in the transaction, this statement is logged earlier than the actual execution time of this statement. Because, the statement (update) that was executed before it , recorded a later time than this statement.
Is this the reason for the function ( CURRENT_TIMESTAMP(6) ) that gets the time? What should I do if I want to record the actual execution time and modifications?
--- init
|
CREATE TABLE tNqrncdI (ID INT, VAL INT, c0 BOOLEAN , c1 DOUBLE , c2 BOOLEAN); |
CREATE TABLE tNqrncdI_log (ID INT, VAL INT, c0 BOOLEAN , c1 DOUBLE , c2 BOOLEAN); |
ALTER TABLE tNqrncdI_log |
ADD COLUMN operation_type VARCHAR(6), |
ADD COLUMN session_id VARCHAR(50), |
ADD COLUMN time TIMESTAMP(6) DEFAULT CURRENT_TIMESTAMP(6); |
|
|
INSERT INTO tNqrncdI (ID, VAL, c0, c1, c2) VALUES (3771, 4229, 1, -20.0, 0); |
INSERT INTO tNqrncdI (ID, VAL, c0, c1, c2) VALUES (3772, 4230, 1, -20.0, 0); |
SET GLOBAL lock_wait_timeout = 10; |
SET GLOBAL innodb_lock_wait_timeout = 10; |
|
|
DELIMITER $$
|
CREATE TRIGGER tri_update_tNqrncdI |
AFTER UPDATE ON tNqrncdI |
FOR EACH ROW |
BEGIN |
INSERT INTO tNqrncdI_log (operation_type, session_id, id, val, c0, c1, c2) |
VALUES ('UPDATE', CONNECTION_ID(), NEW.ID, NEW.VAL, OLD.c0, OLD.c1, OLD.c2); |
END; |
CREATE TRIGGER tri_delete_tNqrncdI |
AFTER DELETE ON tNqrncdI |
FOR EACH ROW |
BEGIN |
INSERT INTO tNqrncdI_log (operation_type, session_id, id, val, c0, c1, c2) |
VALUES ('DELETE', CONNECTION_ID(), OLD.ID, -1, OLD.c0, OLD.c1, OLD.c2); |
END; |
$$
|
DELIMITER ;
|
--- session 1
|
BEGIN; |
UPDATE tNqrncdI SET VAL = 4231 WHERE ( tNqrncdI.c2 = 0 ); |
--- session 2
|
BEGIN; |
DELETE tNqrncdI FROM tNqrncdI WHERE ( tNqrncdI.c2 = 0 ); |
--- session 1
|
UPDATE tNqrncdI SET VAL = 4232, tNqrncdI.c2 = 0; |
--- session 1
|
COMMIT; |
--- session 2
|
COMMIT; |
--- session 1
|
SELECT * from tNqrncdI_log; |
+------+------+------+------+------+----------------+------------+----------------------------+ |
| ID | VAL | c0 | c1 | c2 | operation_type | session_id | time | |
+------+------+------+------+------+----------------+------------+----------------------------+ |
| 3771 | 4231 | 1 | -20 | 0 | UPDATE | 5321 | 2025-02-19 15:03:06.311373 | |
| 3772 | 4231 | 1 | -20 | 0 | UPDATE | 5321 | 2025-02-19 15:03:06.311373 | |
| 3771 | 4232 | 1 | -20 | 0 | UPDATE | 5321 | 2025-02-19 15:03:16.789257 | |
| 3772 | 4232 | 1 | -20 | 0 | UPDATE | 5321 | 2025-02-19 15:03:16.789257 | |
*| 3771 | -1 | 1 | -20 | 0 | DELETE | 5322 | 2025-02-19 15:03:13.481262 | |
| 3772 | -1 | 1 | -20 | 0 | DELETE | 5322 | 2025-02-19 15:03:13.481262 |* |
+------+------+------+------+------+----------------+------------+----------------------------+ |
6 rows in set (0.00 sec) |
Yes, this is the documented behavior of both MariaDB and MySQL, e.g.
https://dev.mysql.com/doc/refman/8.4/en/date-and-time-functions.html#function_now
In MariaDB KB this note, while also present, is hidden in a description of a different function.
As for what to do to circumvent it, I recommend searching for community discussions and solutions proposed there, there have been many.
I'm keeping this ticket as a documentation issue, as I think the KB page about NOW() should have this information, it is a common question.