node-oracledb icon indicating copy to clipboard operation
node-oracledb copied to clipboard

Memory leak with getRows()

Open lkiii opened this issue 6 years ago • 62 comments

  1. Is it an error or a hang or a crash? Out of memory. RAM usage.
  2. What error(s) you are seeing? This output is visible after ~20 http rest api calls to the server and each request accesses database via oracledb.
rss: " 1158.07 MB"
heapTotal: " 65.07 MB"
heapUsed: " 42.65 MB"
external: " 1.34 MB"
  1. Include a runnable Node.js script that shows the problem. I am closing all the connections and triggering garbage collector manually. oracledb is used to call stored procedures and functions with object binds. I am using connection.getDbObjectClass() for the binds and I suspect this could be the cause of the memory issues. It seems that all the issues have started after upgrading to this approach.
  2. Run node and show the output of:
> process.platform
'linux'
> process.version
'v12.14.0'
> process.arch
'x64'
> require('oracledb').versionString
'4.1.0'
> require('oracledb').oracleClientVersionString
'18.3.0.0.0'
  1. What is your Oracle Database version? 12c

Here is the backstory, how I have come to a conclusion that this is oracledb related issue https://github.com/nodejs/help/issues/2393

lkiii avatar Jan 07 '20 22:01 lkiii

We're still going to need a runnable script that demonstrates the problem; otherwise, we are just guessing! There is a known issue with connection.getDbObjectClass() which has not yet been fixed in Node.js (see here) but there might be something else that requires further attention. Please provide a runnable script. Thanks!

anthony-tuininga avatar Jan 07 '20 22:01 anthony-tuininga

I will try to replicate the issue with a small example. It is a part of a custom framework and I need some time to try isolating the issue.

Is there any known workaround on how to force memory release?

lkiii avatar Jan 07 '20 23:01 lkiii

Also, look through this issue: https://github.com/oracle/node-oracledb/issues/1186

In the last message from @zymon, he provides a link to an excel document with memory usage analysis from before and after he implemented the changes I suggested. Before the changes, there was an unreasonable amount of RSS memory consumed.

The changes mostly had to do with the way the JavaScript code worked with connections from the database. For example, don't use Promise.all with database connections. Do you know if you're using Promise.all with database connections?

dmcghan avatar Jan 07 '20 23:01 dmcghan

No there is no Promise.all nowhere in the project. I will try to get back with the code example tomorrow morning.

One http request is qual to one database call at most of the cases. Here is the simple representation of the flow of the application: HTTP request -> oracle connect -> getDbObjectClass -> prepare binds -> execute -> get results from cursor (getRows() cursor is being closed after reading the data) -> HTTP response -> oracle connection close

lkiii avatar Jan 07 '20 23:01 lkiii

That was just a lucky guess. :) There are lots of other ways this could happen.

Could you please share some code with us? Maybe just edit any sensitive parts out?

dmcghan avatar Jan 07 '20 23:01 dmcghan

@dmcghan @anthony-tuininga I have already prepared a test case: app.zip

To start the application you need to:

  1. cp config\config.example.json config\config.json and change config.json values for database:
   "db": {
        "user": "aaa",
        "password": "aaa",
        "connectString": "192.168.1.1/SID",
        .....
  1. prepare a database with the types and package from database.sql
  2. npm install
  3. npm run build
  4. npm run start
  5. Send http get requests to:
localhost:8081/v1/number-table
localhost:8081/v1/string-table
localhost:8081/v1/object-table

You will see memory usage statistics inside each response

lkiii avatar Jan 08 '20 14:01 lkiii

The first thing that jumps out at me, if I'm reading the code correctly, is that you're creating a single connection to the database and caching that in your database module. I can see how this may be the source of the trouble.

You'll need to switch to using a connection pool. Update execute so that it gets connections from the pool, uses them, and then releases them. See the simpleExecute method in this post for an example: https://jsao.io/2018/03/creating-a-rest-api-database-basics/

Get rid of methods like commit and rollback, which don't add anything - just use the methods on the connection.

If possible, get rid of setTimeDateLocaleParameters in favor of using the environment variables ORA_SDTZ and NLS_DATE_FORMAT. See the doc here: https://oracle.github.io/node-oracledb/doc/api.html#-15163-fetching-dates-and-timestamps

This will be more important as you move to a connection pool as you don't want to incur two round trips (one per execute) to set these values. There are other options if you can't use environment variables for some reason.

Make those changes and test again. Let us know how it goes.

dmcghan avatar Jan 08 '20 14:01 dmcghan

@dmcghan Thank you for the response. The connection pool is already in our to-do list. I do totally agree that it would be more efficient, but I think that the issue is with connection.getDbObjectClass() because even a single request to the freshly started server has huge rss usage.

Also, the current issue has only appeared after upgrading to binding approach. Before that, the same application used oracledb V3.x and we haven't had rss ram issues.

lkiii avatar Jan 08 '20 15:01 lkiii

The connection pool is already in our to-do list.

Please try to escalate this ASAP. The current implementation is all kinds of wrong.

because even a single request to the freshly started server has huge rss usage.

Ah, that is interesting. Are you calling this for a lot of classes?

Now that you have a test case, you should be able to test this, no? Find out which classes you're calling the method for (hopefully there's just a few) and get the values it's returning.

Then update the function so that it doesn't actually call the method - just return the values based on the string passed in.

dmcghan avatar Jan 08 '20 15:01 dmcghan

@dmcghan I have recreated the same case without any binds except cursor output and the leak is still there. It is almost visible, but still there. It seems that you will be right regarding leak origin being creating new database connection on each request and then closing it after request. This seems to be another issue, but the connection pool might solve this.

I will upgrade connection handling and let you know about the results.

lkiii avatar Jan 08 '20 20:01 lkiii

I wouldn't expect to see the RSS issues when creating one-off connections for each request. Though I would expect performance to suck. Use a pool! :)

I'm still new to your code, and I'm not a TS person, but from what I see, generalDBGetHandler creates a new instance of CallParameters. CallParameters uses the OracleDBHelper class, but doesn't create a new instance.

The only method that creates a new instance of OracleDBHelper is initiateDatabase, which I think happens only once. Nothing else calls oracledb.getConnection, so I'm assuming you're sharing a single connection across multiple requests. That's what has me cringing. Again, creating new connections per request is bad for various reasons, but sharing a single connection amongst many connections is also bad, just for different reasons.

Update your code to use a pool and let us know what happens.

dmcghan avatar Jan 08 '20 21:01 dmcghan

I'm still new to your code, and I'm not a TS person, but from what I see, generalDBGetHandler creates a new instance of CallParameters. CallParameters uses the OracleDBHelper class, but doesn't create a new instance.

OracleDBHelper is being created on each http request, it means each time a new connection is being created. After http response is sent connection is being closed. So this still should not have any memory issues.

I wouldn't expect to see the RSS issues when creating one-off connections for each request. Though I would expect performance to suck. Use a pool! :)

The pool priority went up after your comments and will be implemented soon. But there is a memory leak still somewhere with single instance creation even if pool will resolve the issues.

lkiii avatar Jan 08 '20 21:01 lkiii

OracleDBHelper is being created on each http request

I believe you, but please point out the files and relevant lines.

dmcghan avatar Jan 08 '20 21:01 dmcghan

OracleDBHelper is being created on each http request

I believe you, but please point out the files and relevant lines.

Create connection: App.ts:80 await req.database.initialize() creates new connection before each request handler and sets the value to http request object. Then in the request handler same connection is being used as part of OracleDBHelper to execute, getDbObjectClass, etc.

Close connection: App.ts:124 this happens after each request both on success and error.

lkiii avatar Jan 08 '20 22:01 lkiii

I see, so App.ts line 69 is being invoked per request. The name initiateDatabase is deceiving.

But this does mean that you're creating a request for each http request and then invoking execute twice just to initialize some session settings (ORA_SDTZ and NLS_DATE_FORMAT). While this is bad, I don't see how it would be responsible for the RSS issues.

Please update the code and let us know how things afterward.

dmcghan avatar Jan 08 '20 22:01 dmcghan

It's worth testing Node.js 13, since the potential fix @anthony-tuininga pointed to only just landed in a Node.js 12 code line last night: https://github.com/nodejs/node/pull/30109

cjbj avatar Jan 08 '20 23:01 cjbj

@dmcghan @cjbj I have implemented connection pool and rss ram usage decreased around 30% but this is still way above what is expected. Is there anything I could do to help to find a solution for this issue?

Also, I have tried updating node to V12.14.1 and this had 0 impact on the issue.

The issue is clearly related to getDbObjectClass() because I have done a test when I have converted SQL + binds to SQL (i.e. ("select * from a where a = :a", {a:'a1'}) to ("select * from a where a = ''a1", {})) without binds and the issue was still there.

I am building a new docker image with node V13.x and I will let you know about the results.

lkiii avatar Jan 09 '20 19:01 lkiii

@lkiii after you've tried Node 13, you could give us a test case (not an app, e.g. give us a single javascript file) and the SQL to create the tables + data. Also run some tests and plot the results to show whether this is a leak over time. Thanks,

cjbj avatar Jan 09 '20 21:01 cjbj

Node v13 had no impact on the RAM issue.

@cjbj Hello, I have provided simple test case. oracletestcase.zip

here is a graph of memory usage image

lkiii avatar Jan 10 '20 11:01 lkiii

@lkiii thanks for that work - but can you remove all the other modules to eliminate them as causes? You'll have to monitor the memory externally.

cjbj avatar Jan 10 '20 23:01 cjbj

@cjbj @dmcghan Hello, Here is latest minimal example with memory issue

Memory usage: It seems that there is a cap on the memory used, but if there is more than one object it stacks and does not get released using massive amounts of memory

image

Memory
0.65
37.67
45.35
48.24
54.1
60.55
65.32
67.31
73.12
54.42
62.58
67.16
71.38
73.35
79.59
85.31
90.34
98.4
105
113.2
113.1
113.2
113.2
113.2
113.6
113.5
114.2
114.2
114.2
114.3

lkiii avatar Jan 13 '20 10:01 lkiii

Hi @lkiii ,

Thanks for the info and the simplified script! I have tried your latest script on Oracle DB 19.5, Instant Client 19.5, Node 12.13, it ran for about 10 hrs. I'm seeing some bumps in the memory but it gets stabilized. I will try some more combinations to keep trying to replicate this. I'll keep you posted.

issue1194

j-antonio-rivera avatar Jan 13 '20 23:01 j-antonio-rivera

@j-antonio-rivera I am getting similar results if running the same script for a long time. Memory goes up and down, but the maximum value is always getting bigger by several megabytes. As I had written before it seems that there is some kind of threshold of memory after which memory usage does not increase so drastically, but the issue is that initial calls use some memory and it seems that it is not being released. I think the same thing happens with each different object so the used memory stacks if different objects are being called. I will try to replicate heavier usage with more different objects from the database.

Also, you could try increasing const OBJECT_SAMPLE_SIZE = 1000000 this should give you more visible increase.

Database version used for tests: Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production

The same behaviour is visible in both docker container with oracle linux and windows environments

lkiii avatar Jan 14 '20 00:01 lkiii

@lkiii then you are not getting similar results, because @j-antonio-rivera didn't see an increase :)

cjbj avatar Jan 14 '20 00:01 cjbj

@lkiii then you are not getting similar results, because @j-antonio-rivera didn't see an increase :)

@cjbj I am trying to tell that you do not need to look for 10 hours. The increase is most severe in several hundred first creations of DBObject and that memory is not being released.

As I mentioned I will try to recreate an example with more different DBOjects.

lkiii avatar Jan 14 '20 00:01 lkiii

@lkiii sounds good! And let us know your exact Oracle client & server versions.

cjbj avatar Jan 14 '20 00:01 cjbj

Server: Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production Client: Tested both 18.3 and 19.5, both gives similar results.

I could also provide docker image with the environment, but the same results are happening on my local windows machine, so the issue seems not to be related to Linux/Windows node differences.

lkiii avatar Jan 14 '20 00:01 lkiii

I had built a test script to confirm my guess regarding multiple types and there is no difference with single dbobject. Trying to create a better test case with an isolated issue.

lkiii avatar Jan 14 '20 11:01 lkiii

confirmation regarding the issue in oracledb https://github.com/nodejs/help/issues/2393#issuecomment-574455333

lkiii avatar Jan 15 '20 08:01 lkiii

@lkiii Confirmation in what way? We know there is > 0 memory being used but so far haven't seen any actual leak.

cjbj avatar Jan 15 '20 10:01 cjbj