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.

Sign up for GitHub

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

Jump to bottom

Stack overflow in stress test of asynchttpserver on Windows [DEBUG] #3919

Closed
cheatfate opened this issue Feb 29, 2016 · 6 comments
Closed

Stack overflow in stress test of asynchttpserver on Windows [DEBUG] #3919

cheatfate opened this issue Feb 29, 2016 · 6 comments
Labels
Garbage Collection Severe

Comments

@cheatfate
Copy link
Member

I made wrk's stress test from Linux VM (guest) to Windows (host) asynchttpserver.nim.
And got an error.

There 4 compilation variants i have tested.

  1. x86_64-w64-mingw32 (4.8.3) / "nim c asynchttpserver.nim"
  2. x86_64-w64-mingw32 (4.8.3) / "nim c -d:release asynchttpserver.nim"
  3. vcc (19.00.23506 for x64) / "nim c asynchttpserver.nim"
  4. vcc (19.00.23506 for x64) / "nim c -d:release asynchttpserver.nim"

wrk options was "wrk -d 10"

All tests was performed on current devel version of nim repository.

x86_64-w64-mingw32 (4.8.3) / "nim c asynchttpserver.nim"

HOST:

Traceback (most recent call last)
asynchttpserver.nim(305) asynchttpserver
asynchttpserver.nim(304) main
asyncdispatch.nim(1617)  runForever
asyncdispatch.nim(446)   poll
asyncdispatch.nim(722)   :anonymous
asyncdispatch.nim(213)   complete
asyncdispatch.nim(1257)  cb
asyncnet.nim(322)        recvLineIntoIter
asyncdispatch.nim(222)   complete
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
(1874 calls omitted) ...
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1257)  cb
asynchttpserver.nim(249) processClientIter
asyncdispatch.nim(1270)  cb
asyncdispatch.nim(1257)  cb
asynchttpserver.nim(301) cbIter
asynchttpserver.nim(132) respond
asyncnet.nim(273)        send
asyncdispatch.nim(166)   newFuture
gc.nim(580)              growObj
gc.nim(529)              growObj
alloc.nim(671)           rawAlloc
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim              add
Stack overflow

GUEST:

./wrk -d 10 http://192.168.2.10:5555
Running 10s test @ http://192.168.2.10:5555
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     3.94ms    2.40ms  14.78ms   55.24%
    Req/Sec   247.90     53.77   380.00     80.00%
  248 requests in 10.09s, 31.00KB read
  Socket errors: connect 0, read 10, write 90, timeout 0
Requests/sec:     24.57
Transfer/sec:      3.07KB

x86_64-w64-mingw32 (4.8.3) / "nim c -d:release asynchttpserver.nim"

HOST:

NO ERROR

GUEST:

./wrk -d 10 http://192.168.2.10:5555
Running 10s test @ http://192.168.2.10:5555
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   782.54us    1.19ms  10.09ms   84.77%
    Req/Sec    11.21k   415.54    12.74k    71.00%
  224220 requests in 10.06s, 27.37MB read
Requests/sec:  22287.20
Transfer/sec:      2.72MB

vcc (19.00.23506 for x64) / "nim c asynchttpserver.nim"

HOST:

Traceback (most recent call last)
asynchttpserver.nim(294) asynchttpserver
asynchttpserver.nim(293) main
asyncdispatch.nim(1617)  runForever
asyncdispatch.nim(446)   poll
asyncdispatch.nim(856)   :anonymous
asyncdispatch.nim(213)   complete
asyncdispatch.nim(267)   :anonymous
asyncnet.nim(301)        :anonymous
asyncdispatch.nim(213)   complete
asyncdispatch.nim(1257)  cb
asynchttpserver.nim(274) serveIter
asyncdispatch.nim(1270)  processClient
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
(1874 calls omitted) ...
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1262)  cb
asyncdispatch.nim(260)   callback=
asyncdispatch.nim(1257)  cb
asynchttpserver.nim(238) processClientIter
asyncdispatch.nim(1270)  cb
asyncdispatch.nim(1257)  cb
asynchttpserver.nim(290) cbIter
asynchttpserver.nim(129) respond
asyncdispatch.nim(1270)  send
asyncdispatch.nim(1257)  cb
asyncnet.nim(283)        sendIter
asyncdispatch.nim(776)   send
asyncdispatch.nim(166)   newFuture
gc.nim(580)              growObj
gc.nim(529)              growObj
alloc.nim(671)           rawAlloc
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(61)          add
avltree.nim(56)          add
alloc.nim                allocAvlNode
Stack overflow

GUEST:

./wrk -d 10 http://192.168.2.10:5555
Running 10s test @ http://192.168.2.10:5555
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     3.32ms    2.26ms  17.81ms   77.21%
    Req/Sec   271.30     94.87   346.00     90.00%
  272 requests in 10.09s, 37.82KB read
  Socket errors: connect 0, read 10, write 90, timeout 0
  Non-2xx or 3xx responses: 1
Requests/sec:     26.96
Transfer/sec:      3.75KB

vcc (19.00.23506 for x64) / "nim c -d:release asynchttpserver.nim"

HOST:

NO ERROR

GUEST:

./wrk -d 10 http://192.168.2.10:5555
Running 10s test @ http://192.168.2.10:5555
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     0.89ms    1.48ms  12.04ms   86.92%
    Req/Sec    10.89k   535.04    13.51k    77.50%
  218026 requests in 10.07s, 26.61MB read
Requests/sec:  21649.95
Transfer/sec:      2.64MB
@vegansk
Copy link
Contributor

vegansk commented Mar 1, 2016

Caused by nimFrame function, used in debug by default:

  proc nimFrame(s: PFrame) {.compilerRtl, inl, exportc: "nimFrame".} =
    s.calldepth = if framePtr == nil: 0 else: framePtr.calldepth+1
    s.prev = framePtr
    framePtr = s
    if s.calldepth == 2000: stackOverflow()

@Araq, by the way, maybe there must be the compiler switch, that defines maximum calldepth?

@Xe
Copy link

Xe commented Mar 1, 2016

What was the code that you used for this on the client and server side?

@cheatfate
Copy link
Member Author

Server side is asynchttpserver.nim's code.

when not defined(testing) and isMainModule:
  proc main =
    var server = newAsyncHttpServer()
    proc cb(req: Request) {.async.} =
      #echo(req.reqMethod, " ", req.url)
      #echo(req.headers)
      let headers = {"Date": "Tue, 29 Apr 2014 23:40:08 GMT",
          "Content-type": "text/plain; charset=utf-8"}
      await req.respond(Http200, "Hello World", headers.newStringTable())

    asyncCheck server.serve(Port(5555), cb)
    runForever()
  main()

Client side is wrk's https://github.com/wg/wrk default request.

GET / HTTP/1.1
Host: xxx.xxx.xxx.xxx:yyyy

@dom96
Copy link
Contributor

dom96 commented Mar 3, 2016

Looks like a problem with GC, try --gc:boehm maybe.

@cheatfate
Copy link
Member Author

@dom96, problem is not in GC. Now i'm completely sure that problem is here:
Lines 744-765
Under heavy load if you complete futures in this way it causes a stack overflow. If you delete this lines and let poll() dispatch callbacks - this stack overflow will not happen even in debug version.

@cheatfate cheatfate mentioned this issue Apr 18, 2016
Closed
@cheatfate
Copy link
Member Author

@dom96 this is reminder comment for you.
We are talking about to add queue and callSoon mechanism to asyncdispatch.nim to avoid deep recursion for "immediate completion"/"return finished future" functions.

The best place to put callSoon() would be https://github.com/nim-lang/Nim/blob/devel/lib/pure/asyncdispatch.nim#L260.

I have already tested this variant and it works good, the only problem is strange errors and big amount of warnings... So please do it for yourself.

cheatfate added a commit to cheatfate/Nim that referenced this issue May 13, 2016
@cheatfate
Resolve nim-lang#3919
1786ab1 
Introduce `callSoon` procedure to dispatch user callbacks in pool() context.
This was referenced May 13, 2016
Closed
Closed
Closed
Closed
Merged
@cheatfate cheatfate mentioned this issue Mar 14, 2017
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Garbage Collection Severe
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@dom96 @Xe @vegansk @cheatfate