Cfstoredproc creating high open cursors in Oracle

dman1 · November 21, 2022, 9:01pm

Lucee: 5.3.8.206
Oracle driver: 19.12.0

When using on a heavily used server we have noticed that we end up with a large number of open cursors which are not closed, this leads to:
ORA-00604: error occurred at recursive SQL level 1
ORA-01000: maximum open cursors exceeded

We did investigate increasing the allowed open cursors, but this would just kick the can down the road a bit.

One of our Java devs suggested that Lucee doesn’t close the ResultSet or the PreparedStatement afterwards. here

I thought I’d post here for comment before filing a GitHub issue.

dman1 · January 18, 2023, 9:38pm

@Zackster flagging this one with you as its got no love so far. We are daily having to restart instances on our servers as the db connections are creating large number of cursors. We have tried setting the data sources to have a stricter max connection time (3 hours) but this hasnt helped. We cant go lower than that because we have some long running background jobs that can take that long. Right now Im investigating forcing the datasource to close the connection at the end of the request.

Zackster · January 19, 2023, 9:35am

like with any bug, if you could provide us with a reproducible test case, we can solve it

we don’t run oracle as part of the main lucee ci process as the service takes forever to start

but it does have it’s own CI and tests in the extension repo GitHub - lucee/extension-jdbc-oracle

you can take this as an example Lucee/LDEV0637.cfc at 6.0 · lucee/Lucee · GitHub

and drop your test case as a PR under /tests/

to run the tests locally, you’ll need to set up some env vars like the GHA pointing to your local oracle instance and checkout a copy of

Script Runner (requires ant)
Lucee 6

this is what I use locally to run the tests

call ant
if %errorlevel% neq 0 exit /b %errorlevel%
set testLabels=oracle
set testFilter=
set testAdditional=C:\work\lucee-extensions\extension-jdbc-oracle\tests
set testServices=oracle

ant -buildfile="C:\work\script-runner" -DluceeVersion="light-6.0.0.328-SNAPSHOT" -Dwebroot="C:\work\lucee6\test" -Dexecute="/bootstrap-tests.cfm" -DextensionDir="C:\work\lucee-extensions\extension-jdbc-oracle\dist"

Zackster · January 19, 2023, 12:03pm

I’ve knocked up basic test to check open cursors, not quite sure how to pass in the sysdba

I tried username="sys as sysdba"; but that didn’t work either

Zackster · January 20, 2023, 4:00pm

got that working, there a bit of noise due to
https://lucee.daemonite.io/t/build-better-handling-of-bad-test-cases/11977/2

     [java]    [script] 	testAdditional.cursors 
     [java]    [script] query("HIGHEST_OPEN_CUR":[37],"MAX_OPEN_CUR":["300"])
     [java]    [script] query("HIGHEST_OPEN_CUR":[37],"MAX_OPEN_CUR":["300"])
     [java]    [script] 	 (1 tests passed in 105 ms)

@dman1 add your test code here

github.com

lucee/extension-jdbc-oracle/blob/master/tests/cursors.cfc#L9


      
          component extends="org.lucee.cfml.test.LuceeTestCase" labels="oracle" {
          	function run(){
          		describe( title="check open cursors",  skip=doSkip(),body=function(){
          			it(title="Checking oracle query to select current Date & time", body=function(){
          				systemOutput("", true);
          				var initial_cursor = checkCursors();
          				systemOutput(initial_cursor, true);
          
          
				// do some stuff to reproduce the cursor problem
          
          
				var post_cursor = checkCursors();
          				systemOutput(post_cursor, true);
          
          
				expect( initial_cursor.highest_open_cur ).toBe( post_cursor.highest_open_cur );
          			});
          		});
          	}
          
          
	private query function checkCursors(){

dman1 · January 20, 2023, 11:09pm

Cheers Zak, I managed to get it running yesterday and couldnt reproduce the problem, even running 50k loops of a stored proceedure
We are thinking this may be related to https://lucee.daemonite.io/t/resource-leak-in-datasourceconnectionpool-5-3-10/11853, with the cursors being a symptom of the data source connections not actually being closed, leaving the cursors open in Oracle.
Below is a graph of active datasource connections after our early morning restart. We would expect these to peak around 3PM then decrease as our service becomes less utilized, however they only ever trend upward. If we run an Oracle query to list the inactive datasource connections, we get high numbers of inactive connections that go well past the liveTime.

Zackster · January 21, 2023, 8:40am

Try using threads in the test case, that uses the connection pool, as each thread uses it’s own pageContext

github.com

lucee/Lucee/blob/6.0/test/tickets/LDEV4320.cfc#L13


      
          	function beforeAll(){

          		application action="update" datasource=server.getDatasource( 

          			service="h2",

          			dbFile=server._getTempDir( "h24320" ),

          			options={ connectionLimit:2 }

          		);

          	}

          	

          	function run( testResults , testBox ) {

          		describe( "Testcase for LDEV-4320", function() {

          			it(title="testing connection limit", body=function( currentSpec ) {

          				var names="";

          				loop from=1 to=20 index="local.i" {

          					var name="LDEV4320-"&createUniqueID()&"-"&i;

          					names=listAppend(names, name);

          					thread name=name {

          						query {

          							echo("show tables");

          						}

          					}

          				}

I also added a manual github aciton to test with 5.3, as the default action uses 6.0 which uses the Apache Connection pool