Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

node and ibm_db getting slower with each node release #269

Open
amcintyre99 opened this issue May 28, 2017 · 32 comments
Open

node and ibm_db getting slower with each node release #269

amcintyre99 opened this issue May 28, 2017 · 32 comments

Comments

@amcintyre99
Copy link

amcintyre99 commented May 28, 2017

The subject says it all. And original odbc module has same issue.

timings
https://gist.github.com/amcintyre99/87ab958187f30989b816d238d341566d
code
https://gist.github.com/amcintyre99/4d13fbab65e78694accaf81ce95af6b9

db2 v11 on ubuntu 16.04 x64

any thoughts?

@bimalkjha
Copy link
Member

@amcintyre99 If without changing the code of ibm_db, it performs slower with different versions of node.js, means issue is with node.js itself. Also, you already verified with two drivers. So, please open issue with Node. It does not seem an ibm_db issue. Thanks.

@bnoordhuis
Copy link
Contributor

@bimalkjha Unless you or @amcintyre99 can point to specific reasons why it is slower, it is extremely unlikely that anyone at nodejs/node is going to look at it.

(I'm saying this with my node.js maintainer hat on. Not many people have the time or inclination to sift through thousands of lines of third-party C++ code on the off chance that the issue is with node.js and not the third-party module.)

@bimalkjha
Copy link
Member

Well, in that case https://gist.github.com/amcintyre99/4d13fbab65e78694accaf81ce95af6b9 should be updated to distinguish between the time consumed by node.js code and C++ code. Thanks.

@bimalkjha bimalkjha reopened this May 30, 2017
@amcintyre99
Copy link
Author

If someone would tell me how to "distinguish between the time consumed by node.js code and C++ code", I will be glad to rerun the timings.

@bnoordhuis
Copy link
Contributor

You can use perf(1) (see man perf) to get detailed traces:

$ perf record <flags> node --perf_basic_prof script.js
$ perf report --stdio

@amcintyre99
Copy link
Author

amcintyre99 commented May 31, 2017

this was fun
https://gist.github.com/amcintyre99/64bd41217a9e875c19a8f7f0c7fb7211

andrew@sherlock:/dma/odbc_ibm$ node -v
v6.10.3
andrew@sherlock:
/dma/odbc_ibm$ uname -a
Linux sherlock 4.4.0-78-generic #99-Ubuntu SMP Thu Apr 27 15:29:09 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

i'm seeing strike through'ed lines above, not sure why

@amcintyre99
Copy link
Author

amcintyre99 commented May 31, 2017

also used the node profiler and got this
https://gist.github.com/amcintyre99/465514ff05ea8740d96162e2dc79f39b

here is the summary section followed by the first line of C++ section

[Summary]:
   ticks  total  nonlib   name
    291    0.8%    1.5%  JavaScript
  16269   43.4%   85.6%  C++
     84    0.2%    0.4%  GC
  18502   49.3%          Shared libraries
   2449    6.5%          Unaccounted

 [C++ entry points]:
   ticks    cpp   total   name
   5198   93.0%   13.9%  v8::internal::Heap::MoveElements(v8::internal::FixedArray*, int, int, int)

@bnoordhuis
Copy link
Contributor

Your version of perf seems to be too old to understand the .map files that --perf_basic_prof produces but the profile from the builtin profiler is interesting: it shows that the main thread is mostly either doing nothing (blocked in syscall), busy mutating arrays (MoveElements) or waiting on a semaphore (semop).

Nothing really stands out but I noticed that lib/odbc.js is sloppy mode code. Adding a 'use strict' at the top might help, that gives V8 more leeway to optimize. The file needs to be strict mode compatible, of course, but I expect sloppy mode code will only get penalized more going forward so it pays to switch to strict mode.

By the way, is your nodejs binary from the ubuntu repos? Have you tried the official ones from https://nodejs.org/? I ask because some ticks are counted twice (once as C++, once as Shared libraries), which is a bug that doesn't exist in the official binaries as far as I'm aware.

@bnoordhuis
Copy link
Contributor

I should add that since the lion's share is node sleeping in a syscall, most of the work probably takes place off-thread, in odbc's thread pool.

@amcintyre99
Copy link
Author

re perf, am very current, probably just didn't point to the .map files
Welcome to Ubuntu 16.04.2 LTS (GNU/Linux 4.4.0-78-generic x86_64)

i will try 'use strict'

nodejs binary installed via latest nodesource package
https://github.com/nodesource/distributions

andrew@sherlock:~$ dpkg -l nodejs
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name                                           Version                      Architecture                 Description
+++-==============================================-============================-============================-==================================================================================================
ii  nodejs                                         6.10.3-1nodesource1~xenial1  amd64                        Node.js event-based server-side javascript engine
andrew@sherlock:~$ 

@amcintyre99
Copy link
Author

with 'use strict' got this immediately

/home/andrew/dma/odbc_ibm/node_modules/ibm_db/lib/odbc.js:129
    delete db;
           ^^
SyntaxError: Delete of an unqualified identifier in strict mode.

i'm not much of a js coder so will need the package maintainers to try this change. thanks!!

@amcintyre99
Copy link
Author

jeez, /proc/sys/kernel/kptr_restrict change required for perf

has symbols now
https://gist.github.com/amcintyre99/3a854a915c31b1548cfe68005a932a57

@amcintyre99
Copy link
Author

@bnoordhuis
Copy link
Contributor

Can you try v6 with perf record -g, that gives call stacks. This:

11.47%  V8 WorkerThread  nodejs                [.] v8::internal::LAllocator::AllocateRegisters                                                                                                                 
9.38% node libpthread-2.23.so [.] pthread_cond_wait@@GLIBC_2.3.2 

Suggests V8 spends quite a bit of time compiling JS code but it would be good to know the call graphs leading up to pthread_cond_wait().

re perf, am very current, probably just didn't point to the .map files

perf is supposed to pick them up automatically from /tmp. Yours (4.4) I suspect is too old but it's easy to build from source: download recent kernel tarball, unpack and make -C tools/perf.

@amcintyre99
Copy link
Author

-g done, report file large so gzipped
https://gist.github.com/amcintyre99/8e6e7412d98562346f419efc8b0c008d
perf.gz

@bnoordhuis
Copy link
Contributor

Thanks. That one shows node spending nearly all its time either in the write(2) system call or waiting on a mutex, which is quite different from the last one. I don't really have any suggestions to offer.

@amcintyre99
Copy link
Author

here is same code 3 times without the -g, but all are different
note times are all very close so should be very repeatable
am i missing some perf parm? or if not perf, any other profiler you might suggest?
https://gist.github.com/amcintyre99/661e2c73baa0ad354124c1284614c627

@amcintyre99
Copy link
Author

node profiler is consistent with run 2 days ago
https://gist.github.com/amcintyre99/6021c358b901aa98961469872e430107

[Summary]:
   ticks  total  nonlib   name
    267    0.7%    1.4%  JavaScript
  16288   43.6%   85.8%  C++
     86    0.2%    0.5%  GC
  18356   49.1%          Shared libraries
   2438    6.5%          Unaccounted

@amcintyre99 amcintyre99 changed the title Node 6.10.3 slower timings with ibm_db than Node 4.8.3 Node 6.x and 8.x slower timings with ibm_db than Node 4.8.3 Jul 10, 2017
@amcintyre99
Copy link
Author

latest timings with ibm_db 2.1
4.8.3 still wins - and 8.1.3 improved some over 6.x
https://gist.github.com/amcintyre99/600ba93e7a74beedd7af3ac0d63d3326/edit

@bimalkjha
Copy link
Member

@amcintyre99 Please share the latest timings with [email protected] . Thanks.

@amcintyre99
Copy link
Author

latest timings
4.8.3 still fastest (see previous post) with 8.6.0 coming in 2nd
https://gist.github.com/amcintyre99/f2be210098ac9379298789fe66b80244

@amcintyre99 amcintyre99 changed the title Node 6.x and 8.x slower timings with ibm_db than Node 4.8.3 Node 6.x/8.x slower timings with ibm_db than Node 4.8.3 Sep 30, 2017
@amcintyre99
Copy link
Author

870 better than 860
ibm_db 2.2.1

100000 queries issued in 23.282 seconds, 4295/sec : Prepare - ExecuteNonQuery

@amcintyre99
Copy link
Author

893 slightly faster than 870, probably just noise
483 still fastest
ibm_db 221

fyi, all of these timings were done on same box, best of 10 with performance gov set and nothing else running

100000 queries issued in 23.088 seconds, 4331/sec : Prepare - ExecuteNonQuery

@amcintyre99
Copy link
Author

894 faster than 893

100000 queries issued in 21.011 seconds, 4759/sec : Prepare - ExecuteNonQuery

@amcintyre99
Copy link
Author

6x and 8x slower than 4x might be related to this open nodejs issue
nodejs/node#16164

@amcintyre99 amcintyre99 changed the title Node 6.x/8.x slower timings with ibm_db than Node 4.8.3 node and ibm_db getting slower with each node release Jul 7, 2019
@amcintyre99
Copy link
Author

latest timings

node and ibm_db getting slower with each node release

i7-4770 @ 3.4 GHz

db2 10.5.6
ibm_db 2.5.2

best of 20 runs
with scaling governor performance set

nodejs binaries installed from nodesource


================================================================
bionic - Ubuntu 18.04.2 LTS (GNU/Linux 4.18.0-25-generic x86_64)

node 4.9.1 - no bionic binaries from nodesource
?

node 6.14.1 - last bionic binary from nodesource
100000 queries issued in 14.234 seconds, 7025/sec : Prepare - ExecuteNonQuery

node 8.16.0
100000 queries issued in 34.501 seconds, 2898/sec : Prepare - ExecuteNonQuery

node 10.16.0
100000 queries issued in 38.798 seconds, 2577/sec : Prepare - ExecuteNonQuery


================================================================
xenial - Ubuntu 16.04.6 LTS (GNU/Linux 4.4.0-154-generic x86_64)

node 4.9.1
100000 queries issued in 5.767 seconds, 17340/sec : Prepare - ExecuteNonQuery

node 6.17.1
100000 queries issued in 13.879 seconds, 7205/sec : Prepare - ExecuteNonQuery

node 8.16.0
100000 queries issued in 36.374 seconds, 2749/sec : Prepare - ExecuteNonQuery

node 10.16.0
100000 queries issued in 37.543 seconds, 2663/sec : Prepare - ExecuteNonQuery

@amcintyre99
Copy link
Author

fyi, here is the code i'm using

"use strict";

var common = require("./commons")
  , odbc = require("ibm_db")
  , db = new odbc.Database()
  , iterations = 100000
  ;

db.open(common.connectionString, function(err){
  if (err) {
    console.error(err);
    process.exit(1);
  }

  issueQuery2(function () {
    finish();
  });
});

function issueQuery2(done) {
  var count = 0
    , time = new Date().getTime();

  var stmt = db.prepareSync('select cast(? as integer) as test FROM SYSIBM.SYSDUMMY1');

  for (var x = 0; x < iterations; x++) {
    (function (x) {
      stmt.executeNonQuery([x], cb);
    })(x);
  }

  function cb (err, data) {

    if (err) {
      console.error(err);
      return finish();
    }

    if (++count == iterations) {
      var elapsed = new Date().getTime() - time;

      console.log("%d queries issued in %d seconds, %d/sec : Prepare - ExecuteNonQuery ", count, elapsed/1000, Math.floor(count/(elapsed/1000)));
      return done();
    }
  }
}

function finish() {
  db.close(function () {
    console.log("connection closed");
  });
}

@bimalkjha
Copy link
Member

Tested on Ubuntu LTS 14.04 against remote DB2 Server v11.5.1.0 using perfTest.js. [email protected] shows better performance using node.js v12.x compare to node.js v11.x

[email protected]:
node 6.17.1 : 100000 queries issued in 43.884 seconds, 2278/sec : Prepare - ExecuteNonQuery
node 11.0.0 : 100000 queries issued in 74.255 seconds, 1346/sec : Prepare - ExecuteNonQuery

[email protected]:
node 6.17.1 : 100000 queries issued in 43.797 seconds, 2283/sec : Prepare - ExecuteNonQuery
node 11.0.0 : 100000 queries issued in 74.309 seconds, 1345/sec : Prepare - ExecuteNonQuery
node 12.13.1 : 100000 queries issued in 51.143 seconds, 1955/sec : Prepare - ExecuteNonQuery

@amcintyre99
Copy link
Author

Great improvement. Still not as good as Node V4 or V6 (see above) but 2.6.2 and V12 much better.

Thanks!!

i7-4770 @ 3.4 GHz

db2 10.5.6
best of 10 runs
with scaling governor performance set



node v10.16.0

[email protected]
100000 queries issued in 38.8 seconds, 2577/sec : Prepare - ExecuteNonQuery

[email protected]
100000 queries issued in 38.626 seconds, 2588/sec : Prepare - ExecuteNonQuery



node v12.13.1

[email protected]
100000 queries issued in 16.595 seconds, 6025/sec : Prepare - ExecuteNonQuery

@siva-srini
Copy link

@bimalkjha Any idea how it performs with Array as input. Also, what's the best way to update 100000 records. Using array promises?

@lucaskuperman
Copy link

Vote up
pure jdbc: <200ms
ibm_db: >1700ms

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

6 participants