Make spawning super fast! #190

richardschneider · 2018-01-27T23:40:05Z

@dryajov Some details for #188

Well it was having a bad night, the 10s/command is now down to ~1.5s/command. It's still slow.

I'll be very interested in seeing what unix reports. To get these results, you need to set the environment variable, in windows its set DEBUG=ipfsd-ctl*. Then npm run test:node.

  ipfsd-ctl:run ipfs.exe init -b 2048 +3s
  ipfsd-ctl:run ipfs.exe config API.HTTPHeaders.Access-Control-Allow-Origin ["*"] --json +2s
  ipfsd-ctl:run ipfs.exe config API.HTTPHeaders.Access-Control-Allow-Methods ["PUT","POST","GET"] --json +1s
  ipfsd-ctl:run ipfs.exe config Addresses.Swarm ["/ip4/127.0.0.1/tcp/0"] --json +1s
  ipfsd-ctl:run ipfs.exe config Addresses.API "/ip4/127.0.0.1/tcp/0" --json +1s
  ipfsd-ctl:run ipfs.exe config Addresses.Gateway "/ip4/127.0.0.1/tcp/0" --json +1s
          √ create node and init (7084ms)
  ipfsd-ctl:run ipfs.exe daemon +1s
          √ start node (3790ms)```

richardschneider · 2018-01-28T00:38:38Z

@diasdavid @dryajov ipfsd-ctl uses subcommandte to run the command. It creates another NodeJS process that spawns the actual command. Seems very inefficient to me. subcommandte is fine when a long running child process needs to be killed when the parent the process is killed. However, this is not our case, our child process are short lived and we wait for them to close.

I'll try calling child_process directly and see what happens.

codecov · 2018-01-28T02:49:44Z

Codecov Report

❗ No coverage uploaded for pull request base (master@1f3f172). Click here to learn what that means.
The diff coverage is 100%.

@@            Coverage Diff            @@
##             master     #190   +/-   ##
=========================================
  Coverage          ?   87.67%           
=========================================
  Files             ?       18           
  Lines             ?      698           
  Branches          ?        0           
=========================================
  Hits              ?      612           
  Misses            ?       86           
  Partials          ?        0

Impacted Files	Coverage Δ
src/utils/exec.js	`100% <100%> (ø)`
src/utils/subcomandante-lite.js	`100% <100%> (ø)`

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 1f3f172...54cd1a8. Read the comment docs.

richardschneider · 2018-01-28T02:52:48Z

It's now ~350ms/command.

        spawn an initialized node
  ipfsd-ctl:run ipfs.exe init -b 2048 +2s
  ipfsd-ctl:run ipfs.exe config API.HTTPHeaders.Access-Control-Allow-Origin ["*"] --json +1s
  ipfsd-ctl:run ipfs.exe config API.HTTPHeaders.Access-Control-Allow-Methods ["PUT","POST","GET"] --json +303ms
  ipfsd-ctl:run ipfs.exe config Addresses.Swarm ["/ip4/127.0.0.1/tcp/0"] --json +286ms
  ipfsd-ctl:run ipfs.exe config Addresses.API "/ip4/127.0.0.1/tcp/0" --json +289ms
  ipfsd-ctl:run ipfs.exe config Addresses.Gateway "/ip4/127.0.0.1/tcp/0" --json +291ms
          √ create node and init (2584ms)
  ipfsd-ctl:run ipfs.exe daemon +288ms

daviddias · 2018-01-28T02:58:31Z

@richardschneider historically, we had many issues with ipfs process spawning and killing, to the point that using ipfs-desktop would spawn dozens of IPFS nodes without being able to effectively shut them down.

In order to move away from subcomandante, we need to be extremely careful and test well that we don't end up in that world again.

richardschneider · 2018-01-28T03:04:31Z

@diasdavid "Test well", does that mean that all tests run on all platforms?

daviddias · 2018-01-28T03:12:06Z

More than unit tests. I'm talking about linking it to apps like ipfs-desktop and using it in multiple platforms + run the js-ipfs-api tests with it to ensure that everything is running as expected.

richardschneider · 2018-01-28T05:07:41Z

@diasdavid ran the js-ipfs-api tests in node and except for the 2 known pubsub test issues, everything passed. I also checked for zombie processes and none were found. During the test, at most only 4 js/go processes were active.

Then tried running the tests in the browser and as you can guess webpack failed with heap error.

I don't know about ipfs-desktop. How should I go about testing it?

dryajov · 2018-01-29T03:05:48Z

package.json

    "detect-node": "^2.0.3",
    "hapi": "^16.6.2",
    "hat": "0.0.3",
+    "ipfs-api": "^17.3.0",


can we keep this as a devDependency? We don't want to bundle this, in case the consuming project already defines their own version.

Sorry about that. It seems that npm install just does that.

dryajov · 2018-01-29T03:07:37Z

@richardschneider I wonder why such a performance bust? I'd imagine go being a bit lighter than node in general?

richardschneider · 2018-01-29T03:19:30Z

@dryajov I beginning to feel that killing a node subprocess is causing the issue, especially on Windows. See @diasdavid comment. This is the reason for #195

I'm fighting other fires right now, so will eventually get back to this.

daviddias · 2018-02-16T17:28:01Z

I don't know about ipfs-desktop. How should I go about testing it?

@hacdias can you give a hand here?

richardschneider · 2018-02-16T20:54:47Z

@diasdavid I've been waiting for ipfsd-ctl to settle down before continuing with this PR.

I'll rebase real soon and continue my investigations.

daviddias · 2018-02-17T08:02:32Z

@richardschneider thank you :)

daviddias · 2018-02-23T08:31:46Z

@richardschneider wanna rebase now?

richardschneider · 2018-02-23T08:36:12Z

@diasdavid I need graceful stop before rebasing. What does another week matter.

daviddias · 2018-03-14T14:21:24Z

@richardschneider time to rebase master onto this branch! :D

dryajov · 2018-03-14T18:20:38Z

I've ran this branch locally and got this results:

real    4m20.749s
user    3m19.980s
sys     0m24.760s

In comparison, master yields this:

real    4m45.159s
user    3m39.185s
sys     0m27.601s

daviddias · 2018-03-15T02:38:02Z

I've rebased master onto this branch, here are my results:

# master
npm test  159.45s user 27.56s system 65% cpu 4:45.73 total
# perf
npm test  134.43s user 21.23s system 63% cpu 4:06.89 total

dryajov · 2018-03-16T15:57:45Z

This seems to work as expected. Should we go with it (I'm 👍)?

@richardschneider if we merge this, lets not forget to remove subcomandante from the package.json deps

richardschneider · 2018-03-16T20:49:22Z

@dryajov done!

dryajov

LGTM

daviddias · 2018-03-17T19:14:29Z

Please take into account my comment above -- #190 (comment) -- simply trusting CI won't do it for this PR.

dryajov · 2018-03-20T18:50:34Z

@hacdias how can we test this with ipfs-desktop?

travisperson · 2018-04-05T02:34:04Z

TL;DR; - I think we need to look into this further to make sure we are handling things correctly and allowing gracefully shutdown across all platforms, while also being a friendly module to users consuming ipfsd-ctl.

I believe it is generally frowned upon to listen to the main process signals in a library. The issue is that when listening on SIGINT and SIGTERM the default node handlers are removed that cause the process to exit. Any module / application must implement its own handlers if it wishes to exit from the signals when the event loop is not empty if it consumes this module.

The subcomandante module gets around this as it does not listen on these signals from the consumed module, but from the forked child subcom, and polls for the parent PID.

It's a little dense and hard to parse, but the section on Signal Events provides some insight to how nodejs signals are handled.

I think it's also important to note this line from the process docs with regard to windows

Sending SIGINT, SIGTERM, and SIGKILL cause the unconditional termination of the target process.

The standard ChildProcess.prototype.kill sends a SIGTERM, which cannot be handled on windows, subcomandante doesn't really handle this well either. It will turn a SIGKILL into a SIGHUP though.

Both nodejs and golang exit the process on a SIGHUP.

Side note of Windows

SIGHUP is generated on Windows when the console window is closed [...] however, Node.js will be unconditionally terminated by Windows about 10 seconds later

The go-ipfs project gracefully handles the SIGHUP. However, js-ipfs does not and instead will immediately terminate.

I don't have a good solution to this at the moment, but I do think we need to dig a bit further to see if we can come up with a better solution.

This thread (nodejs/node#12378) on the node project provides more insight as well, and is worth a read through.

Signals in golang can also be read up on (https://golang.org/pkg/os/signal) here.

hacdias · 2018-04-05T07:22:45Z

@dryajov sorry. Completely missed this.

Time elapsed from 'DaemonFactory.create().spawn(...' to 'node.start':

v0.31.0: 3251.473ms
This branch: 3177.366ms

Don't forget that between the process of those two functions there are a lot more things going on on IPFS Desktop.

Everything else seems to be working as expected. I'll leave IPFS Desktop running with this branch to see if I fall into any issues.

dryajov · 2018-04-05T17:12:55Z

Thanks @hacdias!

dryajov · 2018-04-05T19:01:16Z

I agree, we need to look into this further. I think that by removing the intermediate subcomandante process we fall back into the same issues subcomandante is trying to mitigate - namely forcefully killing ipfsd-ctl will leave a zombi ipfs process.

We should definitely handle the SIGHUP signal in js-ipfs, and it even works on windows - amazing 👅 !

daviddias · 2018-06-04T08:12:01Z

I'm closing this PR given that the risk / speed tradeoff doesn't justify spending much more time into it right now.

ghost assigned richardschneider Jan 27, 2018

ghost added the status/in-progress In progress label Jan 27, 2018

dryajov reviewed Jan 29, 2018

View reviewed changes

daviddias changed the title ~~[WIP] Performance~~ Make spawning super fast! Mar 14, 2018

richardschneider force-pushed the perf branch from bf05306 to ce5f0fe Compare March 14, 2018 23:40

daviddias force-pushed the perf branch from ce5f0fe to e40c76a Compare March 15, 2018 02:31

ghost assigned daviddias Mar 15, 2018

dryajov approved these changes Mar 17, 2018

View reviewed changes

ghost assigned dryajov Mar 23, 2018

richardschneider and others added 5 commits March 23, 2018 11:35

feat: ignore subcomandante and use child_process

888e330

chore: liniting

8e4ea4a

chore: follow conventions

0c012a2

fix: move subcomandante-lite to utils

cc27fe0

chore: remove subcomandante

5ec714f

dryajov force-pushed the perf branch from 2e5ce54 to 5ec714f Compare March 23, 2018 17:47

daviddias unassigned dryajov and daviddias May 14, 2018

daviddias closed this Jun 4, 2018

ghost removed the status/in-progress In progress label Jun 4, 2018

daviddias deleted the perf branch June 4, 2018 08:12

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Make spawning super fast! #190

Make spawning super fast! #190

richardschneider commented Jan 27, 2018

richardschneider commented Jan 28, 2018 •

edited

Loading

codecov bot commented Jan 28, 2018 •

edited

Loading

richardschneider commented Jan 28, 2018

daviddias commented Jan 28, 2018

richardschneider commented Jan 28, 2018

daviddias commented Jan 28, 2018

richardschneider commented Jan 28, 2018

dryajov Jan 29, 2018

richardschneider Jan 29, 2018

dryajov commented Jan 29, 2018

richardschneider commented Jan 29, 2018 •

edited

Loading

daviddias commented Feb 16, 2018

richardschneider commented Feb 16, 2018

daviddias commented Feb 17, 2018

daviddias commented Feb 23, 2018

richardschneider commented Feb 23, 2018

daviddias commented Mar 14, 2018

dryajov commented Mar 14, 2018

daviddias commented Mar 15, 2018

dryajov commented Mar 16, 2018

richardschneider commented Mar 16, 2018

dryajov left a comment

daviddias commented Mar 17, 2018

dryajov commented Mar 20, 2018

travisperson commented Apr 5, 2018

hacdias commented Apr 5, 2018 •

edited

Loading

dryajov commented Apr 5, 2018

dryajov commented Apr 5, 2018

daviddias commented Jun 4, 2018

Make spawning super fast! #190

Make spawning super fast! #190

Conversation

richardschneider commented Jan 27, 2018

richardschneider commented Jan 28, 2018 • edited Loading

codecov bot commented Jan 28, 2018 • edited Loading

Codecov Report

richardschneider commented Jan 28, 2018

daviddias commented Jan 28, 2018

richardschneider commented Jan 28, 2018

daviddias commented Jan 28, 2018

richardschneider commented Jan 28, 2018

dryajov Jan 29, 2018

Choose a reason for hiding this comment

richardschneider Jan 29, 2018

Choose a reason for hiding this comment

dryajov commented Jan 29, 2018

richardschneider commented Jan 29, 2018 • edited Loading

daviddias commented Feb 16, 2018

richardschneider commented Feb 16, 2018

daviddias commented Feb 17, 2018

daviddias commented Feb 23, 2018

richardschneider commented Feb 23, 2018

daviddias commented Mar 14, 2018

dryajov commented Mar 14, 2018

daviddias commented Mar 15, 2018

dryajov commented Mar 16, 2018

richardschneider commented Mar 16, 2018

dryajov left a comment

Choose a reason for hiding this comment

daviddias commented Mar 17, 2018

dryajov commented Mar 20, 2018

travisperson commented Apr 5, 2018

hacdias commented Apr 5, 2018 • edited Loading

dryajov commented Apr 5, 2018

dryajov commented Apr 5, 2018

daviddias commented Jun 4, 2018

richardschneider commented Jan 28, 2018 •

edited

Loading

codecov bot commented Jan 28, 2018 •

edited

Loading

richardschneider commented Jan 29, 2018 •

edited

Loading

hacdias commented Apr 5, 2018 •

edited

Loading