Moodle

Oracle cursor leaks (was: Properly close all the recordsets used in code)

Details

  • Type: Bug Bug
  • Status: Closed Closed
  • Priority: Critical Critical
  • Resolution: Not a bug
  • Affects Version/s: 1.8.2, 1.9
  • Fix Version/s: 1.7.4, 1.8.4, 1.9
  • Component/s: Database SQL/XMLDB
  • Labels:
    None
  • Database:
    Any
  • Affected Branches:
    MOODLE_18_STABLE, MOODLE_19_STABLE
  • Fixed Branches:
    MOODLE_17_STABLE, MOODLE_18_STABLE, MOODLE_19_STABLE

Description

== note

We have later found the problem to be related to a bug in the OCI8 driver.

== end - original description follows...

It seems that, until now, we've been relying in the PHP ability, when using not-persistent connections, to close open connections (and associated resources) per request.

And it works more or less okey for http requests (where only "a few" recordsets are opened).

But with more and more queries coming everyday per request, plus some batch processes (like cron, or enrol_database_sync.php or....) it's possible to raise DB limits before finishing the execution.

So, I propose to review:

  • dmllib.php
  • any place using its own recordsets.

ASAP, in order to close all the unclosed recordsets. It will free tons of resources, absolutely!

(Thanks to Iñaki Arenaza by giving me a clue about this important issue, with their Oracle max_cursors problem)

I'd apply fix for both 18_STABLE and HEAD

Any vote/comment? I'll try to start with this tomorrow. Ciao

  1. eloy_test_results.html
    07/Nov/07 7:10 AM
    3 kB
    Eloy Lafuente (stronk7)
  2. oracle_test_cursors.php
    07/Nov/07 5:48 AM
    3 kB
    Iñaki Arenaza
  3. oracle-cursors-problem.tgz
    05/Oct/07 4:33 AM
    12 kB
    Iñaki Arenaza

Activity

Hide
Eloy Lafuente (stronk7) added a comment -

Adding some people here...

Show
Eloy Lafuente (stronk7) added a comment - Adding some people here...
Hide
Iñaki Arenaza added a comment -

+1 for this, obviously

Saludos. Iñaki.

Show
Iñaki Arenaza added a comment - +1 for this, obviously Saludos. Iñaki.
Hide
Martín Langhoff added a comment -

I agree from a clean-and-tidy POV, but I wonder if there's a bug in AdoDB. Have we got any testcase showing that there is actually a problem?

The short version: this is only a problem in the global scope, which is fairly limited. Function scope is fine.

Long version: The recordset "handle" object var must have an appropriate destructor. Local (function / method) scoped recordset handles are unset() at the end of the function/method scope.

Show
Martín Langhoff added a comment - I agree from a clean-and-tidy POV, but I wonder if there's a bug in AdoDB. Have we got any testcase showing that there is actually a problem? The short version: this is only a problem in the global scope, which is fairly limited. Function scope is fine. Long version: The recordset "handle" object var must have an appropriate destructor. Local (function / method) scoped recordset handles are unset() at the end of the function/method scope.
Hide
Eloy Lafuente (stronk7) added a comment -

Uhm, AFAIK, PHP5 calls the destructor automatically when anything falls out of scope... but PHP4 ... no, no, no!

Iñaki.... what PHP version are you using?

Anyway, I really think it's a good idea to close resultsets in a explicit way (ordered Java way, IMO). I really think we only need them in 1-2 places in dmllib and, perhaps, some more uses here and there.

Show
Eloy Lafuente (stronk7) added a comment - Uhm, AFAIK, PHP5 calls the destructor automatically when anything falls out of scope... but PHP4 ... no, no, no! Iñaki.... what PHP version are you using? Anyway, I really think it's a good idea to close resultsets in a explicit way (ordered Java way, IMO). I really think we only need them in 1-2 places in dmllib and, perhaps, some more uses here and there.
Hide
Iñaki Arenaza added a comment -

> Have we got any testcase showing that there is actually a problem?

At least we do. Using Moodle 1.7.2+ (will try with 1.8.2+ this week), on W2003, Apache 2.2.4, PHP 5.2.4, Oracle 10g. With custom patch for course creation from template (but have tried commenting it out, and we're stil able to reproduce it).

Running enrol_database_sync.php with 300+ courses and 300+ students exhausts 3000 open cursors in Oracle before finishing running. In fact, with the default of 300 max. open cursors, we are able to create just 6-8 new courses before running out of cursors.

Even if we don't create new courses, just checking the enrolments consumes more than 300 cursors. We have added some addtional debugging code to show the Oracle current number of open cursors in each iteration of the main loop inside sync_enrolments(), and the cursor usage goes up in each iteration (and never goes down).

We have tried both using persistent and non-persistent connections, but it doesn't make a difference (which is normal, as we do all the work in the same 'page request').

I can provide additional details if needed.

Saludos. Iñaki.

Show
Iñaki Arenaza added a comment - > Have we got any testcase showing that there is actually a problem? At least we do. Using Moodle 1.7.2+ (will try with 1.8.2+ this week), on W2003, Apache 2.2.4, PHP 5.2.4, Oracle 10g. With custom patch for course creation from template (but have tried commenting it out, and we're stil able to reproduce it). Running enrol_database_sync.php with 300+ courses and 300+ students exhausts 3000 open cursors in Oracle before finishing running. In fact, with the default of 300 max. open cursors, we are able to create just 6-8 new courses before running out of cursors. Even if we don't create new courses, just checking the enrolments consumes more than 300 cursors. We have added some addtional debugging code to show the Oracle current number of open cursors in each iteration of the main loop inside sync_enrolments(), and the cursor usage goes up in each iteration (and never goes down). We have tried both using persistent and non-persistent connections, but it doesn't make a difference (which is normal, as we do all the work in the same 'page request'). I can provide additional details if needed. Saludos. Iñaki.
Hide
Eloy Lafuente (stronk7) added a comment -

Hi Iñaki,

apart of the rest of places to be checked... I've been examining enrol_database_sync.php and the underlying sync_enrolments() functions and everything seems to be properly closed there (at least the obvious result sets). Apart from some missing rs_close() that were added in MDL-8134 (Moodle 1.7.1).

Four quick questions:

1) What Oracle lib are you using ? Version? I say this because yesterday I performed some BIG recursive tests using Oracle with OCI = 10g, leaving results set unclosed on purpose and I wasn't able to open more than 10 cursors (the degree of recursion).

2) Can you send me, privately, if you prefer, the complete output of the execution (I hope it'll has some output showing the points of execution).

3) Are you using something like this to count open cursors?

select s.username, a.sid, a.value
from v$sesstat a, v$statname b, v$session s
where a.statistic# = b.statistic#
and s.sid = a.sid
and b.name = 'opened cursors current'
and s.sid = (select sid from v$mystat where rownum = 1)

4) 300 sounds as a really small limit. In a perfect world, with everything closed properly, I can imagine, easily, each request using, say, 5 cursors (it isn't exaggerated, I think). That will allow you one maximum concurrency of 60... just one comment.

All these points apart from the main (general) task of searching and destroying unclosed result sets here and there.

Ciao

Show
Eloy Lafuente (stronk7) added a comment - Hi Iñaki, apart of the rest of places to be checked... I've been examining enrol_database_sync.php and the underlying sync_enrolments() functions and everything seems to be properly closed there (at least the obvious result sets). Apart from some missing rs_close() that were added in MDL-8134 (Moodle 1.7.1). Four quick questions: 1) What Oracle lib are you using ? Version? I say this because yesterday I performed some BIG recursive tests using Oracle with OCI = 10g, leaving results set unclosed on purpose and I wasn't able to open more than 10 cursors (the degree of recursion). 2) Can you send me, privately, if you prefer, the complete output of the execution (I hope it'll has some output showing the points of execution). 3) Are you using something like this to count open cursors? select s.username, a.sid, a.value from v$sesstat a, v$statname b, v$session s where a.statistic# = b.statistic# and s.sid = a.sid and b.name = 'opened cursors current' and s.sid = (select sid from v$mystat where rownum = 1) 4) 300 sounds as a really small limit. In a perfect world, with everything closed properly, I can imagine, easily, each request using, say, 5 cursors (it isn't exaggerated, I think). That will allow you one maximum concurrency of 60... just one comment. All these points apart from the main (general) task of searching and destroying unclosed result sets here and there. Ciao
Hide
Martín Langhoff added a comment - - edited

> I've been examining enrol_database_sync.php and the underlying sync_enrolments()

Yeah, I have given that code a very quick check and nothing suspicious jumpted to my eyes either. Can you try and trace where / why the cursors are being used?

Also - what version of enrol/database are you using? 1.7, 1.8 or the one I've been maintaining? ( I'm cleaning it up for 1.9 – yay!)

Show
Martín Langhoff added a comment - - edited > I've been examining enrol_database_sync.php and the underlying sync_enrolments() Yeah, I have given that code a very quick check and nothing suspicious jumpted to my eyes either. Can you try and trace where / why the cursors are being used? Also - what version of enrol/database are you using? 1.7, 1.8 or the one I've been maintaining? ( I'm cleaning it up for 1.9 – yay!)
Hide
Iñaki Arenaza added a comment -

> 1) What Oracle lib are you using ? Version? I say this because yesterday I performed
> some BIG recursive tests using Oracle with OCI = 10g, leaving results set unclosed on
> purpose and I wasn't able to open more than 10 cursors (the degree of recursion).

The php_oci8.dll that comes with PHP 5.2.4 for Windows (the PHP version with the MSI installer). The file properties say it's version 5.2.4.4. Oracle 10g Enterprise Edition is installed locally on the server, so I guess we are using its client libraries (in case PHP needs them).

We have $CFG->dbtype = 'oci8po'; and $CFG->dbpersist = false; in config.php.

> 2) Can you send me, privately, if you prefer, the complete output of the execution
> (I hope it'll has some output showing the points of execution).

Sure. I'll send you a copy of the code and the execution output.

> 3) Are you using something like this to count open cursors?

$sql = 'SELECT a.NAME, b.sid, b.VALUE
FROM v$statname a, v$mystat b
WHERE a.statistic# = b.statistic#
AND lower(a.NAME) LIKE '."'%cursor%'";
$ns = get_records_sql($sql);
echo "open cursors: " . $ns["opened cursors current"]->value . "\n";

> 300 sounds as a really small limit. In a perfect world, with everything closed properly,
> I can imagine, easily, each request using, say, 5 cursors (it isn't exaggerated, I think).
> That will allow you one maximum concurrency of 60... just one comment.

You are right. But we wanted to hit the limit fast (to be able to debug it easier). We don't mind raising it to 500-1000 later. On the other hand, the server has only 4 GB of RAM, so I guess 60 concurrent users is nearly the limit imposed by the system RAM.

If any of you think this is really not worth it, or just so Oracle specific that reproducing it will be too hard to 'waste' a precious time you might not have now (with 1.9 nearly out of the door), just tell me. We are determined to fix this issue so it doesn't bit us in the back again in the future

Saludos. Iñaki.

Show
Iñaki Arenaza added a comment - > 1) What Oracle lib are you using ? Version? I say this because yesterday I performed > some BIG recursive tests using Oracle with OCI = 10g, leaving results set unclosed on > purpose and I wasn't able to open more than 10 cursors (the degree of recursion). The php_oci8.dll that comes with PHP 5.2.4 for Windows (the PHP version with the MSI installer). The file properties say it's version 5.2.4.4. Oracle 10g Enterprise Edition is installed locally on the server, so I guess we are using its client libraries (in case PHP needs them). We have $CFG->dbtype = 'oci8po'; and $CFG->dbpersist = false; in config.php. > 2) Can you send me, privately, if you prefer, the complete output of the execution > (I hope it'll has some output showing the points of execution). Sure. I'll send you a copy of the code and the execution output. > 3) Are you using something like this to count open cursors? $sql = 'SELECT a.NAME, b.sid, b.VALUE FROM v$statname a, v$mystat b WHERE a.statistic# = b.statistic# AND lower(a.NAME) LIKE '."'%cursor%'"; $ns = get_records_sql($sql); echo "open cursors: " . $ns["opened cursors current"]->value . "\n"; > 300 sounds as a really small limit. In a perfect world, with everything closed properly, > I can imagine, easily, each request using, say, 5 cursors (it isn't exaggerated, I think). > That will allow you one maximum concurrency of 60... just one comment. You are right. But we wanted to hit the limit fast (to be able to debug it easier). We don't mind raising it to 500-1000 later. On the other hand, the server has only 4 GB of RAM, so I guess 60 concurrent users is nearly the limit imposed by the system RAM. If any of you think this is really not worth it, or just so Oracle specific that reproducing it will be too hard to 'waste' a precious time you might not have now (with 1.9 nearly out of the door), just tell me. We are determined to fix this issue so it doesn't bit us in the back again in the future Saludos. Iñaki.
Hide
Iñaki Arenaza added a comment -

> Can you try and trace where / why the cursors are being used?

> what version of enrol/database are you using? 1.7, 1.8 or the one I've been maintaining? ( I'm cleaning it up for 1.9 – yay!)

Neither of them . It's the 1.8 one, plus the patch I maintain at http://orodruin.escomposlinux.org/~iarenaza/moodle/enrol_database/ for public consumption, plus the code we are developing in-house to auto-create courses with content cloning from a course template.

I don't have a copy at hand (I'm not the one developing the code, I just give them a hand when they ask me), but when I helped them debug the cursors issue, we commented all of this auto-creation code out. Not that it matters too much, as this code uses a differente Oracle database in a different server to pull its data, so it can't/shouldn't waste any cursors from the Moodle Oracle database.

I've been a bit busy this week, but I plan to have a couple of free hours tomorrow, so I'll try to get a copy of the code, clean it a bit (there is lots of code commented out, just to echo different things to debug it easier) and publish it somewhere so you can have a look at it.

Saludos. Iñaki.

Show
Iñaki Arenaza added a comment - > Can you try and trace where / why the cursors are being used? > what version of enrol/database are you using? 1.7, 1.8 or the one I've been maintaining? ( I'm cleaning it up for 1.9 – yay!) Neither of them . It's the 1.8 one, plus the patch I maintain at http://orodruin.escomposlinux.org/~iarenaza/moodle/enrol_database/ for public consumption, plus the code we are developing in-house to auto-create courses with content cloning from a course template. I don't have a copy at hand (I'm not the one developing the code, I just give them a hand when they ask me), but when I helped them debug the cursors issue, we commented all of this auto-creation code out. Not that it matters too much, as this code uses a differente Oracle database in a different server to pull its data, so it can't/shouldn't waste any cursors from the Moodle Oracle database. I've been a bit busy this week, but I plan to have a couple of free hours tomorrow, so I'll try to get a copy of the code, clean it a bit (there is lots of code commented out, just to echo different things to debug it easier) and publish it somewhere so you can have a look at it. Saludos. Iñaki.
Hide
Martín Langhoff added a comment -

Iñaki, I agree that we need to fix it, I'm asking more about it because it looks like we are closing things nicely, but there's some other bug lurking somewhere... so rs_close() won't fix the problem.

We need to diagnose what it actually is.

> All these points apart from the main (general) task of searching and destroying unclosed result sets here and there.

You mean that if you fix a missing rs_close(), things do improve...?

Show
Martín Langhoff added a comment - Iñaki, I agree that we need to fix it, I'm asking more about it because it looks like we are closing things nicely, but there's some other bug lurking somewhere... so rs_close() won't fix the problem. We need to diagnose what it actually is. > All these points apart from the main (general) task of searching and destroying unclosed result sets here and there. You mean that if you fix a missing rs_close(), things do improve...?
Hide
Iñaki Arenaza added a comment -

It's been a really busy couple of weeks here, so I didn't have the chance to test this thing any further or upload the files somewhere. But I've had a little time today to at least pack the relevant files, and I'll attach a .tar.gz archive to the bug so anyone can have a look at it.

There is a README inside the archive that explains what the other files are, and what we've done so far. I haven't done a full audit of the code (just a cursory review, as I didn't have much time), but the code inside create_course() shouldn't be the source of the problem, as we commented out the calls to that function in one of the runs, and the results were the same.

I've wrapped all the non-standard code in sync_enrolments() function inside '/// — iarenaza ---' markers. Then there is an addition get_course_details() function that is part of our 'enhanced ext db' patch, but that shouldn't leak cursors either (unless the call to get_field() core function is doing it).

As always, feel free to request any additional details you may need.

Saludos. Iñaki.

Show
Iñaki Arenaza added a comment - It's been a really busy couple of weeks here, so I didn't have the chance to test this thing any further or upload the files somewhere. But I've had a little time today to at least pack the relevant files, and I'll attach a .tar.gz archive to the bug so anyone can have a look at it. There is a README inside the archive that explains what the other files are, and what we've done so far. I haven't done a full audit of the code (just a cursory review, as I didn't have much time), but the code inside create_course() shouldn't be the source of the problem, as we commented out the calls to that function in one of the runs, and the results were the same. I've wrapped all the non-standard code in sync_enrolments() function inside '/// — iarenaza ---' markers. Then there is an addition get_course_details() function that is part of our 'enhanced ext db' patch, but that shouldn't leak cursors either (unless the call to get_field() core function is doing it). As always, feel free to request any additional details you may need. Saludos. Iñaki.
Hide
Iñaki Arenaza added a comment -

I've had a little email exchange with Martin L and other people
@catalyst, that might shed some light into this issue. I'm pasting the
relevant parts of the emails, and attaching the script file I
reference in one of the mails (to make this comment shorter

Saludos. Iñaki.

<<<<<<<< From Iñaki Arenaza @mondragon.edu >>>>>>>

Hi all,

>>From I could see during my testing yesterday, the 'maximum open
>cursors exceeded' message is appearing when an user (an ordinary
>staff member, ie in legacy student role) first logs in. We're
>using SSO and ldap

I've had a couple of spare hours today and have found a couple of
surprising things. I'm using Moodle 1.8.3+, Apache 2.2.4, PHP
2.5.4, Oracle 10g, running on the same host, under Windows
2003 R2. I'm using this config.php file:

======================< config.ph >=====================
<?php /// Moodle Configuration File

unset($CFG);

$CFG->dbtype = 'oci8po';
$CFG->dbhost = '';
$CFG->dbname = 'moodle';
$CFG->dbuser = 'moodle_user';
$CFG->dbpass = 'moodle_password';
$CFG->dbpersist = false;
$CFG->prefix = 'm_';

$CFG->wwwroot = 'http://localhost/devel';
$CFG->dirroot = 'D:\web\moodle\devel';
$CFG->dataroot = 'D:\web\moodledata\devel';
$CFG->admin = 'admin';

$CFG->directorypermissions = 00777; // try 02777 on a server in Safe Mode

require_once("$CFG->dirroot/lib/setup.php");
// MAKE SURE WHEN YOU EDIT THIS FILE THAT THERE ARE NO SPACES, BLANK LINES,
// RETURNS, OR ANYTHING ELSE AFTER THE TWO CHARACTERS ON THE NEXT LINE.
?>
======================< config.ph >=====================

I've used the following script to try to debug the issue. There is
a lot of ripped code from lib/setup.php, in order to be able to
disconnect and reconnect to the Oracle database (to see if that
has any impact on cursor usage at all). I've also tried to disable
all record caching inside Moodle (but may have failed, I don't
know all the internal details of the caching system). See below
for a couple of interesting facts.

--< see attached oracle_test_cursors.php file >--

This is the output I get:

========================< Execution output >=====================
1.- Iteration. Oracle open cursors: 7
2.- Iteration. Oracle open cursors: 8
3.- Iteration. Oracle open cursors: 9
4.- Iteration. Oracle open cursors: 10
5.- Iteration. Oracle open cursors: 11
6.- Iteration. Oracle open cursors: 12
7.- Iteration. Oracle open cursors: 13
8.- Iteration. Oracle open cursors: 14
9.- Iteration. Oracle open cursors: 15
10.- Iteration. Oracle open cursors: 16
object Object
(
[dbqueries] => 20
[logwrites] => 0
[starttime] => 0.99591800 1193573749
[startmemory] => 284104
)

1.- Iteration. Oracle open cursors: 17
2.- Iteration. Oracle open cursors: 17
3.- Iteration. Oracle open cursors: 17
4.- Iteration. Oracle open cursors: 17
5.- Iteration. Oracle open cursors: 17
6.- Iteration. Oracle open cursors: 17
7.- Iteration. Oracle open cursors: 17
8.- Iteration. Oracle open cursors: 17
9.- Iteration. Oracle open cursors: 17
10.- Iteration. Oracle open cursors: 17
object Object
(
[dbqueries] => 40
[logwrites] => 0
[starttime] => 0.99591800 1193573749
[startmemory] => 284104
)

1.- Iteration. Oracle open cursors: 7
2.- Iteration. Oracle open cursors: 8
3.- Iteration. Oracle open cursors: 9
4.- Iteration. Oracle open cursors: 10
5.- Iteration. Oracle open cursors: 11
6.- Iteration. Oracle open cursors: 12
7.- Iteration. Oracle open cursors: 13
8.- Iteration. Oracle open cursors: 14
9.- Iteration. Oracle open cursors: 15
10.- Iteration. Oracle open cursors: 16
object Object
(
[dbqueries] => 61
[logwrites] => 0
[starttime] => 0.99591800 1193573749
[startmemory] => 284104
)

1.- Iteration. Oracle open cursors: 17
2.- Iteration. Oracle open cursors: 17
3.- Iteration. Oracle open cursors: 17
4.- Iteration. Oracle open cursors: 17
5.- Iteration. Oracle open cursors: 17
6.- Iteration. Oracle open cursors: 17
7.- Iteration. Oracle open cursors: 17
8.- Iteration. Oracle open cursors: 17
9.- Iteration. Oracle open cursors: 17
10.- Iteration. Oracle open cursors: 17
object Object
(
[dbqueries] => 81
[logwrites] => 0
[starttime] => 0.99591800 1193573749
[startmemory] => 284104
)
===================< Execution output >==================

There are a couple of surprising things:

  • Cursor closing doesn't seem to have any effect at all (see the
    numbers above).
  • get_recordset('roles') and get_recordset('roles', 'shortname', '*')
    have completely different cursor usage !?!?!?!?
  • closing the connection and opening a new one seems to make a
    difference. Beware, you need to use NConnect to get a brand new
    connection!!! Otherwise the OCI8 driver reuses the existing
    conection and cursor usage doesn't drop at all (just change
    $db->NConnect to $db->Connect and see it by yourself).

I don't know whose to blame here: adodb, the PHP OCI8 driver or
Oracle itself.

<<<<<<<<<< From Martin L @catalyst >>>>>>>>>>

> There are a couple of surprising things:

Crazy things!

> - Cursor closing doesn't seem to have any effect at all (see the
> numbers above).

Hmmm. I suspected that the closing of handles wouldn't be to
blame. My gut feeling is that there's something more subtle
happening...

> - get_recordset('roles') and get_recordset('roles', 'shortname', '*')
> have completely different cursor usage !?!?!?!?

I suspect AdoDB strangeness - for some things like inserts/updates
AdoDB and dmllib are definitely running queries behind our backs
to decide what the table schema looks like. Perhaps something
similar happens with get_recordset() somewhere in the pipeline?

I'm offline right now (on the plane to welly) but I am wondering
what's the lowest level of debug output. I really like tailing the
Pg log set to "log all statements", but I don't think Oracle has
anything equivalent.

At the oci8 driver on the PHP side, I can't see any setting in
stock standard php.ini - but perhaps running strings on oci8.so
gives us a hint or two (don't have php5-oci8 installed here ATM).

If nothing else works - ethereal and a debugger might help :-/

Hmmmm. Does disabling statement caching help?
oci8.statement_cache_size in php.ini ...

> - closing the connection and opening a new one seems to make a
> difference. Beware, you need to use NConnect to get a brand new

that's a good hint - (btw, there's an option in php.ini to control this
as well...)

> I don't know whose to blame here: adodb, the PHP OCI8 driver or Oracle
> itself.

I'd say AdoDB, or the driver. But at least we are seeing it
consistently on several different rigs, and different versions of
things. Jonathan s working on a SuSE 8 or 9, and you're probably
on Debian Etch. right?

We should document exact PHP, driver and Oracle versions.

> I hope this helps tracking the issue. Martin, do you think I should add
> all this to the Moodle bug tracker?

Yes - not sure how we fell into private email. Just as good as I'm
on the plane, but Eloy's input on this would be invaluable.

<<<<<<<< End of email exchange >>>>>>>>>

Show
Iñaki Arenaza added a comment - I've had a little email exchange with Martin L and other people @catalyst, that might shed some light into this issue. I'm pasting the relevant parts of the emails, and attaching the script file I reference in one of the mails (to make this comment shorter Saludos. Iñaki. <<<<<<<< From Iñaki Arenaza @mondragon.edu >>>>>>> Hi all, >>From I could see during my testing yesterday, the 'maximum open >cursors exceeded' message is appearing when an user (an ordinary >staff member, ie in legacy student role) first logs in. We're >using SSO and ldap I've had a couple of spare hours today and have found a couple of surprising things. I'm using Moodle 1.8.3+, Apache 2.2.4, PHP 2.5.4, Oracle 10g, running on the same host, under Windows 2003 R2. I'm using this config.php file: ======================< config.ph >===================== <?php /// Moodle Configuration File unset($CFG); $CFG->dbtype = 'oci8po'; $CFG->dbhost = ''; $CFG->dbname = 'moodle'; $CFG->dbuser = 'moodle_user'; $CFG->dbpass = 'moodle_password'; $CFG->dbpersist = false; $CFG->prefix = 'm_'; $CFG->wwwroot = 'http://localhost/devel'; $CFG->dirroot = 'D:\web\moodle\devel'; $CFG->dataroot = 'D:\web\moodledata\devel'; $CFG->admin = 'admin'; $CFG->directorypermissions = 00777; // try 02777 on a server in Safe Mode require_once("$CFG->dirroot/lib/setup.php"); // MAKE SURE WHEN YOU EDIT THIS FILE THAT THERE ARE NO SPACES, BLANK LINES, // RETURNS, OR ANYTHING ELSE AFTER THE TWO CHARACTERS ON THE NEXT LINE. ?> ======================< config.ph >===================== I've used the following script to try to debug the issue. There is a lot of ripped code from lib/setup.php, in order to be able to disconnect and reconnect to the Oracle database (to see if that has any impact on cursor usage at all). I've also tried to disable all record caching inside Moodle (but may have failed, I don't know all the internal details of the caching system). See below for a couple of interesting facts. --< see attached oracle_test_cursors.php file >-- This is the output I get: ========================< Execution output >===================== 1.- Iteration. Oracle open cursors: 7 2.- Iteration. Oracle open cursors: 8 3.- Iteration. Oracle open cursors: 9 4.- Iteration. Oracle open cursors: 10 5.- Iteration. Oracle open cursors: 11 6.- Iteration. Oracle open cursors: 12 7.- Iteration. Oracle open cursors: 13 8.- Iteration. Oracle open cursors: 14 9.- Iteration. Oracle open cursors: 15 10.- Iteration. Oracle open cursors: 16 object Object ( [dbqueries] => 20 [logwrites] => 0 [starttime] => 0.99591800 1193573749 [startmemory] => 284104 ) 1.- Iteration. Oracle open cursors: 17 2.- Iteration. Oracle open cursors: 17 3.- Iteration. Oracle open cursors: 17 4.- Iteration. Oracle open cursors: 17 5.- Iteration. Oracle open cursors: 17 6.- Iteration. Oracle open cursors: 17 7.- Iteration. Oracle open cursors: 17 8.- Iteration. Oracle open cursors: 17 9.- Iteration. Oracle open cursors: 17 10.- Iteration. Oracle open cursors: 17 object Object ( [dbqueries] => 40 [logwrites] => 0 [starttime] => 0.99591800 1193573749 [startmemory] => 284104 ) 1.- Iteration. Oracle open cursors: 7 2.- Iteration. Oracle open cursors: 8 3.- Iteration. Oracle open cursors: 9 4.- Iteration. Oracle open cursors: 10 5.- Iteration. Oracle open cursors: 11 6.- Iteration. Oracle open cursors: 12 7.- Iteration. Oracle open cursors: 13 8.- Iteration. Oracle open cursors: 14 9.- Iteration. Oracle open cursors: 15 10.- Iteration. Oracle open cursors: 16 object Object ( [dbqueries] => 61 [logwrites] => 0 [starttime] => 0.99591800 1193573749 [startmemory] => 284104 ) 1.- Iteration. Oracle open cursors: 17 2.- Iteration. Oracle open cursors: 17 3.- Iteration. Oracle open cursors: 17 4.- Iteration. Oracle open cursors: 17 5.- Iteration. Oracle open cursors: 17 6.- Iteration. Oracle open cursors: 17 7.- Iteration. Oracle open cursors: 17 8.- Iteration. Oracle open cursors: 17 9.- Iteration. Oracle open cursors: 17 10.- Iteration. Oracle open cursors: 17 object Object ( [dbqueries] => 81 [logwrites] => 0 [starttime] => 0.99591800 1193573749 [startmemory] => 284104 ) ===================< Execution output >================== There are a couple of surprising things:
  • Cursor closing doesn't seem to have any effect at all (see the numbers above).
  • get_recordset('roles') and get_recordset('roles', 'shortname', '*') have completely different cursor usage !?!?!?!?
  • closing the connection and opening a new one seems to make a difference. Beware, you need to use NConnect to get a brand new connection!!! Otherwise the OCI8 driver reuses the existing conection and cursor usage doesn't drop at all (just change $db->NConnect to $db->Connect and see it by yourself).
I don't know whose to blame here: adodb, the PHP OCI8 driver or Oracle itself. <<<<<<<<<< From Martin L @catalyst >>>>>>>>>> > There are a couple of surprising things: Crazy things! > - Cursor closing doesn't seem to have any effect at all (see the > numbers above). Hmmm. I suspected that the closing of handles wouldn't be to blame. My gut feeling is that there's something more subtle happening... > - get_recordset('roles') and get_recordset('roles', 'shortname', '*') > have completely different cursor usage !?!?!?!? I suspect AdoDB strangeness - for some things like inserts/updates AdoDB and dmllib are definitely running queries behind our backs to decide what the table schema looks like. Perhaps something similar happens with get_recordset() somewhere in the pipeline? I'm offline right now (on the plane to welly) but I am wondering what's the lowest level of debug output. I really like tailing the Pg log set to "log all statements", but I don't think Oracle has anything equivalent. At the oci8 driver on the PHP side, I can't see any setting in stock standard php.ini - but perhaps running strings on oci8.so gives us a hint or two (don't have php5-oci8 installed here ATM). If nothing else works - ethereal and a debugger might help :-/ Hmmmm. Does disabling statement caching help? oci8.statement_cache_size in php.ini ... > - closing the connection and opening a new one seems to make a > difference. Beware, you need to use NConnect to get a brand new that's a good hint - (btw, there's an option in php.ini to control this as well...) > I don't know whose to blame here: adodb, the PHP OCI8 driver or Oracle > itself. I'd say AdoDB, or the driver. But at least we are seeing it consistently on several different rigs, and different versions of things. Jonathan s working on a SuSE 8 or 9, and you're probably on Debian Etch. right? We should document exact PHP, driver and Oracle versions. > I hope this helps tracking the issue. Martin, do you think I should add > all this to the Moodle bug tracker? Yes - not sure how we fell into private email. Just as good as I'm on the plane, but Eloy's input on this would be invaluable. <<<<<<<< End of email exchange >>>>>>>>>
Hide
Eloy Lafuente (stronk7) added a comment -

Well,

some weeks ago I performed some tests here, both under PHP4 and PHP5 (running one Debian box against Oracle 10g) and I only detected minor differences in open cursors between both PHP versions. Only PHP5 seemed to close open cursors more "automatically" than PHP4 (when the script ended).

But I wasn't able to find real differences, nor problems.

Apart of that, I thought that we should close as many resultsets as possible (it's IMO a good dev. practice), no matter of PHP own abilities to do that.

And, right now, I've executed the oracle_test_cursors.php script in my server (Apache 2+ PHP 5.2.x + Oracle 10g) and results show "normal" numbers, with open cursors NOT growing and growing continuously (results attached above).

So, the most I think on it, the most I think it's something related with the LAOP (linux, apache, oracle, php) stack, instead of bugs in adodb/moodle code.... I cannot find any other reason for such differences when executing the script.

If, from moodle code we can make anything, let's do it but, from your comments, it seems that only closing and reopening connections causes cursors to be freed, while closing recordsets haven't effect at all. So I've real doubts about being able to perform anything useful from Moodle code. Perhaps we should investigate what LAOP combinations are problematic and why?

Ciao

Show
Eloy Lafuente (stronk7) added a comment - Well, some weeks ago I performed some tests here, both under PHP4 and PHP5 (running one Debian box against Oracle 10g) and I only detected minor differences in open cursors between both PHP versions. Only PHP5 seemed to close open cursors more "automatically" than PHP4 (when the script ended). But I wasn't able to find real differences, nor problems. Apart of that, I thought that we should close as many resultsets as possible (it's IMO a good dev. practice), no matter of PHP own abilities to do that. And, right now, I've executed the oracle_test_cursors.php script in my server (Apache 2+ PHP 5.2.x + Oracle 10g) and results show "normal" numbers, with open cursors NOT growing and growing continuously (results attached above). So, the most I think on it, the most I think it's something related with the LAOP (linux, apache, oracle, php) stack, instead of bugs in adodb/moodle code.... I cannot find any other reason for such differences when executing the script. If, from moodle code we can make anything, let's do it but, from your comments, it seems that only closing and reopening connections causes cursors to be freed, while closing recordsets haven't effect at all. So I've real doubts about being able to perform anything useful from Moodle code. Perhaps we should investigate what LAOP combinations are problematic and why? Ciao
Hide
Iñaki Arenaza added a comment -

> Perhaps we should investigate what LAOP combinations are problematic and why?

Sure!. But the system where I'm doing my tests is a WAOP, not a LAOP. I'll try to setup a test LAOP system and see if I get any differences at all.

Saludos. Iñaki.

Show
Iñaki Arenaza added a comment - > Perhaps we should investigate what LAOP combinations are problematic and why? Sure!. But the system where I'm doing my tests is a WAOP, not a LAOP. I'll try to setup a test LAOP system and see if I get any differences at all. Saludos. Iñaki.
Hide
Eloy Lafuente (stronk7) added a comment -

Great!

I think I'll be able to set a pure WAOP system here too, to see if I can reproduce the problem.

Ciao

Show
Eloy Lafuente (stronk7) added a comment - Great! I think I'll be able to set a pure WAOP system here too, to see if I can reproduce the problem. Ciao
Hide
Martín Langhoff added a comment -

I'm working with Jonathan Newman to debug this as well. Hopefully we'll have a patch with a fix or workaround soon.

Show
Martín Langhoff added a comment - I'm working with Jonathan Newman to debug this as well. Hopefully we'll have a patch with a fix or workaround soon.
Hide
Martín Langhoff added a comment -

Jonathan is testing this but I suspect we found what the problem is.

oci8.statement_cache_size will keep N statements cached per http process, per DB handle. Each cached statement is an open cursor on the DB side, according to slide 40 on this PDF: http://www.oracle.com/technology/tech/php/pdf/oracle-php-performance-presentation.pdf

So a statement_cache_size larger than the number of queries we issue per page will give a performance boost on the PHP side (saving statement preparations) but it eats up cursors on the DB side, specially if there are many Apache+PHP processes.

Iñaki - if this analysis is right, setting oci8.statement_cache_size=0 should help in your case...

Show
Martín Langhoff added a comment - Jonathan is testing this but I suspect we found what the problem is. oci8.statement_cache_size will keep N statements cached per http process, per DB handle. Each cached statement is an open cursor on the DB side, according to slide 40 on this PDF: http://www.oracle.com/technology/tech/php/pdf/oracle-php-performance-presentation.pdf So a statement_cache_size larger than the number of queries we issue per page will give a performance boost on the PHP side (saving statement preparations) but it eats up cursors on the DB side, specially if there are many Apache+PHP processes. Iñaki - if this analysis is right, setting oci8.statement_cache_size=0 should help in your case...
Hide
Jonathan Newman added a comment -

I've just run oracle_test_cursors script on a LOAP setup (Ubuntu, Oracle 10gR2, Apache 2.0.55, PHP 5.1.2) running Moodle 1.8.3 and have confirmed:
1) Cursors continue to increment when we do get_recordset ('role')
2) Cursor closing does not have any affect.
3) Changing setting oci8.statement_cache_size=0 does not affect the number of cursors used.

Below is the output of the script in which the following oci settings are used:

OCI8 Support enabled
Version 1.2.4
Revision $Revision: 1.269.2.16.2.38 $
Active Persistent Connections 0
Active Connections 1
Oracle Instant Client Version 10.2
Temporary Lob support enabled
Collections support enabled

Directive Local Value Master Value
oci8.default_prefetch 100 100
oci8.max_persistent -1 -1
oci8.old_oci_close_semantics 0 0
oci8.persistent_timeout -1 -1
oci8.ping_interval 60 60
oci8.privileged_connect Off Off
oci8.statement_cache_size 0 0

========================< Execution output >=====================

1.- Iteration. Oracle open cursors: 10
2.- Iteration. Oracle open cursors: 11
3.- Iteration. Oracle open cursors: 12
4.- Iteration. Oracle open cursors: 13
5.- Iteration. Oracle open cursors: 14
6.- Iteration. Oracle open cursors: 15
7.- Iteration. Oracle open cursors: 16
8.- Iteration. Oracle open cursors: 17
9.- Iteration. Oracle open cursors: 18
10.- Iteration. Oracle open cursors: 19
object Object
(
[dbqueries] => 22
[logwrites] => 0
[starttime] => 0.27602500 1194497576
[startmemory] => 210456
[startposixtimes] =>
)

1.- Iteration. Oracle open cursors: 20
2.- Iteration. Oracle open cursors: 20
3.- Iteration. Oracle open cursors: 20
4.- Iteration. Oracle open cursors: 20
5.- Iteration. Oracle open cursors: 20
6.- Iteration. Oracle open cursors: 20
7.- Iteration. Oracle open cursors: 20
8.- Iteration. Oracle open cursors: 20
9.- Iteration. Oracle open cursors: 20
10.- Iteration. Oracle open cursors: 20
object Object
(
[dbqueries] => 42
[logwrites] => 0
[starttime] => 0.27602500 1194497576
[startmemory] => 210456
[startposixtimes] =>
)

1.- Iteration. Oracle open cursors: 21
2.- Iteration. Oracle open cursors: 22
3.- Iteration. Oracle open cursors: 23
4.- Iteration. Oracle open cursors: 24
5.- Iteration. Oracle open cursors: 25
6.- Iteration. Oracle open cursors: 26
7.- Iteration. Oracle open cursors: 27
8.- Iteration. Oracle open cursors: 28
9.- Iteration. Oracle open cursors: 29
10.- Iteration. Oracle open cursors: 30
object Object
(
[dbqueries] => 63
[logwrites] => 0
[starttime] => 0.27602500 1194497576
[startmemory] => 210456
[startposixtimes] =>
)

1.- Iteration. Oracle open cursors: 31
2.- Iteration. Oracle open cursors: 31
3.- Iteration. Oracle open cursors: 31
4.- Iteration. Oracle open cursors: 31
5.- Iteration. Oracle open cursors: 31
6.- Iteration. Oracle open cursors: 31
7.- Iteration. Oracle open cursors: 31
8.- Iteration. Oracle open cursors: 31
9.- Iteration. Oracle open cursors: 31
10.- Iteration. Oracle open cursors: 31
object Object
(
[dbqueries] => 83
[logwrites] => 0
[starttime] => 0.27602500 1194497576
[startmemory] => 210456
[startposixtimes] =>
)

========================< Execution output >=====================

I've also confirmed that changing from the dbconnection from Connect to NConnect closes the cursors. Here is the output (same oci settings as listed above):

========================< Execution output >=====================

1.- Iteration. Oracle open cursors: 10
2.- Iteration. Oracle open cursors: 11
3.- Iteration. Oracle open cursors: 12
4.- Iteration. Oracle open cursors: 13
5.- Iteration. Oracle open cursors: 14
6.- Iteration. Oracle open cursors: 15
7.- Iteration. Oracle open cursors: 16
8.- Iteration. Oracle open cursors: 17
9.- Iteration. Oracle open cursors: 18
10.- Iteration. Oracle open cursors: 19
object Object
(
[dbqueries] => 22
[logwrites] => 0
[starttime] => 0.80109600 1194497386
[startmemory] => 210376
[startposixtimes] =>
)

1.- Iteration. Oracle open cursors: 20
2.- Iteration. Oracle open cursors: 20
3.- Iteration. Oracle open cursors: 20
4.- Iteration. Oracle open cursors: 20
5.- Iteration. Oracle open cursors: 20
6.- Iteration. Oracle open cursors: 20
7.- Iteration. Oracle open cursors: 20
8.- Iteration. Oracle open cursors: 20
9.- Iteration. Oracle open cursors: 20
10.- Iteration. Oracle open cursors: 20
object Object
(
[dbqueries] => 42
[logwrites] => 0
[starttime] => 0.80109600 1194497386
[startmemory] => 210376
[startposixtimes] =>
)

1.- Iteration. Oracle open cursors: 7
2.- Iteration. Oracle open cursors: 8
3.- Iteration. Oracle open cursors: 9
4.- Iteration. Oracle open cursors: 10
5.- Iteration. Oracle open cursors: 11
6.- Iteration. Oracle open cursors: 12
7.- Iteration. Oracle open cursors: 13
8.- Iteration. Oracle open cursors: 14
9.- Iteration. Oracle open cursors: 15
10.- Iteration. Oracle open cursors: 16
object Object
(
[dbqueries] => 63
[logwrites] => 0
[starttime] => 0.80109600 1194497386
[startmemory] => 210376
[startposixtimes] =>
)

1.- Iteration. Oracle open cursors: 17
2.- Iteration. Oracle open cursors: 17
3.- Iteration. Oracle open cursors: 17
4.- Iteration. Oracle open cursors: 17
5.- Iteration. Oracle open cursors: 17
6.- Iteration. Oracle open cursors: 17
7.- Iteration. Oracle open cursors: 17
8.- Iteration. Oracle open cursors: 17
9.- Iteration. Oracle open cursors: 17
10.- Iteration. Oracle open cursors: 17
object Object
(
[dbqueries] => 83
[logwrites] => 0
[starttime] => 0.80109600 1194497386
[startmemory] => 210376
[startposixtimes] =>
)

========================< Execution output >=====================

Show
Jonathan Newman added a comment - I've just run oracle_test_cursors script on a LOAP setup (Ubuntu, Oracle 10gR2, Apache 2.0.55, PHP 5.1.2) running Moodle 1.8.3 and have confirmed: 1) Cursors continue to increment when we do get_recordset ('role') 2) Cursor closing does not have any affect. 3) Changing setting oci8.statement_cache_size=0 does not affect the number of cursors used. Below is the output of the script in which the following oci settings are used: OCI8 Support enabled Version 1.2.4 Revision $Revision: 1.269.2.16.2.38 $ Active Persistent Connections 0 Active Connections 1 Oracle Instant Client Version 10.2 Temporary Lob support enabled Collections support enabled Directive Local Value Master Value oci8.default_prefetch 100 100 oci8.max_persistent -1 -1 oci8.old_oci_close_semantics 0 0 oci8.persistent_timeout -1 -1 oci8.ping_interval 60 60 oci8.privileged_connect Off Off oci8.statement_cache_size 0 0 ========================< Execution output >===================== 1.- Iteration. Oracle open cursors: 10 2.- Iteration. Oracle open cursors: 11 3.- Iteration. Oracle open cursors: 12 4.- Iteration. Oracle open cursors: 13 5.- Iteration. Oracle open cursors: 14 6.- Iteration. Oracle open cursors: 15 7.- Iteration. Oracle open cursors: 16 8.- Iteration. Oracle open cursors: 17 9.- Iteration. Oracle open cursors: 18 10.- Iteration. Oracle open cursors: 19 object Object ( [dbqueries] => 22 [logwrites] => 0 [starttime] => 0.27602500 1194497576 [startmemory] => 210456 [startposixtimes] => ) 1.- Iteration. Oracle open cursors: 20 2.- Iteration. Oracle open cursors: 20 3.- Iteration. Oracle open cursors: 20 4.- Iteration. Oracle open cursors: 20 5.- Iteration. Oracle open cursors: 20 6.- Iteration. Oracle open cursors: 20 7.- Iteration. Oracle open cursors: 20 8.- Iteration. Oracle open cursors: 20 9.- Iteration. Oracle open cursors: 20 10.- Iteration. Oracle open cursors: 20 object Object ( [dbqueries] => 42 [logwrites] => 0 [starttime] => 0.27602500 1194497576 [startmemory] => 210456 [startposixtimes] => ) 1.- Iteration. Oracle open cursors: 21 2.- Iteration. Oracle open cursors: 22 3.- Iteration. Oracle open cursors: 23 4.- Iteration. Oracle open cursors: 24 5.- Iteration. Oracle open cursors: 25 6.- Iteration. Oracle open cursors: 26 7.- Iteration. Oracle open cursors: 27 8.- Iteration. Oracle open cursors: 28 9.- Iteration. Oracle open cursors: 29 10.- Iteration. Oracle open cursors: 30 object Object ( [dbqueries] => 63 [logwrites] => 0 [starttime] => 0.27602500 1194497576 [startmemory] => 210456 [startposixtimes] => ) 1.- Iteration. Oracle open cursors: 31 2.- Iteration. Oracle open cursors: 31 3.- Iteration. Oracle open cursors: 31 4.- Iteration. Oracle open cursors: 31 5.- Iteration. Oracle open cursors: 31 6.- Iteration. Oracle open cursors: 31 7.- Iteration. Oracle open cursors: 31 8.- Iteration. Oracle open cursors: 31 9.- Iteration. Oracle open cursors: 31 10.- Iteration. Oracle open cursors: 31 object Object ( [dbqueries] => 83 [logwrites] => 0 [starttime] => 0.27602500 1194497576 [startmemory] => 210456 [startposixtimes] => ) ========================< Execution output >===================== I've also confirmed that changing from the dbconnection from Connect to NConnect closes the cursors. Here is the output (same oci settings as listed above): ========================< Execution output >===================== 1.- Iteration. Oracle open cursors: 10 2.- Iteration. Oracle open cursors: 11 3.- Iteration. Oracle open cursors: 12 4.- Iteration. Oracle open cursors: 13 5.- Iteration. Oracle open cursors: 14 6.- Iteration. Oracle open cursors: 15 7.- Iteration. Oracle open cursors: 16 8.- Iteration. Oracle open cursors: 17 9.- Iteration. Oracle open cursors: 18 10.- Iteration. Oracle open cursors: 19 object Object ( [dbqueries] => 22 [logwrites] => 0 [starttime] => 0.80109600 1194497386 [startmemory] => 210376 [startposixtimes] => ) 1.- Iteration. Oracle open cursors: 20 2.- Iteration. Oracle open cursors: 20 3.- Iteration. Oracle open cursors: 20 4.- Iteration. Oracle open cursors: 20 5.- Iteration. Oracle open cursors: 20 6.- Iteration. Oracle open cursors: 20 7.- Iteration. Oracle open cursors: 20 8.- Iteration. Oracle open cursors: 20 9.- Iteration. Oracle open cursors: 20 10.- Iteration. Oracle open cursors: 20 object Object ( [dbqueries] => 42 [logwrites] => 0 [starttime] => 0.80109600 1194497386 [startmemory] => 210376 [startposixtimes] => ) 1.- Iteration. Oracle open cursors: 7 2.- Iteration. Oracle open cursors: 8 3.- Iteration. Oracle open cursors: 9 4.- Iteration. Oracle open cursors: 10 5.- Iteration. Oracle open cursors: 11 6.- Iteration. Oracle open cursors: 12 7.- Iteration. Oracle open cursors: 13 8.- Iteration. Oracle open cursors: 14 9.- Iteration. Oracle open cursors: 15 10.- Iteration. Oracle open cursors: 16 object Object ( [dbqueries] => 63 [logwrites] => 0 [starttime] => 0.80109600 1194497386 [startmemory] => 210376 [startposixtimes] => ) 1.- Iteration. Oracle open cursors: 17 2.- Iteration. Oracle open cursors: 17 3.- Iteration. Oracle open cursors: 17 4.- Iteration. Oracle open cursors: 17 5.- Iteration. Oracle open cursors: 17 6.- Iteration. Oracle open cursors: 17 7.- Iteration. Oracle open cursors: 17 8.- Iteration. Oracle open cursors: 17 9.- Iteration. Oracle open cursors: 17 10.- Iteration. Oracle open cursors: 17 object Object ( [dbqueries] => 83 [logwrites] => 0 [starttime] => 0.80109600 1194497386 [startmemory] => 210376 [startposixtimes] => ) ========================< Execution output >=====================
Hide
Eloy Lafuente (stronk7) added a comment -

One not-confirmed-at-all guess.... could be one PHP-OCI bug the cause for this?

In my tests with Oracle I use one custom PHP-OCI module, compiled in the server and build over/with the Oracle Instant Client libraries (from Oracle).

Could be possible that pre-compiled packages (windows, linux distros are using another oracle oci libraries to build the PHP-OCI module?).

Just one difference I've in my test servers (where I cannot reproduce the open cursors problem - as attached above).

Ciao

Show
Eloy Lafuente (stronk7) added a comment - One not-confirmed-at-all guess.... could be one PHP-OCI bug the cause for this? In my tests with Oracle I use one custom PHP-OCI module, compiled in the server and build over/with the Oracle Instant Client libraries (from Oracle). Could be possible that pre-compiled packages (windows, linux distros are using another oracle oci libraries to build the PHP-OCI module?). Just one difference I've in my test servers (where I cannot reproduce the open cursors problem - as attached above). Ciao
Hide
Martín Langhoff added a comment -

Narrowing down on this, I think.

First, something that confused me a bit from I~naki's example:

// this line will select all rows where shortname='*' - IOWs, empty resultset
$roles = get_recordset ('role', 'shortname','*');

I managed to narrow it down to the fields that we are selecting, with

// this leaks cursors
$roles = get_recordset ('role','','','','id,name,shortname,description');
// this leaks cursors too
$roles = get_recordset ('role','','','','*');
// this does not leak cursors
$roles = get_recordset ('role','','','','id,name,shortname');

Which is our ever troublesome CLOBs... a bit of googling leads me to http://bugs.php.net/bug.php?id=42496 ...

Show
Martín Langhoff added a comment - Narrowing down on this, I think. First, something that confused me a bit from I~naki's example: // this line will select all rows where shortname='*' - IOWs, empty resultset $roles = get_recordset ('role', 'shortname','*'); I managed to narrow it down to the fields that we are selecting, with // this leaks cursors $roles = get_recordset ('role','','','','id,name,shortname,description'); // this leaks cursors too $roles = get_recordset ('role','','','','*'); // this does not leak cursors $roles = get_recordset ('role','','','','id,name,shortname'); Which is our ever troublesome CLOBs... a bit of googling leads me to http://bugs.php.net/bug.php?id=42496 ...
Hide
Martín Langhoff added a comment -

Narrowed down the problem to the OCI8 driver, which is versioned separately from PHP. After a bit of testing of different versions, the problem appeared in v1.2.4 of OCI8, which got included in PHP v5.2.3

OCI8 v1.2.3 does not exhibit the problem. vOCI8 1.3.0 Beta (as of today) still exhibits the problem. I've reported it on the bugtracker here http://pecl.php.net/bugs/bug.php?id=12407 linking back to this bug.

The different versions of the OCI8 driver are downloadable from http://pecl.php.net/package/oci8 – it would be interesting to check what version Eloy is running - it should say $Revision XXX $ in the phpinfo page...

These are the revisions as reported for the versions I've tested:

grep -r Revision oci8-1.*/oci8.c
oci8-1.1.1/oci8.c: php_info_print_table_row(2, "Revision", "$Revision: 1.274 $");
oci8-1.2.3/oci8.c: php_info_print_table_row(2, "Revision", "$Revision: 1.269.2.16.2.29 $");
oci8-1.2.4/oci8.c: php_info_print_table_row(2, "Revision", "$Revision: 1.269.2.16.2.38 $");
oci8-1.3.0/oci8.c: php_info_print_table_row(2, "Revision", "$Revision: 1.269.2.16.2.38.4.1 $");

Show
Martín Langhoff added a comment - Narrowed down the problem to the OCI8 driver, which is versioned separately from PHP. After a bit of testing of different versions, the problem appeared in v1.2.4 of OCI8, which got included in PHP v5.2.3 OCI8 v1.2.3 does not exhibit the problem. vOCI8 1.3.0 Beta (as of today) still exhibits the problem. I've reported it on the bugtracker here http://pecl.php.net/bugs/bug.php?id=12407 linking back to this bug. The different versions of the OCI8 driver are downloadable from http://pecl.php.net/package/oci8 – it would be interesting to check what version Eloy is running - it should say $Revision XXX $ in the phpinfo page... These are the revisions as reported for the versions I've tested: grep -r Revision oci8-1.*/oci8.c oci8-1.1.1/oci8.c: php_info_print_table_row(2, "Revision", "$Revision: 1.274 $"); oci8-1.2.3/oci8.c: php_info_print_table_row(2, "Revision", "$Revision: 1.269.2.16.2.29 $"); oci8-1.2.4/oci8.c: php_info_print_table_row(2, "Revision", "$Revision: 1.269.2.16.2.38 $"); oci8-1.3.0/oci8.c: php_info_print_table_row(2, "Revision", "$Revision: 1.269.2.16.2.38.4.1 $");
Hide
Eloy Lafuente (stronk7) added a comment -

Confirmed, I'm using:

Oci8 - Version 1.2.3
Oci8 - Revision $Revision: 1.269.2.16.2.29 $
Oracle Instant Client Version 10.2

(all them from my phpinfo page )

Ciao

Show
Eloy Lafuente (stronk7) added a comment - Confirmed, I'm using: Oci8 - Version 1.2.3 Oci8 - Revision $Revision: 1.269.2.16.2.29 $ Oracle Instant Client Version 10.2 (all them from my phpinfo page ) Ciao
Hide
Jonathan Newman added a comment -

The problem also occurs in the latest stable version of oci8 (v1.2.4). The output I reported from my machine yesterday is using:

Oci8 - Version 1.2.4
Oci8 - Revision $Revision: 1.269.2.16.2.38 $
Oracle Instant Client Version 10.2

(all from my phpinfo page)

Show
Jonathan Newman added a comment - The problem also occurs in the latest stable version of oci8 (v1.2.4). The output I reported from my machine yesterday is using: Oci8 - Version 1.2.4 Oci8 - Revision $Revision: 1.269.2.16.2.38 $ Oracle Instant Client Version 10.2 (all from my phpinfo page)
Hide
Iñaki Arenaza added a comment -

Directly from admin/phpinfo.php:

Version 1.2.3
Revision $Revision: 1.269.2.16.2.37 $

There's no mention of the Oracle Instant Client Version at all. ??

Saludos. Iñaki.

Show
Iñaki Arenaza added a comment - Directly from admin/phpinfo.php: Version 1.2.3 Revision $Revision: 1.269.2.16.2.37 $ There's no mention of the Oracle Instant Client Version at all. ?? Saludos. Iñaki.
Hide
Martín Langhoff added a comment -

Iñaki – are you saying that you get the problem even with v1.2.3? The revision is slightly different, so perhaps downgrading might help? I don't know how you'd compile a PECL extension on Win32 unfortunately :-/

Show
Martín Langhoff added a comment - Iñaki – are you saying that you get the problem even with v1.2.3? The revision is slightly different, so perhaps downgrading might help? I don't know how you'd compile a PECL extension on Win32 unfortunately :-/
Hide
Iñaki Arenaza added a comment -

We've downgraded to PHP 5.2.1 today (windows binary .zip package from www.php.net) and the problem has gone away. We've been able to auto-create 250 course in a batch with enrol_database_sync.php, without using more than 30 open cursors at any given time. With PHP 5.2.4 we reached the 300 default maximum with just 6-7 auto-created courses.

The oci8 driver from 5.2.1 shows:

Version: 1.2.3
Revision: $Revision: 1.269.2.16.2.30 $

So this is definetly a regression in the PHP oci8 driver. Great detective job Martin L. and the people at Catalyst!

I'd say we can close this bug and keep an eye on the PECL bug Martin L. has opened, and the associated PHP bug.

Saludos. Iñaki.

Show
Iñaki Arenaza added a comment - We've downgraded to PHP 5.2.1 today (windows binary .zip package from www.php.net) and the problem has gone away. We've been able to auto-create 250 course in a batch with enrol_database_sync.php, without using more than 30 open cursors at any given time. With PHP 5.2.4 we reached the 300 default maximum with just 6-7 auto-created courses. The oci8 driver from 5.2.1 shows: Version: 1.2.3 Revision: $Revision: 1.269.2.16.2.30 $ So this is definetly a regression in the PHP oci8 driver. Great detective job Martin L. and the people at Catalyst! I'd say we can close this bug and keep an eye on the PECL bug Martin L. has opened, and the associated PHP bug. Saludos. Iñaki.
Hide
Martín Langhoff added a comment -

I'm keeping an eye on the PHP bug, and a programmer with an @oracle.com address has been emailing me in private - IOWs there's some interest in this.

I've added some notes here http://docs.moodle.org/en/Installing_Oracle_for_PHP – that page needs some love and care
(there are some good notes on the talk page too)

Show
Martín Langhoff added a comment - I'm keeping an eye on the PHP bug, and a programmer with an @oracle.com address has been emailing me in private - IOWs there's some interest in this. I've added some notes here http://docs.moodle.org/en/Installing_Oracle_for_PHP – that page needs some love and care (there are some good notes on the talk page too)
Hide
Martín Langhoff added a comment -

"Not a moodle bug" at least

Show
Martín Langhoff added a comment - "Not a moodle bug" at least

Dates

  • Created:
    Updated:
    Resolved: