jco icon indicating copy to clipboard operation
jco copied to clipboard

stream not found to dispose on v1.0: is this expected under some load?

Open squillace opened this issue 2 years ago • 6 comments

a wasi v0.2.0 module build using tinygo has no problem on wasmtime nor spin (which is wasmtime) at 10,000 requests over 10 connections, but jco 1.0 can only handle about 9,000 before the following error appears:

squillace@idiopath:~/work/hello-wasi-http-go$ jco serve main.component.wasm
Server listening on 8000...
file:///home/squillace/.nvm/versions/node/v21.5.0/lib/node_modules/@bytecodealliance/jco/node_modules/@bytecodealliance/preview2-shim/lib/synckit/index.js:85
      if (error instanceof Error) throw Object.assign(error, properties);
                                  ^

Error: wasi-io trap: stream not found to dispose
    at handle (file:///home/squillace/.nvm/versions/node/v21.5.0/lib/node_modules/@bytecodealliance/jco/node_modules/@bytecodealliance/preview2-shim/lib/io/worker-thread.js:397:15)
    at file:///home/squillace/.nvm/versions/node/v21.5.0/lib/node_modules/@bytecodealliance/jco/node_modules/@bytecodealliance/preview2-shim/lib/synckit/index.js:105:38
    at MessagePort.<anonymous> (file:///home/squillace/.nvm/versions/node/v21.5.0/lib/node_modules/@bytecodealliance/jco/node_modules/@bytecodealliance/preview2-shim/lib/synckit/index.js:112:9)
    at [nodejs.internal.kHybridDispatch] (node:internal/event_target:822:20)
    at exports.emitMessage (node:internal/per_context/messageport:23:28)

Node.js v21.5.0```

Module built using the 06d197d6e608ac52da8ad39a5b6e5b41270fb773 commit of https://github.com/mossaka/hello-wasi-http-go. Again, like #335, Dan's rust hello world works fine under load, but the tinygo fails out. 

WSL2, Ubuntu 22.04.3 LTS, Windows 11, JCO 1.0.0

squillace avatar Feb 09 '24 14:02 squillace

@Mossaka heads up.

squillace avatar Feb 09 '24 14:02 squillace

Thanks for posting, can you share the example component to replicate this? Would be great to resolve. We could just ignore these errors but it's quite important to catch disposal invariant breaks.

guybedford avatar Feb 12 '24 23:02 guybedford

I'll repro today.

squillace avatar Feb 21 '24 08:02 squillace

OK! Back to this finally. I'm using Dan's rust component for jco serve. Same happens with go and python components.

jco version: 1.0.2 node: Node.js v21.6.2

Error occurs only after whacking it reasonably heavily:

squillace@dellsquill:~/work/squillace/hello-wasi-http$ jco serve target/wasm32-wasi/debug/hello_wasi_http.wasm
Server listening on 8000...
file:///usr/lib/node_modules/@bytecodealliance/jco/node_modules/@bytecodealliance/preview2-shim/lib/synckit/index.js:85
      if (error instanceof Error) throw Object.assign(error, properties);
                                  ^

Error: wasi-io trap: stream not found to dispose
    at handle (file:///usr/lib/node_modules/@bytecodealliance/jco/node_modules/@bytecodealliance/preview2-shim/lib/io/worker-thread.js:397:15)
    at file:///usr/lib/node_modules/@bytecodealliance/jco/node_modules/@bytecodealliance/preview2-shim/lib/synckit/index.js:105:38
    at MessagePort.<anonymous> (file:///usr/lib/node_modules/@bytecodealliance/jco/node_modules/@bytecodealliance/preview2-shim/lib/synckit/index.js:112:9)
    at [nodejs.internal.kHybridDispatch] (node:internal/event_target:822:20)
    at exports.emitMessage (node:internal/per_context/messageport:23:28)

Node.js v21.6.2

Here's the run that hurts it. I can run with ONE connection and it'll get a bit farther, but still collapses.

squillace@dellsquill:~$ hey -n 10000 -c 20 http://localhost:8000

Summary:
  Total:        4.9213 secs
  Slowest:      0.0241 secs
  Fastest:      0.0032 secs
  Average:      0.0122 secs
  Requests/sec: 2031.9800


Response time histogram:
  0.003 [1]     |
  0.005 [1]     |
  0.007 [1]     |
  0.009 [92]    |■
  0.012 [3330]  |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  0.014 [3097]  |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  0.016 [1166]  |■■■■■■■■■■■■■■
  0.018 [216]   |■■■
  0.020 [48]    |■
  0.022 [17]    |
  0.024 [31]    |


Latency distribution:
  10% in 0.0103 secs
  25% in 0.0109 secs
  50% in 0.0119 secs
  75% in 0.0131 secs
  90% in 0.0145 secs
  95% in 0.0155 secs
  99% in 0.0183 secs

Details (average, fastest, slowest):
  DNS+dialup:   0.0000 secs, 0.0032 secs, 0.0241 secs
  DNS-lookup:   0.0000 secs, 0.0000 secs, 0.0016 secs
  req write:    0.0000 secs, 0.0000 secs, 0.0008 secs
  resp wait:    0.0119 secs, 0.0016 secs, 0.0237 secs
  resp read:    0.0003 secs, 0.0000 secs, 0.0026 secs

Status code distribution:
  [200] 8000 responses

Error distribution:
  [2000]        Get "http://localhost:8000": dial tcp 127.0.0.1:8000: connect: connection refused

squillace avatar Mar 05 '24 10:03 squillace

@squillace thanks for the follow-up here - could you try test this out on the latest 1.0.3 version and let me know if it is still happening there? If so, please share the component and I'll look into it further.

guybedford avatar Mar 08 '24 01:03 guybedford