Stream 15x slower when JS devconsole is open

[asadovsky]

@nlacasse @bjornick @aghassemi @bprosnitz

As part of debugging poor todosapp->syncbase RPC performance, I added a benchmark that does 100 puts (in parallel), then scans the written records. I console.log() very little - just enough to know how long the operations took from the client's perspective. It turns out that simply having the devconsole open makes the scan ~15x slower - see below.

With devconsole open:

benchmark.js:23 15:59:46.546 initSyncbaseDispatcher start
benchmark.js:23 15:59:47.945 runBenchmark start
benchmark.js:23 15:59:47.946 doPuts start
benchmark.js:29 15:59:53.632 doPuts took 5686ms
benchmark.js:23 15:59:53.633 doScan(15.59.47.946.) start
benchmark.js:74 scanned 1490 bytes
benchmark.js:29 16:00:02.867 doScan(15.59.47.946.) took 9234ms <---------- HERE
benchmark.js:29 16:00:02.867 runBenchmark took 14922ms
benchmark.js:29 16:00:02.868 initSyncbaseDispatcher took 16322ms

With devconsole closed (opened only at the end, to get console logs):

bundle.min.js:25 16:01:12.210 initSyncbaseDispatcher start
bundle.min.js:25 16:01:13.033 runBenchmark start
bundle.min.js:25 16:01:13.033 doPuts start
bundle.min.js:31 16:01:17.095 doPuts took 4062ms
bundle.min.js:25 16:01:17.095 doScan(16.01.13.034.) start
bundle.min.js:76 scanned 1490 bytes
bundle.min.js:31 16:01:17.753 doScan(16.01.13.034.) took 658ms <---------- HERE
bundle.min.js:31 16:01:17.753 runBenchmark took 4720ms
bundle.min.js:31 16:01:17.753 initSyncbaseDispatcher took 5543ms

Note, the VDL scan API looks like this:

Scan(start, limit []byte) stream<_, KeyValue> error

Where KeyValue is defines as such:

type KeyValue struct {
    Key   string
    Value []byte
}

As another data point: running Scan using vrpc takes under 300ms.

time $V23_ROOT/release/go/bin/vrpc -v23.credentials=tmp/creds call /localhost:8200/todos/db/tb Scan '"16.01.13.034."' '"16.01.13.034/"' > /dev/null

real    0m0.272s
user    0m0.135s
sys 0m0.019s

To reproduce this, see instructions here: $V23_ROOT/experimental/projects/todosapp/README.md
Run all the steps in the "Running the web application" section, then visit http://localhost:4000/?d=syncbase&n=/localhost:8200&bm=1 in your browser.

[nlacasse]

What version of Chrome are you using?

I want to rule out the following bug(s):
https://code.google.com/p/chromium/issues/detail?id=485052
https://code.google.com/p/chromium/issues/detail?id=490645

On Mon, Jul 13, 2015 at 4:09 PM, Adam Sadovsky notifications@github.com
wrote:

@nlacasse https://github.com/nlacasse @bjornick
https://github.com/bjornick

As part of debugging poor todosapp->syncbase RPC performance, I added a
benchmark that does 100 puts (in parallel), then scans the written records.
I console.log() very little - just enough to know how long the operations
took from the client's perspective. It turns out that simply having the
devconsole open makes the scan ~15x slower - see below.

With devconsole open:

benchmark.js:23 15:59:46.546 initSyncbaseDispatcher start
benchmark.js:23 15:59:47.945 runBenchmark start
benchmark.js:23 15:59:47.946 doPuts start
benchmark.js:29 15:59:53.632 doPuts took 5686ms
benchmark.js:23 15:59:53.633 doScan(15.59.47.946.) start
benchmark.js:74 scanned 1490 bytes
benchmark.js:29 16:00:02.867 doScan(15.59.47.946.) took 9234ms
benchmark.js:29 16:00:02.867 runBenchmark took 14922ms
benchmark.js:29 16:00:02.868 initSyncbaseDispatcher took 16322ms

With devconsole closed (opened only at the end, to get console logs):

bundle.min.js:25 16:01:12.210 initSyncbaseDispatcher start
bundle.min.js:25 16:01:13.033 runBenchmark start
bundle.min.js:25 16:01:13.033 doPuts start
bundle.min.js:31 16:01:17.095 doPuts took 4062ms
bundle.min.js:25 16:01:17.095 doScan(16.01.13.034.) start
bundle.min.js:76 scanned 1490 bytes
bundle.min.js:31 16:01:17.753 doScan(16.01.13.034.) took 658ms
bundle.min.js:31 16:01:17.753 runBenchmark took 4720ms
bundle.min.js:31 16:01:17.753 initSyncbaseDispatcher took 5543ms

Note, the VDL scan API looks like this:

Scan(start, limit []byte) stream<_, KeyValue> error

Where KeyValue is defines as such:

type KeyValue struct {
Key string
Value []byte
}

As another data point: running Scan using vrpc takes under 300ms.

time $V23_ROOT/release/go/bin/vrpc -v23.credentials=tmp/creds call /localhost:8200/todos/db/tb Scan '"16.01.13.034."' '"16.01.13.034/"' > /dev/null

real 0m0.272s
user 0m0.135s
sys 0m0.019s

To reproduce this, see instructions here:
$V23_ROOT/experimental/projects/todosapp/README.md
Run all the steps in the "Running the web application" section, then visit
http://localhost:4000/?d=syncbase&n=/localhost:8200&bm=1 in your browser.

—
Reply to this email directly or view it on GitHub
#610.

[asadovsky]

Linux Chrome, Version 43.0.2357.132 (64-bit)

[bjornick]

It sounds like the second bug isn't fixed it. Maybe we should use exorcist?

[asadovsky]

We already use exorcist and extract the sourcemap into a separate file.

[asadovsky]

That said, bundle.min.js is 1.1M, so perhaps that's part of the problem..?

-rw-r----- 1 sadovsky eng 1.1M Jul 13 17:08 bundle.min.js
-rw-r----- 1 sadovsky eng 1.3M Jul 13 17:08 bundle.min.js.map

[nlacasse]

@asadovsky Do you have "async stack trackes" and/or "pause on exceptions" enabled in your dev console?

With both of those options enabled, my benchmark takes ~14 seconds.

14:41:42.313 initSyncbaseDispatcher start
benchmark.js:23 14:41:43.594 runBenchmark start
benchmark.js:23 14:41:43.594 doPuts start
benchmark.js:29 14:41:48.418 doPuts took 4824ms
benchmark.js:23 14:41:48.418 doScan(14.41.43.595.) start
benchmark.js:73 scanned 1490 bytes
benchmark.js:29 14:41:56.527 doScan(14.41.43.595.) took 8109ms
benchmark.js:29 14:41:56.528 runBenchmark took 12934ms
benchmark.js:29 14:41:56.528 initSyncbaseDispatcher took 14215ms

With both of those options disabled, my benchmark takes ~7.5 seconds.

14:44:34.969 initSyncbaseDispatcher start
benchmark.js:23 14:44:35.890 runBenchmark start
benchmark.js:23 14:44:35.891 doPuts start
benchmark.js:29 14:44:39.363 doPuts took 3472ms
benchmark.js:23 14:44:39.363 doScan(14.44.35.891.) start
benchmark.js:73 scanned 1490 bytes
benchmark.js:29 14:44:42.394 doScan(14.44.35.891.) took 3031ms
benchmark.js:29 14:44:42.394 runBenchmark took 6504ms
benchmark.js:29 14:44:42.394 initSyncbaseDispatcher took 7425ms

With the dev console closed, my benchmarks take ~4.5 seconds.

Using the Vanadium Extension's NaCl WSPR
bundle.min.js:25 14:45:10.933 initSyncbaseDispatcher start
bundle.min.js:25 14:45:11.719 runBenchmark start
bundle.min.js:25 14:45:11.719 doPuts start
bundle.min.js:31 14:45:14.949 doPuts took 3230ms
bundle.min.js:25 14:45:14.949 doScan(14.45.11.719.) start
bundle.min.js:75 scanned 1490 bytes
bundle.min.js:31 14:45:15.479 doScan(14.45.11.719.) took 530ms
bundle.min.js:31 14:45:15.480 runBenchmark took 3761ms
bundle.min.js:31 14:45:15.480 initSyncbaseDispatcher took 4547ms

[asadovsky]

I don't remember what I had checked. I think I tried various combinations, but based on your numbers I'm guessing my 16x figure had both options checked. Thanks for looking into this!

I'm going to implement my own logging helper that can write either to console.log or to a text log in the DOM.

[nlacasse]

Closing this issue. The "async stack traces" and "pause on exceptions" were causing the slowness.

Adam implemented a logger that writes to DOM, so we don't need that lousy dev console any more :)