MySQL Bugs: #64761: NOW() returns inconsitent times when used with nested stored procedures

Bug #64761	NOW() returns inconsitent times when used with nested stored procedures
Submitted:	26 Mar 2012 10:49	Modified:	7 Jun 2012 15:42
Reporter:	Patrick Mulvany (OCA)	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: Stored Routines	Severity:	S3 (Non-critical)
Version:	5.1.61, 5.5.21	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
NOW() returns different results within a stored procedure depending if nested stored procedures have been called. Possibly returning invocation time SYSDATE() regardless of when executed.

http://dev.mysql.com/doc/refman/5.5/en/date-and-time-functions.html#function_now

NOW() returns a constant time that indicates the time at which the statement began to execute. (Within a stored function or trigger, NOW() returns the time at which the function or triggering statement began to execute.) This differs from the behavior for SYSDATE(), which returns the exact time at which it executes. 

Only work around is to call NOW() once at start of outer most stored procedure and pass value into/around from then on.

How to repeat:
CREATE TABLE t1 (id INT NOT NULL AUTO_INCREMENT, dt_now DATETIME,dt_sysdate DATETIME,dt_outer DATETIME,
  PRIMARY KEY (id));

DELIMITER $$

CREATE PROCEDURE inner1 (p_date DATETIME)
  BEGIN
    SELECT SLEEP(5);
 	  INSERT INTO t1 (dt_now,dt_sysdate,dt_outer) VALUES (now(), sysdate(),p_date);
    SELECT SLEEP(5);
  END
;

$$

CREATE PROCEDURE outer1 ()
  BEGIN
 	  INSERT INTO t1 (dt_now,dt_sysdate,dt_outer) VALUES (NULL, sysdate(),NOW());
    SELECT SLEEP(10);
 	  INSERT INTO t1 (dt_now,dt_sysdate,dt_outer) VALUES (NULL, sysdate(),NOW());
    CALL inner1(NOW());
 	  INSERT INTO t1 (dt_now,dt_sysdate,dt_outer) VALUES (NULL, sysdate(),NOW());
    SELECT SLEEP(10);
 	  INSERT INTO t1 (dt_now,dt_sysdate,dt_outer) VALUES (NULL, sysdate(),NOW());
    CALL inner1(NOW());
 	  INSERT INTO t1 (dt_now,dt_sysdate,dt_outer) VALUES (NULL, sysdate(),NOW());
    SELECT SLEEP(10);
 	  INSERT INTO t1 (dt_now,dt_sysdate,dt_outer) VALUES (NULL, sysdate(),NOW());
    CALL inner1(NOW());
 	  INSERT INTO t1 (dt_now,dt_sysdate,dt_outer) VALUES (NULL, sysdate(),NOW());
    END
;
    
$$

DELIMITER ;

call outer1();

SELECT * FROM t1;

Example output as CSV from test script

Attachment: test.csv (application/vnd.ms-excel, text), 603 bytes.

Retested on Windows 5.5.21 and Linux 5.5.21 with consistent results

Thank you for the problem report. Verified on 5.1.x also (so this is not a recent regression):

...
mysql> call outer1();
+-----------+
| SLEEP(10) |
+-----------+
|         0 |
+-----------+
1 row in set (10.00 sec)

+----------+
| SLEEP(5) |
+----------+
|        0 |
+----------+
1 row in set (15.00 sec)

+----------+
| SLEEP(5) |
+----------+
|        0 |
+----------+
1 row in set (20.00 sec)

+-----------+
| SLEEP(10) |
+-----------+
|         0 |
+-----------+
1 row in set (30.00 sec)

+----------+
| SLEEP(5) |
+----------+
|        0 |
+----------+
1 row in set (35.00 sec)

+----------+
| SLEEP(5) |
+----------+
|        0 |
+----------+
1 row in set (40.00 sec)

+-----------+
| SLEEP(10) |
+-----------+
|         0 |
+-----------+
1 row in set (50.00 sec)

+----------+
| SLEEP(5) |
+----------+
|        0 |
+----------+
1 row in set (55.00 sec)

+----------+
| SLEEP(5) |
+----------+
|        0 |
+----------+
1 row in set (1 min 0.00 sec)

Query OK, 1 row affected (1 min 0.00 sec)

mysql> SELECT * FROM t1;
+----+---------------------+---------------------+---------------------+
| id | dt_now              | dt_sysdate          | dt_outer            |
+----+---------------------+---------------------+---------------------+
| 23 | NULL                | 2012-03-26 20:02:13 | 2012-03-26 20:02:13 |
| 24 | NULL                | 2012-03-26 20:02:23 | 2012-03-26 20:02:23 |
| 25 | 2012-03-26 20:02:28 | 2012-03-26 20:02:28 | 2012-03-26 20:02:23 |
| 26 | NULL                | 2012-03-26 20:02:33 | 2012-03-26 20:02:33 |
| 27 | NULL                | 2012-03-26 20:02:43 | 2012-03-26 20:02:43 |
| 28 | 2012-03-26 20:02:48 | 2012-03-26 20:02:48 | 2012-03-26 20:02:43 |
| 29 | NULL                | 2012-03-26 20:02:53 | 2012-03-26 20:02:53 |
| 30 | NULL                | 2012-03-26 20:03:03 | 2012-03-26 20:03:03 |
| 31 | 2012-03-26 20:03:08 | 2012-03-26 20:03:08 | 2012-03-26 20:03:03 |
| 32 | NULL                | 2012-03-26 20:03:13 | 2012-03-26 20:03:13 |
+----+---------------------+---------------------+---------------------+
10 rows in set (0.00 sec)

Might be related to 'Stored procedures are not ACID compliant'
http://bugs.mysql.com/bug.php?id=64776

NOW() only works with a single command not within a transaction so this is a general issue with NOW().

mysql> set autocommit=0;
Query OK, 0 rows affected (0.00 sec)

mysql> select now(),sleep(3),now();
+---------------------+----------+---------------------+
| now()               | sleep(3) | now()               |
+---------------------+----------+---------------------+
| 2012-03-28 10:03:11 |        0 | 2012-03-28 10:03:11 |
+---------------------+----------+---------------------+
1 row in set (3.00 sec)

mysql> select sysdate(),sleep(3),sysdate();
+---------------------+----------+---------------------+
| sysdate()           | sleep(3) | sysdate()           |
+---------------------+----------+---------------------+
| 2012-03-28 10:03:29 |        0 | 2012-03-28 10:03:32 |
+---------------------+----------+---------------------+
1 row in set (3.00 sec)

mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2012-03-28 10:03:53 |
+---------------------+
1 row in set (0.00 sec)

mysql>

From the documentation:

"(Within a stored function or trigger, NOW() returns the time at which the function or triggering statement began to execute.)"

It appears that you are using a stored procedure, not a stored function, correct?