When we are running our simple insert test or our a bit more complex mixed test (SIUD) at a very high pace (10 us delay between statements) maxscale is not sending all statements to the tee'd instance after a short time.
When we lower the pace to 10 ms delay this does not happen.
Unfortunately maxscale is not throwing any warning or error (in maxscale error log) to make us aware of this.
This means tee filter cannot be used reliably in production.
Possibly a statement cache or something like this is overflowing?
Would be good to have something like a "synchronous" mode to guarantee that statements have been received my both database backends with possibly some timeout (similar to semi-synchronous replication).
We want to use this for some kind of quality assurance between 2 different backends and/or for doing a push replication from the secure to the insecure network zone in a security sensitive environment.
I repeated the test. Please find all the information attached. You can also provoke the situation when you set on the tee'd instance innodb_flush_log_at_trx_commit = 1 and sync_binlog = 1 while you have these values set to 2 and 0 on the primary instance. Even with the slow pace:
Test with slow pace (10000 us sleep, everything is fine):
shell> date ; ./mixed_test.php
Wed 6 Jan 09:17:34 CET 2021
IIII.........IIII^CCaught signal: 2
shell> date
Wed 6 Jan 09:19:29 CET 2021
Primary instance: mariadb-105
SQL> SELECT COUNT, CURRENT_TIMESTAMP() FROM test;
-----------------------------+
count
current_timestamp()
-----------------------------+
6163
2021-01-06 09:20:49
-----------------------------+
End of General Log:
330 Query SELECT * FROM test WHERE id = 383966
330 Query INSERT INTO test (id, data, ts) values (383966, "Test data insert", CURRENT_TIMESTAMP(6))
210106 9:19:27 330 Quit
Tee'd instance: mysql-57
SQL> SELECT COUNT, CURRENT_TIMESTAMP() FROM test;
-----------------------------+
count
current_timestamp()
-----------------------------+
6163
2021-01-06 09:21:02
-----------------------------+
End of General Log:
2021-01-06T08:19:26.942277Z 360 Query SELECT * FROM test WHERE id = 383966
2021-01-06T08:19:26.943038Z 360 Query INSERT INTO test (id, data, ts) values (383966, "Test data insert", CURRENT_TIMESTAMP(6))
2021-01-06T08:19:27.522731Z 360 Quit
Test with fast pace (10 us sleep, rows are missing):
shell> date ; ./mixed_test.php ; date
Wed 6 Jan 09:24:26 CET 2021
IIIIIIII...DUDI^CCaught signal: 2
Wed 6 Jan 09:27:30 CET 2021
Primary instance: mariadb-105
350 Query SELECT * FROM test WHERE id = 934
350 Query INSERT INTO test (id, data, ts) values (934, "Test data insert", CURRENT_TIMESTAMP(6))
210106 9:27:30 350 Quit
2021-01-06T08:27:30.470174Z 383 Query DELETE FROM test WHERE id = 61171
2021-01-06T08:27:30.470592Z 383 Query SELECT * FROM test WHERE id = 24971
--> Quit is missing! And last statement was an INSERT NOT a DELETE!
Oli Sennhauser
added a comment - Hi Markus
I repeated the test. Please find all the information attached. You can also provoke the situation when you set on the tee'd instance innodb_flush_log_at_trx_commit = 1 and sync_binlog = 1 while you have these values set to 2 and 0 on the primary instance. Even with the slow pace:
Test with slow pace (10000 us sleep, everything is fine):
shell> date ; ./mixed_test.php
Wed 6 Jan 09:17:34 CET 2021
IIII.........IIII^CCaught signal: 2
shell> date
Wed 6 Jan 09:19:29 CET 2021
Primary instance: mariadb-105
SQL> SELECT COUNT , CURRENT_TIMESTAMP() FROM test;
--------- --------------------+
count
current_timestamp()
--------- --------------------+
6163
2021-01-06 09:20:49
--------- --------------------+
End of General Log:
330 Query SELECT * FROM test WHERE id = 383966
330 Query INSERT INTO test (id, data, ts) values (383966, "Test data insert", CURRENT_TIMESTAMP(6))
210106 9:19:27 330 Quit
Tee'd instance: mysql-57
SQL> SELECT COUNT , CURRENT_TIMESTAMP() FROM test;
--------- --------------------+
count
current_timestamp()
--------- --------------------+
6163
2021-01-06 09:21:02
--------- --------------------+
End of General Log:
2021-01-06T08:19:26.942277Z 360 Query SELECT * FROM test WHERE id = 383966
2021-01-06T08:19:26.943038Z 360 Query INSERT INTO test (id, data, ts) values (383966, "Test data insert", CURRENT_TIMESTAMP(6))
2021-01-06T08:19:27.522731Z 360 Quit
Test with fast pace (10 us sleep, rows are missing):
shell> date ; ./mixed_test.php ; date
Wed 6 Jan 09:24:26 CET 2021
IIIIIIII...DUDI^CCaught signal: 2
Wed 6 Jan 09:27:30 CET 2021
Primary instance: mariadb-105
350 Query SELECT * FROM test WHERE id = 934
350 Query INSERT INTO test (id, data, ts) values (934, "Test data insert", CURRENT_TIMESTAMP(6))
210106 9:27:30 350 Quit
SQL> TRUNCATE TABLE test.test;
SQL> SELECT COUNT , CURRENT_TIMESTAMP() FROM test;
--------- --------------------+
count
current_timestamp()
--------- --------------------+
0
2021-01-06 09:24:12
35817
2021-01-06 09:25:37
55553
2021-01-06 09:26:28
59872
2021-01-06 09:27:01
61970
2021-01-06 09:27:43
61970
2021-01-06 09:28:02
61970
2021-01-06 09:29:29
61970
2021-01-06 09:30:14
--------- --------------------+
Secondary instance: mysql-57
2021-01-06T08:27:30.470174Z 383 Query DELETE FROM test WHERE id = 61171
2021-01-06T08:27:30.470592Z 383 Query SELECT * FROM test WHERE id = 24971
--> Quit is missing! And last statement was an INSERT NOT a DELETE!
SQL> TRUNCATE TABLE test.test;
SQL> SELECT COUNT , CURRENT_TIMESTAMP() FROM test;
--------- --------------------+
count
current_timestamp()
--------- --------------------+
0
2021-01-06 09:24:07
35228
2021-01-06 09:25:36
50725
2021-01-06 09:26:30
59681
2021-01-06 09:27:00
61401
2021-01-06 09:27:42
61401
2021-01-06 09:28:00
61401
2021-01-06 09:29:28
61401
2021-01-06 09:30:13
--------- --------------------+
570 rows missing. Now warning in the MaxScale error log.
The test table:
CREATE TABLE `test` (
`id` int(10) unsigned NOT NULL AUTO_INCREMENT,
`data` varchar(128) DEFAULT NULL,
`ts` timestamp(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6) ON UPDATE CURRENT_TIMESTAMP(6),
PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=100000 DEFAULT CHARSET=latin1
And the test script:
I've managed to reproduce this with a local setup. This seems to happen much more easily when the branched target is slower than the main target. I've created MXS-3370 for the documentation problem and changed this back to a bug.
markus makela
added a comment - I've managed to reproduce this with a local setup. This seems to happen much more easily when the branched target is slower than the main target. I've created MXS-3370 for the documentation problem and changed this back to a bug.
The fix to this was inadequate and it caused a session reference leak. This leak made it appear as if it worked as expected.
markus makela
added a comment - The fix to this was inadequate and it caused a session reference leak. This leak made it appear as if it worked as expected.
People
markus makela
Oli Sennhauser
Votes:
0Vote for this issue
Watchers:
2Start watching this issue
Dates
Created:
Updated:
Resolved:
Git Integration
Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.
{"report":{"fcp":1129.9000005722046,"ttfb":269.6000003814697,"pageVisibility":"visible","entityId":95450,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":32,"apdex":0.5,"journeyId":"c96db2b7-6672-416b-a013-953138ead2f2","navigationType":0,"readyForUser":1249.2000007629395,"redirectCount":0,"resourceLoadedEnd":1277.7000007629395,"resourceLoadedStart":277.70000076293945,"resourceTiming":[{"duration":248.69999980926514,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":277.70000076293945,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":277.70000076293945,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":526.4000005722046,"responseStart":0,"secureConnectionStart":0},{"duration":249,"initiatorType":"link","name":"https://jira.mariadb.org/s/7ebd35e77e471bc30ff0eba799ebc151-CDN/lu2cib/820016/12ta74/494e4c556ecbb29f90a3d3b4f09cb99c/_/download/contextbatch/css/jira.browse.project,project.issue.navigator,jira.view.issue,jira.general,jira.global,atl.general,-_super/batch.css?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&slack-enabled=true&whisper-enabled=true","startTime":278,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":278,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":527,"responseStart":0,"secureConnectionStart":0},{"duration":288.19999980926514,"initiatorType":"script","name":"https://jira.mariadb.org/s/0917945aaa57108d00c5076fea35e069-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":278.20000076293945,"connectEnd":278.20000076293945,"connectStart":278.20000076293945,"domainLookupEnd":278.20000076293945,"domainLookupStart":278.20000076293945,"fetchStart":278.20000076293945,"redirectEnd":0,"redirectStart":0,"requestStart":278.20000076293945,"responseEnd":566.4000005722046,"responseStart":566.3000001907349,"secureConnectionStart":278.20000076293945},{"duration":383.0999994277954,"initiatorType":"script","name":"https://jira.mariadb.org/s/2d8175ec2fa4c816e8023260bd8c1786-CDN/lu2cib/820016/12ta74/494e4c556ecbb29f90a3d3b4f09cb99c/_/download/contextbatch/js/jira.browse.project,project.issue.navigator,jira.view.issue,jira.general,jira.global,atl.general,-_super/batch.js?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&locale=en&slack-enabled=true&whisper-enabled=true","startTime":278.4000005722046,"connectEnd":278.4000005722046,"connectStart":278.4000005722046,"domainLookupEnd":278.4000005722046,"domainLookupStart":278.4000005722046,"fetchStart":278.4000005722046,"redirectEnd":0,"redirectStart":0,"requestStart":278.4000005722046,"responseEnd":661.5,"responseStart":661.5,"secureConnectionStart":278.4000005722046},{"duration":388.80000019073486,"initiatorType":"script","name":"https://jira.mariadb.org/s/a9324d6758d385eb45c462685ad88f1d-CDN/lu2cib/820016/12ta74/c92c0caa9a024ae85b0ebdbed7fb4bd7/_/download/contextbatch/js/atl.global,-_super/batch.js?locale=en","startTime":278.6000003814697,"connectEnd":278.6000003814697,"connectStart":278.6000003814697,"domainLookupEnd":278.6000003814697,"domainLookupStart":278.6000003814697,"fetchStart":278.6000003814697,"redirectEnd":0,"redirectStart":0,"requestStart":278.6000003814697,"responseEnd":667.4000005722046,"responseStart":667.4000005722046,"secureConnectionStart":278.6000003814697},{"duration":389.5,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-en/jira.webresources:calendar-en.js","startTime":278.70000076293945,"connectEnd":278.70000076293945,"connectStart":278.70000076293945,"domainLookupEnd":278.70000076293945,"domainLookupStart":278.70000076293945,"fetchStart":278.70000076293945,"redirectEnd":0,"redirectStart":0,"requestStart":278.70000076293945,"responseEnd":668.2000007629395,"responseStart":668.2000007629395,"secureConnectionStart":278.70000076293945},{"duration":389.80000019073486,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-localisation-moment/jira.webresources:calendar-localisation-moment.js","startTime":279,"connectEnd":279,"connectStart":279,"domainLookupEnd":279,"domainLookupStart":279,"fetchStart":279,"redirectEnd":0,"redirectStart":0,"requestStart":279,"responseEnd":668.8000001907349,"responseStart":668.8000001907349,"secureConnectionStart":279},{"duration":443.69999980926514,"initiatorType":"link","name":"https://jira.mariadb.org/s/b04b06a02d1959df322d9cded3aeecc1-CDN/lu2cib/820016/12ta74/a2ff6aa845ffc9a1d22fe23d9ee791fc/_/download/contextbatch/css/jira.global.look-and-feel,-_super/batch.css","startTime":279.1000003814697,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":279.1000003814697,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":722.8000001907349,"responseStart":0,"secureConnectionStart":0},{"duration":390.3999996185303,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":279.20000076293945,"connectEnd":279.20000076293945,"connectStart":279.20000076293945,"domainLookupEnd":279.20000076293945,"domainLookupStart":279.20000076293945,"fetchStart":279.20000076293945,"redirectEnd":0,"redirectStart":0,"requestStart":279.20000076293945,"responseEnd":669.6000003814697,"responseStart":669.5,"secureConnectionStart":279.20000076293945},{"duration":443.69999980926514,"initiatorType":"link","name":"https://jira.mariadb.org/s/3ac36323ba5e4eb0af2aa7ac7211b4bb-CDN/lu2cib/820016/12ta74/d176f0986478cc64f24226b3d20c140d/_/download/contextbatch/css/com.atlassian.jira.projects.sidebar.init,-_super,-project.issue.navigator,-jira.view.issue/batch.css?jira.create.linked.issue=true","startTime":279.30000019073486,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":279.30000019073486,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":723,"responseStart":0,"secureConnectionStart":0},{"duration":390.80000019073486,"initiatorType":"script","name":"https://jira.mariadb.org/s/5d5e8fe91fbc506585e83ea3b62ccc4b-CDN/lu2cib/820016/12ta74/d176f0986478cc64f24226b3d20c140d/_/download/contextbatch/js/com.atlassian.jira.projects.sidebar.init,-_super,-project.issue.navigator,-jira.view.issue/batch.js?jira.create.linked.issue=true&locale=en","startTime":279.5,"connectEnd":279.5,"connectStart":279.5,"domainLookupEnd":279.5,"domainLookupStart":279.5,"fetchStart":279.5,"redirectEnd":0,"redirectStart":0,"requestStart":279.5,"responseEnd":670.3000001907349,"responseStart":670.3000001907349,"secureConnectionStart":279.5},{"duration":626.5,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-js/jira.webresources:bigpipe-js.js","startTime":280.5,"connectEnd":280.5,"connectStart":280.5,"domainLookupEnd":280.5,"domainLookupStart":280.5,"fetchStart":280.5,"redirectEnd":0,"redirectStart":0,"requestStart":280.5,"responseEnd":907,"responseStart":907,"secureConnectionStart":280.5},{"duration":983.6999998092651,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-init/jira.webresources:bigpipe-init.js","startTime":284.70000076293945,"connectEnd":284.70000076293945,"connectStart":284.70000076293945,"domainLookupEnd":284.70000076293945,"domainLookupStart":284.70000076293945,"fetchStart":284.70000076293945,"redirectEnd":0,"redirectStart":0,"requestStart":284.70000076293945,"responseEnd":1268.4000005722046,"responseStart":1268.4000005722046,"secureConnectionStart":284.70000076293945},{"duration":172.60000038146973,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":735.6000003814697,"connectEnd":735.6000003814697,"connectStart":735.6000003814697,"domainLookupEnd":735.6000003814697,"domainLookupStart":735.6000003814697,"fetchStart":735.6000003814697,"redirectEnd":0,"redirectStart":0,"requestStart":735.6000003814697,"responseEnd":908.2000007629395,"responseStart":908.2000007629395,"secureConnectionStart":735.6000003814697},{"duration":265,"initiatorType":"link","name":"https://jira.mariadb.org/s/d5715adaadd168a9002b108b2b039b50-CDN/lu2cib/820016/12ta74/be4b45e9cec53099498fa61c8b7acba4/_/download/contextbatch/css/jira.project.sidebar,-_super,-project.issue.navigator,-jira.general,-jira.browse.project,-jira.view.issue,-jira.global,-atl.general,-com.atlassian.jira.projects.sidebar.init/batch.css?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&slack-enabled=true&whisper-enabled=true","startTime":1012.7000007629395,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1012.7000007629395,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1277.7000007629395,"responseStart":0,"secureConnectionStart":0}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":106,"responseStart":269,"responseEnd":279,"domLoading":275,"domInteractive":1317,"domContentLoadedEventStart":1317,"domContentLoadedEventEnd":1362,"domComplete":2111,"loadEventStart":2111,"loadEventEnd":2111,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":1291.4000005722046},{"name":"bigPipe.sidebar-id.end","time":1292.2000007629395},{"name":"bigPipe.activity-panel-pipe-id.start","time":1292.4000005722046},{"name":"bigPipe.activity-panel-pipe-id.end","time":1294.5},{"name":"activityTabFullyLoaded","time":1412.8000001907349}],"measures":[],"correlationId":"948a92d6d01a8d","effectiveType":"4g","downlink":10,"rtt":0,"serverDuration":109,"dbReadsTimeInMs":13,"dbConnsTimeInMs":22,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}
Hi Markus
I repeated the test. Please find all the information attached. You can also provoke the situation when you set on the tee'd instance innodb_flush_log_at_trx_commit = 1 and sync_binlog = 1 while you have these values set to 2 and 0 on the primary instance. Even with the slow pace:
Test with slow pace (10000 us sleep, everything is fine):
shell> date ; ./mixed_test.php
Wed 6 Jan 09:17:34 CET 2021
IIII.........IIII^CCaught signal: 2
shell> date
Wed 6 Jan 09:19:29 CET 2021
Primary instance: mariadb-105
SQL> SELECT COUNT
, CURRENT_TIMESTAMP() FROM test;
---------
--------------------+---------
--------------------+---------
--------------------+End of General Log:
330 Query SELECT * FROM test WHERE id = 383966
330 Query INSERT INTO test (id, data, ts) values (383966, "Test data insert", CURRENT_TIMESTAMP(6))
210106 9:19:27 330 Quit
Tee'd instance: mysql-57
SQL> SELECT COUNT
, CURRENT_TIMESTAMP() FROM test;
---------
--------------------+---------
--------------------+---------
--------------------+End of General Log:
2021-01-06T08:19:26.942277Z 360 Query SELECT * FROM test WHERE id = 383966
2021-01-06T08:19:26.943038Z 360 Query INSERT INTO test (id, data, ts) values (383966, "Test data insert", CURRENT_TIMESTAMP(6))
2021-01-06T08:19:27.522731Z 360 Quit
Test with fast pace (10 us sleep, rows are missing):
shell> date ; ./mixed_test.php ; date
Wed 6 Jan 09:24:26 CET 2021
IIIIIIII...DUDI^CCaught signal: 2
Wed 6 Jan 09:27:30 CET 2021
Primary instance: mariadb-105
350 Query SELECT * FROM test WHERE id = 934
350 Query INSERT INTO test (id, data, ts) values (934, "Test data insert", CURRENT_TIMESTAMP(6))
210106 9:27:30 350 Quit
SQL> TRUNCATE TABLE test.test;
, CURRENT_TIMESTAMP() FROM test;
SQL> SELECT COUNT
---------
--------------------+---------
--------------------+---------
--------------------+Secondary instance: mysql-57
2021-01-06T08:27:30.470174Z 383 Query DELETE FROM test WHERE id = 61171
2021-01-06T08:27:30.470592Z 383 Query SELECT * FROM test WHERE id = 24971
--> Quit is missing! And last statement was an INSERT NOT a DELETE!
SQL> TRUNCATE TABLE test.test;
, CURRENT_TIMESTAMP() FROM test;
SQL> SELECT COUNT
---------
--------------------+---------
--------------------+---------
--------------------+570 rows missing. Now warning in the MaxScale error log.
The test table:
CREATE TABLE `test` (
`id` int(10) unsigned NOT NULL AUTO_INCREMENT,
`data` varchar(128) DEFAULT NULL,
`ts` timestamp(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6) ON UPDATE CURRENT_TIMESTAMP(6),
PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=100000 DEFAULT CHARSET=latin1
And the test script: