[MDEV-13727] top-level query timestamp reset at stored func/trigger internal statements Created: 2017-09-04  Updated: 2018-05-25  Resolved: 2018-05-25

Status: Closed
Project: MariaDB Server
Component/s: Server, Tests
Affects Version/s: 10.3
Fix Version/s: 10.3.8

Type: Bug Priority: Major
Reporter: Alice Sherepa Assignee: Michael Widenius
Resolution: Fixed Votes: 0
Labels: None


 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/9482/steps/test_3/logs/stdio

rpl.rpl_concurrency_error 'innodb,stmt'  w2 [ fail ]
        Test ended at 2017-09-05 12:47:50
 
CURRENT_TEST: rpl.rpl_concurrency_error
/mnt/buildbot/build/mariadb-10.3.2/client/mysqltest: Error on delete of '/mnt/buildbot/build/mariadb-10.3.2/mysql-test/var/2/tmp/_var_file_479b03f5-921f-11e7-81e7-525400123456.inc' (Errcode: 2 "No such file or directory")
/mnt/buildbot/build/mariadb-10.3.2/client/mysqltest: Error on delete of '/mnt/buildbot/build/mariadb-10.3.2/mysql-test/var/2/tmp/_var_file_47ae05a4-921f-11e7-81e7-525400123456.inc' (Errcode: 2 "No such file or directory")
mysqltest: In included file "./include/rpl_diff.inc": 
included from /mnt/buildbot/build/mariadb-10.3.2/mysql-test/suite/rpl/t/rpl_concurrency_error.test at line 134:
At line 113: command "diff_files" failed with error: 1  my_errno: 175  errno: -1
 
The result from queries just before the failure was:
< snip >
master-bin.000001	#	Xid	#	#	COMMIT /* XID */
master-bin.000001	#	Gtid	#	#	BEGIN GTID #-#-#
master-bin.000001	#	Query	#	#	use `test`; UPDATE IGNORE t SET f = 'dark blue 1' WHERE f = 'red'
master-bin.000001	#	Query	#	#	use `test`; INSERT INTO t VALUES (6 + (1 * 10),"brown")
master-bin.000001	#	Xid	#	#	COMMIT /* XID */
connection master;
connection slave;
include/rpl_diff.inc
include/rpl_diff.inc
--- /mnt/buildbot/build/mariadb-10.3.2/mysql-test/var/2/tmp/_rpl_diff_server-2.tmp	2017-09-05 12:47:50.274257071 +0300
+++ /mnt/buildbot/build/mariadb-10.3.2/mysql-test/var/2/tmp/_rpl_diff_server-1.tmp	2017-09-05 12:47:50.250257073 +0300
@@ -5,7 +5,7 @@
 2017-09-05 12:47:42	updated t: red -> dark blu
 2017-09-05 12:47:42	updated t: yellow 2 -> gray 2
 2017-09-05 12:47:44	brown
-2017-09-05 12:47:44	updated t: gray 2 -> yellow 1
+2017-09-05 12:47:45	updated t: gray 2 -> yellow 1
 2017-09-05 12:47:45	updated t: red -> magenta
 2017-09-05 12:47:47	brown
 2017-09-05 12:47:47	updated t: red -> dark blu

 
2017-09-05 12:47:39 16 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement accesses nontransactional table as well as transactional or temporary table, and writes to any of them Statement: UPDATE t SET f = 'yellow 2' WHERE i = 3
2017-09-05 12:47:41 17 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement accesses nontransactional table as well as transactional or temporary table, and writes to any of them Statement: UPDATE IGNORE t SET f = 'magenta 2' WHERE f = 'red'
2017-09-05 12:47:41 17 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. UPDATE IGNORE is unsafe because the order in which rows are updated determines which (if any) rows are ignored. This order cannot be predicted and may differ on master and the slave Statement: UPDATE IGNORE t SET f = 'magenta 2' WHERE f = 'red'
2017-09-05 12:47:42 16 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement accesses nontransactional table as well as transactional or temporary table, and writes to any of them Statement: UPDATE t SET f = 'gray 2' WHERE i = 3
2017-09-05 12:47:44 17 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement accesses nontransactional table as well as transactional or temporary table, and writes to any of them Statement: UPDATE IGNORE t SET f = 'dark blue 2' WHERE f = 'red'
2017-09-05 12:47:44 17 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. UPDATE IGNORE is unsafe because the order in which rows are updated determines which (if any) rows are ignored. This order cannot be predicted and may differ on master and the slave Statement: UPDATE IGNORE t SET f = 'dark blue 2' WHERE f = 'red'
2017-09-05 12:47:45 16 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement accesses nontransactional table as well as transactional or temporary table, and writes to any of them Statement: UPDATE t SET f = 'yellow 1' WHERE i = 3
2017-09-05 12:47:47 17 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement accesses nontransactional table as well as transactional or temporary table, and writes to any of them Statement: UPDATE IGNORE t SET f = 'magenta 1' WHERE f = 'red'
2017-09-05 12:47:47 17 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. UPDATE IGNORE is unsafe because the order in which rows are updated determines which (if any) rows are ignored. This order cannot be predicted and may differ on master and the slave Statement: UPDATE IGNORE t SET f = 'magenta 1' WHERE f = 'red'
2017-09-05 12:47:47 16 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement accesses nontransactional table as well as transactional or temporary table, and writes to any of them Statement: UPDATE t SET f = 'gray 1' WHERE i = 3
2017-09-05 12:47:49 17 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement accesses nontransactional table as well as transactional or temporary table, and writes to any of them Statement: UPDATE IGNORE t SET f = 'dark blue 1' WHERE f = 'red'
2017-09-05 12:47:49 17 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. UPDATE IGNORE is unsafe because the order in which rows are updated determines which (if any) rows are ignored. This order cannot be predicted and may differ on master and the slave Statement: UPDATE IGNORE t SET f = 'dark blue 1' WHERE f = 'red'
2017-09-05 12:47:41 13 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement accesses nontransactional table as well as transactional or temporary table, and writes to any of them Statement: UPDATE t SET f = 'yellow 2' WHERE i = 3
2017-09-05 12:47:41 13 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement accesses nontransactional table as well as transactional or temporary table, and writes to any of them Statement: UPDATE IGNORE t SET f = 'magenta 2' WHERE f = 'red'
2017-09-05 12:47:41 13 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. UPDATE IGNORE is unsafe because the order in which rows are updated determines which (if any) rows are ignored. This order cannot be predicted and may differ on master and the slave Statement: UPDATE IGNORE t SET f = 'magenta 2' WHERE f = 'red'
2017-09-05 12:47:44 13 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement accesses nontransactional table as well as transactional or temporary table, and writes to any of them Statement: UPDATE t SET f = 'gray 2' WHERE i = 3
2017-09-05 12:47:44 13 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement accesses nontransactional table as well as transactional or temporary table, and writes to any of them Statement: UPDATE IGNORE t SET f = 'dark blue 2' WHERE f = 'red'
2017-09-05 12:47:44 13 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. UPDATE IGNORE is unsafe because the order in which rows are updated determines which (if any) rows are ignored. This order cannot be predicted and may differ on master and the slave Statement: UPDATE IGNORE t SET f = 'dark blue 2' WHERE f = 'red'
2017-09-05 12:47:47 13 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement accesses nontransactional table as well as transactional or temporary table, and writes to any of them Statement: UPDATE t SET f = 'yellow 1' WHERE i = 3
2017-09-05 12:47:47 13 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement accesses nontransactional table as well as transactional or temporary table, and writes to any of them Statement: UPDATE IGNORE t SET f = 'magenta 1' WHERE f = 'red'
2017-09-05 12:47:47 13 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. UPDATE IGNORE is unsafe because the order in which rows are updated determines which (if any) rows are ignored. This order cannot be predicted and may differ on master and the slave Statement: UPDATE IGNORE t SET f = 'magenta 1' WHERE f = 'red'
2017-09-05 12:47:49 13 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement accesses nontransactional table as well as transactional or temporary table, and writes to any of them Statement: UPDATE t SET f = 'gray 1' WHERE i = 3
2017-09-05 12:47:49 13 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement accesses nontransactional table as well as transactional or temporary table, and writes to any of them Statement: UPDATE IGNORE t SET f = 'dark blue 1' WHERE f = 'red'
2017-09-05 12:47:49 13 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. UPDATE IGNORE is unsafe because the order in which rows are updated determines which (if any) rows are ignored. This order cannot be predicted and may differ on master and the slave Statement: UPDATE IGNORE t SET f = 'dark blue 1' WHERE f = 'red'



 Comments   
Comment by Alice Sherepa [ 2018-04-06 ]

recent occurance http://buildbot.askmonty.org/buildbot/builders/mac-1012-bintar/builds/3177/steps/test/logs/stdio

rpl.rpl_concurrency_error 'innodb,stmt'  [ fail ]
        Test ended at 2018-04-03 09:17:44
 
CURRENT_TEST: rpl.rpl_concurrency_error
/Users/buildbot/maria-slave/mac-1012-bintar/build/client/mysqltest: Error on delete of '/Users/buildbot/maria-slave/mac-1012-bintar/build/mysql-test/var/tmp/_var_file_64d0ac48-3741-11e8-be37-ac87a33b471c.inc' (Errcode: 2 "No such file or directory")
/Users/buildbot/maria-slave/mac-1012-bintar/build/client/mysqltest: Error on delete of '/Users/buildbot/maria-slave/mac-1012-bintar/build/mysql-test/var/tmp/_var_file_64d8aab0-3741-11e8-be37-ac87a33b471c.inc' (Errcode: 2 "No such file or directory")
mysqltest: In included file "./include/rpl_diff.inc": 
included from /Users/buildbot/maria-slave/mac-1012-bintar/build/mysql-test/suite/rpl/t/rpl_concurrency_error.test at line 134:
At line 113: command "diff_files" failed with error: 1  my_errno: 175  errno: -1
 
The result from queries just before the failure was:
< snip >
master-bin.000001	#	Query	#	#	use `test`; UPDATE t SET f = 'gray 1' WHERE i = 3
master-bin.000001	#	Xid	#	#	COMMIT /* XID */
master-bin.000001	#	Gtid	#	#	BEGIN GTID #-#-#
master-bin.000001	#	Query	#	#	use `test`; UPDATE IGNORE t SET f = 'dark blue 1' WHERE f = 'red'
master-bin.000001	#	Query	#	#	use `test`; INSERT INTO t VALUES (6 + (1 * 10),"brown")
master-bin.000001	#	Xid	#	#	COMMIT /* XID */
connection master;
connection slave;
include/rpl_diff.inc
include/rpl_diff.inc
--- /Users/buildbot/maria-slave/mac-1012-bintar/build/mysql-test/var/tmp/_rpl_diff_server-2.tmp	2018-04-03 09:17:43.000000000 -0400
+++ /Users/buildbot/maria-slave/mac-1012-bintar/build/mysql-test/var/tmp/_rpl_diff_server-1.tmp	2018-04-03 09:17:43.000000000 -0400
@@ -1,6 +1,6 @@
 d	f
-2018-04-03 09:17:34	updated t: yelow -> yellow 2
 2018-04-03 09:17:35	updated t: red -> magenta
+2018-04-03 09:17:35	updated t: yelow -> yellow 2
 2018-04-03 09:17:37	brown
 2018-04-03 09:17:37	updated t: red -> dark blu
 2018-04-03 09:17:37	updated t: yellow 2 -> gray 2

Comment by Alexander Barkov [ 2018-04-27 ]

Hi Elkin,
the patch "[Commits] 99c40e0628d: MDEV-13727 rpl.rpl_concurrency_error failed" looks ok for me.
Thanks.

Comment by Andrei Elkin [ 2018-05-21 ]

Made a patch, discussed it with Bar. Todo: need to understand fully what the changes of MDEV-8305 has to do wrt the current timestamp computation (apart from the slow log reporting).

Comment by Andrei Elkin [ 2018-05-21 ]

Analyzed MDEV-8305 in details to stick to initial patch that blocks the session timestamp resetting (via THD::set_time()) when the current statement belongs to either a stored func or a trigger.
Alternative method is drafted into the patch as comments (limited to the trigger case while it applies to the SF as well).
Which method to settle upon is left to review discussion.

Comment by Andrei Elkin [ 2018-05-21 ]

Monty, hello.

The patch deals with a relatively new feature of MDEV-8305. I discussed the issue and my fixing method initially with Bar (who made me something to think about), but considering complexity of the case we decided to engage you for reviewing.

Could you please look at few-liner patch:

From: andrei.elkin@pp.inet.fi
Subject: [Commits] 0768dcbbde5: MDEV-13727 top-level query timestamp reset
at stored func/trigger internal statements

I also show another method which in commented lines that you will see.

Cheers,

Andrei

Comment by Michael Widenius [ 2018-05-23 ]

Agreed with Andrei about a simpler patch to solve this issue.

  • Just remove the time setting code in execute(). It's not needed.
Comment by Andrei Elkin [ 2018-05-25 ]

Took over Monty's refinement of my patch and added up removal of QUERY_START_TIME_INFO related which served exclusively to help
implementing of being removed the time backup/reset/restore inside sp_instr_stmt::execute.
Tested (on very slow BB- and analyzed failures potentially related - none to find).

Generated at Thu Feb 08 08:07:53 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.