We are getting close to going live and I can't find a workaround.
The main difference here is I am not doing a manual prepare, but it sounds like the same problem of releasing the prepare object but not cleaning up a pointer list. This stored proc runs every 1m 30s. This runs fine for about an hour and then I start getting the error. There is a TRANSACTION / COMMIT in the stored procedure, so it isn't leaving something open.
==========================================================
mdbPool = getPool();
mdbConn = await mdbPool.getConnection();
// Use a stored procedure to select and set a job number to prevent duplicate sending of emails.
// Check for db error
if (JSON.stringify(resultSpPrepare).includes("@full_error")) {
const dbResponseErrorMsg = JSON.stringify(resultSpPrepare[0][0]["@full_error"]);
dlog("Throw", dbResponseErrorMsg);
throw
// No error, get returned ID to process emails
const jobNumber = resultSpPrepare[0][0].JobNumber;
=====================================================
DELIMITER //
CREATE OR REPLACE PROCEDURE EM_Email_Prepare_To_Send_U_sp(IN pin_RequestUserId BigInt(20))
NO SQL
SQL SECURITY INVOKER
BEGIN
DECLARE aTimeStamp DateTime DEFAULT UTC_TIMESTAMP(3);
DECLARE aJobNumber BigInt(20);
DECLARE aDbId nVarChar(50);
DECLARE EXIT HANDLER FOR SQLEXCEPTION BEGIN
ROLLBACK;
GET DIAGNOSTICS CONDITION 1 @sqlstate = RETURNED_SQLSTATE,
@errno = MYSQL_ERRNO, @text = MESSAGE_TEXT;
SET @full_error = CONCAT("ERROR ", @errno, " (", @sqlstate, "): ", @text);
SELECT @full_error;
END;
SELECT KeyValue INTO aDbId FROM EM_Config WHERE SubSys = 'CORE' AND KeyName = 'coreDatabaseId';
SET aJobNumber = NEXT VALUE FOR EM_EmailSeq;
START TRANSACTION;
UPDATE EM_Email SET
emProcJobNumber = aJobNumber,
emProcUTCTimeStamp = atimeStamp,
UpdateUserId = pin_RequestUserId,
UpdateUTCTimeStamp = aTimeStamp
WHERE ((emProcStatus = 'Queued') AND (emProcJobNumber = 0)) or
((emProcStatus = 'Retry') AND (emProcJobNumber = 0) AND
(DATE_ADD(emProcUTCTimeStamp, INTERVAL (POWER(emProcTryCount, 2.5)) HOUR) < NOW()));
COMMIT;
SELECT aJobNumber AS JobNumber;
END //
DELIMITER ;
the only way this can occurs is having a race condition releasing prepare from cache before execution.
This is strange, because node.js single thread usually permit to avoid this kind of problem.
I'll check that in detail this afternoon.
Diego Dupin
added a comment - the only way this can occurs is having a race condition releasing prepare from cache before execution.
This is strange, because node.js single thread usually permit to avoid this kind of problem.
I'll check that in detail this afternoon.
Can you confirm you never use prepare + execute type of implementation ? i.e. like :
const prepare = await conn.prepare('SELECT * FROM mysql.user where host = ?');
try {
const res = await prepare.execute(['localhost']);
} finally {
prepare.close();
}
Diego Dupin
added a comment - Can you confirm you never use prepare + execute type of implementation ? i.e. like :
const prepare = await conn.prepare( 'SELECT * FROM mysql.user where host = ?' );
try {
const res = await prepare.execute([ 'localhost' ]);
} finally {
prepare.close();
}
The only way this can occurs is that since PREPARE cache can be use in IO threads, that can lead to race conditions.
Prepare cache need to be slightly changed in order to be used in event only, to ensure cache beeing only used in node.js main thread.
Diego Dupin
added a comment - - edited The only way this can occurs is that since PREPARE cache can be use in IO threads, that can lead to race conditions.
Prepare cache need to be slightly changed in order to be used in event only, to ensure cache beeing only used in node.js main thread.
I can confirm that we don't manually "prepare" any statements. I actually return the connection to the pool as most of the time there aren't any new emails waiting to be sent. So 99% of the time it tries to update records to put them into a batch and doesn't update anything. Please let me know when you have a build of 3.1 and I will be happy to alpha/beta test it.
The scheduler was actually set to 60 seconds. I will increase the time between each job for now. And I am still willing to test the fix for you.
Tom Miller
added a comment - - edited I can confirm that we don't manually "prepare" any statements. I actually return the connection to the pool as most of the time there aren't any new emails waiting to be sent. So 99% of the time it tries to update records to put them into a batch and doesn't update anything. Please let me know when you have a build of 3.1 and I will be happy to alpha/beta test it.
The scheduler was actually set to 60 seconds. I will increase the time between each job for now. And I am still willing to test the fix for you.
Diego Dupin
added a comment - There cannot be any use in I/O thread in current connectors. Wrong assessment.
I've changed implementation to ensure that Prepare result cannot be use when closed. Even if i've not been able to reproduced this issue, correction must avoid this kind of situation.
(commit https://github.com/mariadb-corporation/mariadb-connector-nodejs/commit/14f770456652b3511a443b9dd8eff03293cfb7a4 )
develop branch contain the correction
Diego Dupin
added a comment - - edited about testing, you can already,
cloning project :
git clone https: //github.com/mariadb-corporation/mariadb-connector-nodejs.git
cd mariadb-connector-nodejs
git checkout develop
and in your project, change package.json to replace mariadb version to connector project, like :
"dependencies" : {
...
"mariadb" : "/path/to/connector/mariadb-connector-nodejs" ,
...
1222tmiller since 3.1.0 is being release, i'm closing this task in order to get correction in new release. However, since I haven't reproduced the problem, I can't be sure that this solves your problem. If this is not the case, please recreate a new jira entry referring to this file
Diego Dupin
added a comment - 1222tmiller since 3.1.0 is being release, i'm closing this task in order to get correction in new release. However, since I haven't reproduced the problem, I can't be sure that this solves your problem. If this is not the case, please recreate a new jira entry referring to this file
Just pointing to the directory didn't work. I added the appropriate modules to the project and moved it into the node_modules and renamed the directory to mariadb. But it doesn't seem to fix the problem. Let me know if you want me to run some test or other stuff to see anything in a live system, just let me know.
I have done a lot of pool/warehouse work in other languages. Calling it a warehouse shows my age, but it was very applicable as you would treat the pool like traditional inventory and use a first in - last out inventory methodology. Basically using a stack methodology. You pop a connection off the top and return it to the bottom. With 50 connections, and running every minute, with not much traffic, it should take about 30 minutes for a connection to be reused. And are you using two lists? One for tracking in-use connections and one for unused connections (inventory)? In the documentation, it is recommended not using min/max setting and having a fixed number of connections. I am assuming this is because you have one object list tracking used and available connections. If you use two lists, it is inconsequential to have min/max, because as you request a new connection, and the inventory is empty, you create a new one. Unfortunately, I am a newbie with JavaScript and I am not able to do this. You should also have a setting or algorithm on how quickly you reduce inventory once traffic falls off.
I wish there was a way to reset a connection when returning it to the pool. Having commits in the stored procedure means that by the time I am returning it to the pool, I am not worried about a rollback of any kind. I am also worried that simple selects not in a transaction are leaving things open long after I have used the data returned by the Stored Procedure or Select statement.
conn.release(true);
With the default being false. A true would expedite the resetting of the connection and block it from being used until it is reset.
Let me know how I can help.
Tom Miller
added a comment - Just pointing to the directory didn't work. I added the appropriate modules to the project and moved it into the node_modules and renamed the directory to mariadb. But it doesn't seem to fix the problem. Let me know if you want me to run some test or other stuff to see anything in a live system, just let me know.
I have done a lot of pool/warehouse work in other languages. Calling it a warehouse shows my age, but it was very applicable as you would treat the pool like traditional inventory and use a first in - last out inventory methodology. Basically using a stack methodology. You pop a connection off the top and return it to the bottom. With 50 connections, and running every minute, with not much traffic, it should take about 30 minutes for a connection to be reused. And are you using two lists? One for tracking in-use connections and one for unused connections (inventory)? In the documentation, it is recommended not using min/max setting and having a fixed number of connections. I am assuming this is because you have one object list tracking used and available connections. If you use two lists, it is inconsequential to have min/max, because as you request a new connection, and the inventory is empty, you create a new one. Unfortunately, I am a newbie with JavaScript and I am not able to do this. You should also have a setting or algorithm on how quickly you reduce inventory once traffic falls off.
I wish there was a way to reset a connection when returning it to the pool. Having commits in the stored procedure means that by the time I am returning it to the pool, I am not worried about a rollback of any kind. I am also worried that simple selects not in a transaction are leaving things open long after I have used the data returned by the Stored Procedure or Select statement.
conn.release(true);
With the default being false. A true would expedite the resetting of the connection and block it from being used until it is reset.
Let me know how I can help.
1222tmiller hmm. ok, could you confirm you get the same type of "Unknown prepared statement handler" error ?
The reason to recommand having minimum connection equal maximum is not due to implementation: If you want an application or website that is capable of handling unexpected bursts (peaks) without stumbling, you pretty much have to avoid creating connections on-demand. Trying to spool up new connections when a peak is occuring is almost guaranteed to make things worse. Specifically for node.js : keeping some idle connections cost nearly nothing for node.js : at the difference of some other languages, there is no multithread context, so no context switching.
Diego Dupin
added a comment - 1222tmiller hmm. ok, could you confirm you get the same type of "Unknown prepared statement handler" error ?
The reason to recommand having minimum connection equal maximum is not due to implementation: If you want an application or website that is capable of handling unexpected bursts (peaks) without stumbling, you pretty much have to avoid creating connections on-demand. Trying to spool up new connections when a peak is occuring is almost guaranteed to make things worse. Specifically for node.js : keeping some idle connections cost nearly nothing for node.js : at the difference of some other languages, there is no multithread context, so no context switching.
I switched out all of my code to use a connection vs a pool and it works fine now. But I would like to use the pool capability. We are getting down to the last two weeks before release. And you are working on trying to get 3.1 out the door. Maybe we pick this back up for your 3.1.1 release. I will have more time to help you set up something locally that mimics my setup.
About setting it to the maximum makes sense. I have often used a warehouse for complicated screens with thousands of objects and the screen takes up a lot of memory. But I still think it is a good best practice to do a first in / last out methodology for pools/warehouses.
Tom Miller
added a comment - Yes, getting the same error.
I switched out all of my code to use a connection vs a pool and it works fine now. But I would like to use the pool capability. We are getting down to the last two weeks before release. And you are working on trying to get 3.1 out the door. Maybe we pick this back up for your 3.1.1 release. I will have more time to help you set up something locally that mimics my setup.
About setting it to the maximum makes sense. I have often used a warehouse for complicated screens with thousands of objects and the screen takes up a lot of memory. But I still think it is a good best practice to do a first in / last out methodology for pools/warehouses.
>I switched out all of my code to use a connection vs a pool and it works fine now
That's a good information, I know at least where to search.
>But I still think it is a good best practice to do a first in / last out methodology for pools/warehouses.
that's the case: connections are put in a queue (idleConnections) when created/release to pool, connections are added to the end of the queue. When client ask for a connection, pool give first valid entry of queue.
Diego Dupin
added a comment - >I switched out all of my code to use a connection vs a pool and it works fine now
That's a good information, I know at least where to search.
>But I still think it is a good best practice to do a first in / last out methodology for pools/warehouses.
that's the case: connections are put in a queue (idleConnections) when created/release to pool, connections are added to the end of the queue. When client ask for a connection, pool give first valid entry of queue.
I think i've finally found the problem: Could you share the pool configuration to confirm option `resetAfterUse` is enable ?
Problem here is that prepare cache is not emptied, even if server side all prepared are released.
Diego Dupin
added a comment - I think i've finally found the problem: Could you share the pool configuration to confirm option `resetAfterUse` is enable ?
Problem here is that prepare cache is not emptied, even if server side all prepared are released.
correction is done with this commit on develop branch.
since 3.1.0 is in the process of being release, this correction will only be available on 3.1.1.
Diego Dupin
added a comment - correction is done with this commit on develop branch.
since 3.1.0 is in the process of being release, this correction will only be available on 3.1.1.
People
Diego Dupin
Tom Miller
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":858.7000000476837,"ttfb":232,"pageVisibility":"visible","entityId":118958,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":1,"journeyId":"7215a562-7883-432d-9c7d-95080215015d","navigationType":0,"readyForUser":923.1000000238419,"redirectCount":0,"resourceLoadedEnd":1270.2000000476837,"resourceLoadedStart":238.10000002384186,"resourceTiming":[{"duration":166.5,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2bu7/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":238.10000002384186,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":238.10000002384186,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":404.60000002384186,"responseStart":0,"secureConnectionStart":0},{"duration":166.5,"initiatorType":"link","name":"https://jira.mariadb.org/s/7ebd35e77e471bc30ff0eba799ebc151-CDN/lu2bu7/820016/12ta74/8679b4946efa1a0bb029a3a22206fb5d/_/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","startTime":238.40000009536743,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":238.40000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":404.90000009536743,"responseStart":0,"secureConnectionStart":0},{"duration":175.30000007152557,"initiatorType":"script","name":"https://jira.mariadb.org/s/fbf975c0cce4b1abf04784eeae9ba1f4-CDN/lu2bu7/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":238.60000002384186,"connectEnd":238.60000002384186,"connectStart":238.60000002384186,"domainLookupEnd":238.60000002384186,"domainLookupStart":238.60000002384186,"fetchStart":238.60000002384186,"redirectEnd":0,"redirectStart":0,"requestStart":238.60000002384186,"responseEnd":413.90000009536743,"responseStart":413.90000009536743,"secureConnectionStart":238.60000002384186},{"duration":247.69999992847443,"initiatorType":"script","name":"https://jira.mariadb.org/s/099b33461394b8015fc36c0a4b96e19f-CDN/lu2bu7/820016/12ta74/8679b4946efa1a0bb029a3a22206fb5d/_/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","startTime":238.80000007152557,"connectEnd":238.80000007152557,"connectStart":238.80000007152557,"domainLookupEnd":238.80000007152557,"domainLookupStart":238.80000007152557,"fetchStart":238.80000007152557,"redirectEnd":0,"redirectStart":0,"requestStart":238.80000007152557,"responseEnd":486.5,"responseStart":486.5,"secureConnectionStart":238.80000007152557},{"duration":251.20000004768372,"initiatorType":"script","name":"https://jira.mariadb.org/s/94c15bff32baef80f4096a08aceae8bc-CDN/lu2bu7/820016/12ta74/c92c0caa9a024ae85b0ebdbed7fb4bd7/_/download/contextbatch/js/atl.global,-_super/batch.js?locale=en","startTime":239,"connectEnd":239,"connectStart":239,"domainLookupEnd":239,"domainLookupStart":239,"fetchStart":239,"redirectEnd":0,"redirectStart":0,"requestStart":239,"responseEnd":490.2000000476837,"responseStart":490.2000000476837,"secureConnectionStart":239},{"duration":251.5,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-en/jira.webresources:calendar-en.js","startTime":239.20000004768372,"connectEnd":239.20000004768372,"connectStart":239.20000004768372,"domainLookupEnd":239.20000004768372,"domainLookupStart":239.20000004768372,"fetchStart":239.20000004768372,"redirectEnd":0,"redirectStart":0,"requestStart":239.20000004768372,"responseEnd":490.7000000476837,"responseStart":490.7000000476837,"secureConnectionStart":239.20000004768372},{"duration":251.79999995231628,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-localisation-moment/jira.webresources:calendar-localisation-moment.js","startTime":239.30000007152557,"connectEnd":239.30000007152557,"connectStart":239.30000007152557,"domainLookupEnd":239.30000007152557,"domainLookupStart":239.30000007152557,"fetchStart":239.30000007152557,"redirectEnd":0,"redirectStart":0,"requestStart":239.30000007152557,"responseEnd":491.10000002384186,"responseStart":491.10000002384186,"secureConnectionStart":239.30000007152557},{"duration":316.39999997615814,"initiatorType":"link","name":"https://jira.mariadb.org/s/b04b06a02d1959df322d9cded3aeecc1-CDN/lu2bu7/820016/12ta74/a2ff6aa845ffc9a1d22fe23d9ee791fc/_/download/contextbatch/css/jira.global.look-and-feel,-_super/batch.css","startTime":239.60000002384186,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":239.60000002384186,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":556,"responseStart":0,"secureConnectionStart":0},{"duration":252,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":239.70000004768372,"connectEnd":239.70000004768372,"connectStart":239.70000004768372,"domainLookupEnd":239.70000004768372,"domainLookupStart":239.70000004768372,"fetchStart":239.70000004768372,"redirectEnd":0,"redirectStart":0,"requestStart":239.70000004768372,"responseEnd":491.7000000476837,"responseStart":491.7000000476837,"secureConnectionStart":239.70000004768372},{"duration":316.1999999284744,"initiatorType":"link","name":"https://jira.mariadb.org/s/3ac36323ba5e4eb0af2aa7ac7211b4bb-CDN/lu2bu7/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":239.90000009536743,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":239.90000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":556.1000000238419,"responseStart":0,"secureConnectionStart":0},{"duration":252.40000009536743,"initiatorType":"script","name":"https://jira.mariadb.org/s/3339d87fa2538a859872f2df449bf8d0-CDN/lu2bu7/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":240,"connectEnd":240,"connectStart":240,"domainLookupEnd":240,"domainLookupStart":240,"fetchStart":240,"redirectEnd":0,"redirectStart":0,"requestStart":240,"responseEnd":492.40000009536743,"responseStart":492.40000009536743,"secureConnectionStart":240},{"duration":1026.8999999761581,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-js/jira.webresources:bigpipe-js.js","startTime":240.90000009536743,"connectEnd":240.90000009536743,"connectStart":240.90000009536743,"domainLookupEnd":240.90000009536743,"domainLookupStart":240.90000009536743,"fetchStart":240.90000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":240.90000009536743,"responseEnd":1267.8000000715256,"responseStart":1267.8000000715256,"secureConnectionStart":240.90000009536743},{"duration":1029.2000000476837,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-init/jira.webresources:bigpipe-init.js","startTime":241,"connectEnd":241,"connectStart":241,"domainLookupEnd":241,"domainLookupStart":241,"fetchStart":241,"redirectEnd":0,"redirectStart":0,"requestStart":241,"responseEnd":1270.2000000476837,"responseStart":1270.2000000476837,"secureConnectionStart":241},{"duration":700.6000000238419,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":567.6000000238419,"connectEnd":567.6000000238419,"connectStart":567.6000000238419,"domainLookupEnd":567.6000000238419,"domainLookupStart":567.6000000238419,"fetchStart":567.6000000238419,"redirectEnd":0,"redirectStart":0,"requestStart":567.6000000238419,"responseEnd":1268.2000000476837,"responseStart":1268.2000000476837,"secureConnectionStart":567.6000000238419},{"duration":423.7999999523163,"initiatorType":"script","name":"https://www.google-analytics.com/analytics.js","startTime":852.3000000715256,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":852.3000000715256,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1276.1000000238419,"responseStart":0,"secureConnectionStart":0}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":52,"responseStart":232,"responseEnd":234,"domLoading":236,"domInteractive":1327,"domContentLoadedEventStart":1327,"domContentLoadedEventEnd":1372,"domComplete":1723,"loadEventStart":1723,"loadEventEnd":1723,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":1293.8000000715256},{"name":"bigPipe.sidebar-id.end","time":1294.5},{"name":"bigPipe.activity-panel-pipe-id.start","time":1294.7000000476837},{"name":"bigPipe.activity-panel-pipe-id.end","time":1298.1000000238419},{"name":"activityTabFullyLoaded","time":1394.1000000238419}],"measures":[],"correlationId":"3486e4db8ef99","effectiveType":"4g","downlink":10,"rtt":0,"serverDuration":118,"dbReadsTimeInMs":11,"dbConnsTimeInMs":19,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}
the only way this can occurs is having a race condition releasing prepare from cache before execution.
This is strange, because node.js single thread usually permit to avoid this kind of problem.
I'll check that in detail this afternoon.