Slow performances on query

[labflow]

Hi,

I'd like to migrate from php/laravel to nestjs. I'm doing some tests with node-odbc to check for any perf issue and I'm facing very slow queries.

Every single/simple query is slow vs it's PDO equivalent. Exemples: Simple query: 160ms for PDO (same with DBeaver) vs 2.5sec node-odbc Much larger query (about 5k lines): 2 seconds PDO vs 40 sec node-odbc.

Both are using the same unixODBC source / 64bits ibm-db2 driver. Debian 9 (tried on Debian 10 also). Node 18. No fancy SQL.

Do you have any idea where I should start digging ? Thank you.

Regards, Thomas

[snotmare]

I also see poor performance vs other connectors (ex: JDBC). Performance seems fine when the code runs on power, but when using odbc on my pc, it's painfully slow. I also see differences of < 1s with jdbc vs > 1 min with odbc.

[kadler]

@labflow Can you give more details about the driver you're using along with the database you're connecting to?

@snotmare What JDBC and ODBC drivers are you using and what database are you connecting to?

[snotmare]

Hello @kadler !

For jdbc, we are using this npm package: https://www.npmjs.com/package/jdbc

It uses a jt400.jar to connect to an ibm db2 database. Our server admin, Mike Bohlen from Duncan Aviation, has also reported this issue through another channel. I'm asking for a better reference to post on here if that helps.

I'm told odbc is quite chatty (even more than jdbc), but I'm hopeful there is something that can be done to improve network performance. When I run on my pc, I'm working from home on a vpn, so it probably exaggerates the issue. Since jdbc still performs quite well over vpn, there's gotta be something we can do to improve odbc.

We are quite interested in switching to use odbc. If there is anything else I can do to help, feel free to reach out to me directly. I'd be willing to hop on a call to figure this out also.

[kadler]

Are you using the IBM i Access driver? If so, they work on the same protocol so they should have roughly the same performance, though certainly there are different options which can be enabled that could affect it.

I'd need a trace of both to compare.

[snotmare]

Yes, my connection string looks like this... let connectionString = Driver={IBM i Access ODBC Driver}; Naming=1; System=${process.env.dbName}; Uid=${process.env.dbId}; Pwd=${process.env.dbPw};

[snotmare]

@kadler Are you asking for a network trace?

[kadler]

@snotmare No, I want driver traces.

jt400 trace: https://www.ibm.com/support/pages/how-enable-jdbc-trace-toolbox-driver (this is for WAS, but you can set the properties any way, eg. from the command line) IBM i Access odbc trace: cwbtrc /dt:1 then find csv trace files in ~/.iSeriesAccess with name cwbdetail64*.csv

[snotmare]

@kadler I was able to do an odbc trace following the instructions on the npm site: https://www.npmjs.com/package/odbc

Open up ODBC Data Source Administrator and select the "Tracing" tab. Enter the location where you want the log file to go in "Log File Path", then click "Start Tracing Now".

I've attached the resulting file. Is this what you're looking for?

SQL.LOG

[kadler]

No. Instructions are in my previous post, though I just remembered that if you're on Windows, the commands are different for ODBC. On Windows, run cwbcotrc ON and then find trace files under C:\Users<user>\Documents\IBM\Client Access\Service\Trace Files

[snotmare]

Ok, I've attached a trace. I'm running a simple sql statement: "select * from [table] limit 100". When the trace is off, this statement runs in 9-10 seconds. With the trace on, it timed out and never completed.

Thanks for your help with this! Let me know if there is anything else you need on this. cwbtrace-64-node.exe-18060.log

[kadler]

@snotmare From the trace, I see 3 connections being made. I'm guessing you're using a pool? None of these connections ever do anything though - your statement is never sent to the server.

I did find a driver bug where it's exchanging client/server attributes, but this only wastes half a second.

Each connection takes about 30-40 seconds for each connection to be made, which does seem like it's pretty slow. Part of that is port mapper, which takes 1s each. Each ODBC connection will connect to the as-signon and the as-database, so that's 1s each just to connect to the port mapper and ask what port the servers are on. These ports are almost always left default, so by switching the lookup mode to "use default ports" you can save 2s for each connection. There used to be a GUI to change this in IBM i Navigator, but AFAIK there's no easy way to set this anymore, just through the registry. The registry key is under Computer\HKEY_CURRENT_USER\SOFTWARE\IBM\Client Access Express\CurrentVersion\Environments\My Connections\<system>\Communication\Port lookup mode - setting this to 2 will use the default ports.

But that really isn't that much compared to the whole 30s. I see lots of delays between calls to the server and I'm not sure why. Perhaps the trace is really slowing things down a lot?

If you give me a jdbc trace I could try to compare the performance. Ideally though, we'd have a more complete ODBC trace where a statement actually gets executed (is there a reason it never completes?).

[snotmare]

@kadler I was able to get an odbc trace with a call in it. I increased my connection timeout and went to lunch, lol. It took a looooong time, but the sql statement I ran finally finished. I've attached the trace. I'm struggling to get a jdbc trace.

It may not like my connection string or something. I'll post it when I can get it to work.

cwbtrace-64-node.exe-29612.log

[snotmare]

@kadler I've got a jdbc trace! One difference between the jdbc and odbc traces is that we are using jdbc to start up our local server. You'll see a couple calls in addition to the one I'm testing. The statement I'm testing is: select * from gppuser limit 100

For jdbc, that finished in about 400ms.

Thanks again for your help!

jdbcTrace.txt

[kadler]

So jdbc is running on the IBM i system, but you're running odbc remotely?

[snotmare]

@kadler We are running both idbc and odbc from a pc and hitting a server remotely. Our current set up is to connect to a db2 database with jdbc from a pc, but when running on our dev or prod server, we use idb. We would like to use odbc for both pc and server.

[kadler]

Ok, I just wanted to make sure this is an apples to apples comparison.

Looks like the JDBC trace was insufficient as I need a datastream trace. Can you please re-run with com.ibm.as400.access.Trace.category=all. FYI, I found a better guide for JDBC tracing here: https://www.ibm.com/support/pages/all-one-toolbox-tracing-guide

[kadler]

Maybe it doesn't matter about the datastream trace. I am seeing massive performance issues with your ODBC trace. It takes about 11 seconds from the start of the trace to the start of the first TCP:connect. On my laptop (Lenovo T470), this takes about 50ms. That's about 200x slower than mine, ouch. Perhaps you have some invasive security software mucking things up that doesn't seem to affect java for some reason?

[kadler]

One thing I did notice is that each row is fetched one at a time. This requires a round-trip to the server for each row fetched, which will impact performance and it's better to use a block fetch instead. While node-odbc doesn't support block fetch, the IBM i Access driver supports internal blocking - it will fetch blocks of rows then hand them back one at a time. However, this is disabled when using scrollable cursors like node-odbc uses (SQL_CURSOR_STATIC). From your JDBC trace I can see that it is set to fetch blocks of 512K (block size = "512") unless FOR UPDATE is specified on the statement (block criteria = "2"). The default behavior for the ODBC driver is to use 256K blocks, so it should be close in performance if the internal blocking wasn't being disabled by the cursor type.

I'm not sure why node-odbc is using a scrollable cursor, since it offers no way to scroll. Likely this should be changed to SQL_CURSOR_FORWARD_ONLY, but that's the default so it shouldn't need to be set anyway. The change to set the cursor type was made in #161 but there was no mention of why the change was made, so I'm checking with @markdirish.

[snotmare]

@kadler That sounds promising. Thank you for checking on it! If you decide to change that behavior, I would be happy to test it out.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[snotmare]

Any updates on this? Just didn't want this to be closed because it's stale.

[markdirish]

@snotmare ,

I have remove the explicit setting of CURSOR_TYPE to SQL_CURSOR_STATIC in a beta-tagged release of the package. You should be able to install it with:

npm install odbc@beta

Everything else in the package is completely unchanged, so any difference in performance should be the result of @kadler's suggestion. Hopefully it's a silver bullet!

[snotmare]

@markdirish Good news!

I've updated to the beta version as you suggested and reran my tests. After testing multiple scenarios, I've found that not only did this change resolve the performance issue, ODBC now performs faster than JDBC on my machine when remoting from home. The more rows I return, the greater the difference.

For example, returning 10,000 rows with about 20 columns took 10 seconds with JDBC. ODBC took 6.8 seconds.

Thank you for making this change!

[markdirish]

Love to hear it! I'll try to get an official latest release out later today!

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[markdirish]

Ope! This should be fixed in the latest version (2.4.7) available on npm!

npm install odbc@latest

[KerimG]

@snotmare

How did you get that performance gain, if I may ask? I have an extremely simple query with 100 rows and 3 columns and it takes me ODBC connection a whopping 1.556s while it's instantaneous through Run SQL Scripts in ACS.

[KerimG]

@kadler

Could you please take a look at my odbc trace and perhaps give me a hint what's wrong with my connection? I am querying the a table function to get current active jobs (see image) and it consistently takes 10 times less than through odbc:

cwbtrace-64-node.exe-12932.log

[snotmare]

@snotmare

How did you get that performance gain, if I may ask? I have an extremely simple query with 100 rows and 3 columns and it takes me ODBC connection a whopping 1.556s while it's instantaneous through Run SQL Scripts in ACS.

Hello! I simply updated to the version mentioned above. Maybe that will help you?