workers problem #203

wsbmilk · 2016-12-21T12:38:57Z

if i use custom event loop below:
loop = uvloop.new_event_loop()
and then:
app.run(workers=4, loop=loop)

log will be:
2016-12-21 20:34:56,993: INFO: Spinning up 4 workers...
python: src/unix/linux-core.c:336: uv__io_poll: Assertion `(unsigned) fd < loop->nwatchers' failed.

and actually just 1 cpu core is working...

but when use default loop.
workers=4 will work.

os: ubuntu16.04 x64 and python 3.5.2
why?

edevil · 2016-12-21T14:34:43Z

I actually have a similar problem and I'm not even changing the event loop. I tried the example from the documentation and set the workers to 4:

from sanic import Sanic
from sanic.response import json

app = Sanic()

@app.route("/")
async def test(request):
    return json({"hello": "world"})

if __name__ == "__main__":
    app.run(host="0.0.0.0", port=8000, workers=4)

When I start it, it logs that it is spawning 4 workers, which it does:

2016-12-21 14:27:41,936: INFO: Goin' Fast @ http://0.0.0.0:8000
2016-12-21 14:27:41,936: INFO: Spinning up 4 workers...

But when I use wrk specifying 100 connections and 100 threads, still only one of the processes is handling the requests:

~ ps xau |grep sanic
andre             6351  93.6  0.1  2463520  15224 s002  R+    2:27PM   1:00.47 python hello_sanic.py
andre             6353   0.0  0.1  2463264   8488 s002  S+    2:27PM   0:00.02 python hello_sanic.py
andre             6352   0.0  0.0  2463264   8336 s002  S+    2:27PM   0:00.02 python hello_sanic.py
andre             6350   0.0  0.1  2463264   8540 s002  S+    2:27PM   0:00.02 python hello_sanic.py
andre             6349   0.0  0.1  2431400  17248 s002  S+    2:27PM   0:00.22 python hello_sanic.py

Sanic version 0.1.8.

wsbmilk · 2016-12-21T16:12:26Z

here is mine:
code:

from sanic import Sanic
from sanic.response import json

app = Sanic(__name__)


@app.route("/")
async def test(request):
    return json({"test": True})


app.run(host="0.0.0.0", port=8000, debug=True, workers=4)

result:

➜  ~ ps aux|grep simple_server.py
troy     20963  0.0  0.2  78908 21272 ?        S    Dec21   0:00
troy     20964 10.2  0.2 178404 20108 ?        Rl   Dec21   0:22
troy     20965 10.0  0.2 178408 20008 ?        Rl   Dec21   0:22
troy     20966 10.0  0.2 178408 20032 ?        Rl   Dec21   0:21

it worked well.

but when i change it to:

from sanic import Sanic
from sanic.response import json

import asyncio
import uvloop

asyncio.set_event_loop_policy(uvloop.EventLoopPolicy())
loop = asyncio.get_event_loop()
app = Sanic(__name__)

@app.route("/")
async def test(request):
    return json({"test": True})

app.run(host="0.0.0.0", port=8000, debug=True, workers=4, loop=loop)

result:

➜  ~ ps aux|grep simple_server.py
troy     23156  0.4  0.2  79160 21696 ?        S    00:08 
troy     23159  6.8  0.2 179564 20880 ?        Rl   00:08

only one works well ,other three processes never spawn.

logs as below:

2016-12-22 00:08:32,310: INFO: Goin' Fast @ http://0.0.0.0:8000
2016-12-22 00:08:32,310: INFO: Spinning up 4 workers...
python: src/unix/linux-core.c:336: uv__io_poll: Assertion `(unsigned) fd < loop->nwatchers' failed.
python: src/unix/linux-core.c:336: uv__io_poll: Assertion `(unsigned) fd < loop->nwatchers' failed.
python: src/unix/linux-core.c:336: uv__io_poll: Assertion `(unsigned) fd < loop->nwatchers' failed.

marcosfede · 2016-12-24T10:32:35Z

Same here on macOS ,
code

from sanic import Sanic
from sanic.response import json

app = Sanic(__name__)

@app.route("/")
async def test(request):
    return json({"hi": "hello"})

if __name__ == "__main__":
    app.run(host="0.0.0.0", port=3333, debug=True, workers=4)

it says

2016-12-24 07:29:52,104: INFO: Goin' Fast @ http://0.0.0.0:3333
2016-12-24 07:29:52,105: INFO: Spinning up 4 workers...

but ps xau | grep server.py shows

fede             28188 100.0  0.1  2591252  11312 s000  R+    7:29AM   0:04.76 python3 server.py
fede             28233   0.0  0.0  2434840    800 s002  S+    7:30AM   0:00.00 grep --color=auto server.py
fede             28191   0.0  0.1  2591252  10172 s000  S+    7:29AM   0:00.02 python3 server.py
fede             28190   0.0  0.1  2591252  10036 s000  S+    7:29AM   0:00.03 python3 server.py
fede             28189   0.0  0.1  2591252  10056 s000  S+    7:29AM   0:00.02 python3 server.py
fede             28187   0.0  1.2  2551196 120764 s000  S+    7:29AM   0:02.86 python3 server.py

blazzman · 2016-12-24T11:25:05Z

Here is mine on MacOS 10.11.6 with explicit loop:

import asyncio

from sanic import Sanic
from sanic.response import json

loop = asyncio.get_event_loop()
app = Sanic(__name__)

@app.route('/hello')
async def hello(request):
    return json({'errors': None, 'data': True})

app.run(host='0.0.0.0', port=8080, workers=2, loop=loop, debug=True)

Output:

➜ python test_sanic.py
2016-12-24 14:02:24,540: DEBUG:
                 ▄▄▄▄▄
        ▀▀▀██████▄▄▄       _______________
      ▄▄▄▄▄  █████████▄  /                 \
     ▀▀▀▀█████▌ ▀▐▄ ▀▐█ |   Gotta go fast!  |
   ▀▀█████▄▄ ▀██████▄██ | _________________/
   ▀▄▄▄▄▄  ▀▀█▄▀█════█▀ |/
        ▀▀▀▄  ▀▀███ ▀       ▄▄
     ▄███▀▀██▄████████▄ ▄▀▀▀▀▀▀█▌
   ██▀▄▄▄██▀▄███▀ ▀▀████      ▄██
▄▀▀▀▄██▄▀▀▌████▒▒▒▒▒▒███     ▌▄▄▀
▌    ▐▀████▐███▒▒▒▒▒▐██▌
▀▄▄▄▄▀   ▀▀████▒▒▒▒▄██▀
          ▀▀█████████▀
        ▄▄██▀██████▀█
      ▄██▀     ▀▀▀  █
     ▄█             ▐▌
 ▄▄▄▄█▌              ▀█▄▄▄▄▀▀▄
▌     ▐                ▀▀▄▄▄▀
 ▀▀▄▄▀

2016-12-24 14:02:24,540: INFO: Goin' Fast @ http://0.0.0.0:8080
2016-12-24 14:02:24,540: INFO: Spinning up 2 workers...
2016-12-24 14:02:24,548: ERROR: Unable to start server
Traceback (most recent call last):
  File "/Users/andrey/work/.venv/sanic/lib/python3.5/site-packages/sanic/server.py", line 262, in serve
    http_server = loop.run_until_complete(server_coroutine)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/asyncio/base_events.py", line 375, in run_until_complete
    self.run_forever()
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/asyncio/base_events.py", line 345, in run_forever
    self._run_once()
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/asyncio/base_events.py", line 1276, in _run_once
    event_list = self._selector.select(timeout)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/selectors.py", line 569, in select
    kev_list = self._kqueue.control(None, max_ev, timeout)
OSError: [Errno 9] Bad file descriptor
2016-12-24 14:02:24,549: ERROR: Unable to start server
Traceback (most recent call last):
  File "/Users/andrey/work/.venv/sanic/lib/python3.5/site-packages/sanic/server.py", line 262, in serve
    http_server = loop.run_until_complete(server_coroutine)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/asyncio/base_events.py", line 375, in run_until_complete
    self.run_forever()
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/asyncio/base_events.py", line 345, in run_forever
    self._run_once()
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/asyncio/base_events.py", line 1276, in _run_once
    event_list = self._selector.select(timeout)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.5/lib/python3.5/selectors.py", line 569, in select
    kev_list = self._kqueue.control(None, max_ev, timeout)
OSError: [Errno 9] Bad file descriptor

Another try with explicit uvloop:

import asyncio
import uvloop

from sanic import Sanic
from sanic.response import json

asyncio.set_event_loop_policy(uvloop.EventLoopPolicy())
loop = asyncio.get_event_loop()

app = Sanic(__name__)


@app.route('/hello')
async def hello(request):
    return json({'errors': None, 'data': True})

app.run(host='0.0.0.0', port=8080, workers=2, loop=loop, debug=True)

output:

➜ python test_sanic.py
2016-12-24 14:08:26,085: DEBUG:
                 ▄▄▄▄▄
        ▀▀▀██████▄▄▄       _______________
      ▄▄▄▄▄  █████████▄  /                 \
     ▀▀▀▀█████▌ ▀▐▄ ▀▐█ |   Gotta go fast!  |
   ▀▀█████▄▄ ▀██████▄██ | _________________/
   ▀▄▄▄▄▄  ▀▀█▄▀█════█▀ |/
        ▀▀▀▄  ▀▀███ ▀       ▄▄
     ▄███▀▀██▄████████▄ ▄▀▀▀▀▀▀█▌
   ██▀▄▄▄██▀▄███▀ ▀▀████      ▄██
▄▀▀▀▄██▄▀▀▌████▒▒▒▒▒▒███     ▌▄▄▀
▌    ▐▀████▐███▒▒▒▒▒▐██▌
▀▄▄▄▄▀   ▀▀████▒▒▒▒▄██▀
          ▀▀█████████▀
        ▄▄██▀██████▀█
      ▄██▀     ▀▀▀  █
     ▄█             ▐▌
 ▄▄▄▄█▌              ▀█▄▄▄▄▀▀▄
▌     ▐                ▀▀▄▄▄▀
 ▀▀▄▄▀

2016-12-24 14:08:26,085: INFO: Goin' Fast @ http://0.0.0.0:8080
2016-12-24 14:08:26,085: INFO: Spinning up 2 workers...
2016-12-24 14:08:26,101: ERROR: Unable to start server
Traceback (most recent call last):
  File "uvloop/loop.pyx", line 568, in uvloop.loop.Loop._add_reader (uvloop/loop.c:13938)
KeyError: 18

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/andrey/work/.venv/sanic/lib/python3.5/site-packages/sanic/server.py", line 262, in serve
    http_server = loop.run_until_complete(server_coroutine)
  File "uvloop/loop.pyx", line 1198, in uvloop.loop.Loop.run_until_complete (uvloop/loop.c:24089)
  File "uvloop/loop.pyx", line 1191, in uvloop.loop.Loop.run_until_complete (uvloop/loop.c:23933)
  File "uvloop/loop.pyx", line 1100, in uvloop.loop.Loop.run_forever (uvloop/loop.c:22703)
  File "uvloop/loop.pyx", line 363, in uvloop.loop.Loop._run (uvloop/loop.c:11184)
  File "uvloop/loop.pyx", line 216, in uvloop.loop.Loop._setup_signals (uvloop/loop.c:8816)
  File "uvloop/loop.pyx", line 570, in uvloop.loop.Loop._add_reader (uvloop/loop.c:132016-12-24 14:08:26,101: ERROR: Unable to start server
Traceback (most recent call last):
  File "uvloop/loop.pyx", line 568, in uvloop.loop.Loop._add_reader (uvloop/loop.c:13938)
KeyError: 17

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/andrey/work/.venv/sanic/lib/python3.5/site-packages/sanic/server.py", line 262, in serve
    http_server = loop.run_until_complete(server_coroutine)
  File "uvloop/loop.pyx", line 1198, in uvloop.loop.Loop.run_until_complete (uvloop/loop.c:24089)
  File "uvloop/loop.pyx", line 1191, in uvloop.loop.Loop.run_until_complete (uvloop/loop.c:23933)
  File "uvloop/loop.pyx", line 1100, in uvloop.loop.Loop.run_forever (uvloop/loop.c:22703)
  File "uvloop/loop.pyx", line 363, in uvloop.loop.Loop._run (uvloop/loop.c:11184)
  File "uvloop/loop.pyx", line 216, in uvloop.loop.Loop._setup_signals (uvloop/loop.c:8816)
  File "uvloop/loop.pyx", line 570, in uvloop.loop.Loop._add_reader (uvloop/loop.c:13986)
  File "uvloop/handles/poll.pyx", line 30, in uvloop.loop.UVPoll.new (uvloop/loop.c:58062)
  File "uvloop/handles/poll.pyx", line 18, in uvloop.loop.UVPoll._init (uvloop/loop.c:57949)
OSError: [Errno 9] Bad file descriptor986)
  File "uvloop/handles/poll.pyx", line 30, in uvloop.loop.UVPoll.new (uvloop/loop.c:58062)
  File "uvloop/handles/poll.pyx", line 18, in uvloop.loop.UVPoll._init (uvloop/loop.c:57949)
OSError: [Errno 9] Bad file descriptor

My environment:

➜ uname -a
Darwin andreyb-mbp.local 15.6.0 Darwin Kernel Version 15.6.0: Wed Nov  2 20:30:56 PDT 2016; root:xnu-3248.60.11.1.2~2/RELEASE_X86_64 x86_64

➜ python -V
Python 3.5.2

virtualenv:

➜ pip freeze
-f /Users/andrey/.wheels
aiofiles==0.3.0
httptools==0.0.9
multidict==2.1.4
Sanic==0.1.8
ujson==1.35
uvloop==0.7.0

Worked fine without explicit loop, like:

app.run(host='0.0.0.0', port=8080, workers=2, loop=None, debug=True)

output:

...
2016-12-24 14:13:33,306: INFO: Goin' Fast @ http://0.0.0.0:8080
2016-12-24 14:13:33,306: INFO: Spinning up 2 workers...

➜ curl -X POST http:/localhost:8080/hello
{"errors":null,"data":true}

neoblackcap · 2016-12-25T05:23:44Z

I guess libuv can't simple use with fork()

import asyncio

import uvloop
from sanic import Sanic
from sanic.response import json


def start_server(host, port, workers):
    asyncio.set_event_loop_policy(uvloop.EventLoopPolicy())

    app = Sanic(__name__)

    @app.route('/hello')
    async def hello(request):
        loop = asyncio.get_event_loop()
        print(type(loop))
        return json({'errors': None, 'data': True})

    app.run(host=host, port=port, debug=True, workers=workers)


if __name__ == '__main__':
    start_server('0.0.0.0', 8000, 5)

work perfect, and visit /hello, the stdio output
<class 'uvloop.Loop'>

marcosfede · 2016-12-27T00:50:03Z

@neoblackcap the output shows no errors but I suspect that the additional workers are not being used, since there is no performance gain when you benchmark it with wrk -d10s -t8 -c100 http://0.0.0.0:3333/ and the additional workers show 0 percent utilization when you run ps xau | grep server.py

neoblackcap · 2016-12-27T17:58:08Z

@marcosfede I rerun the test by you without uvloop and get the same result as yours. I think this not a bug of uvloop.

here is my code:

import asyncio

import os
from sanic import Sanic
from sanic.response import json


def start_server(host, port, workers):

    app = Sanic(__name__)

    @app.route('/hello')
    async def hello(request):
        loop = asyncio.get_event_loop()
        print(os.getpid())
        return json({'errors': None, 'data': True})

    app.run(host=host, port=port, debug=True, workers=workers)


if __name__ == '__main__':
    start_server('0.0.0.0', 8000, 5)

test method
wrk -t100 -c100 -d10s http://127.0.0.1:8000/hello

stdio output

62678
62678
62678
62678
...
same pid

seemethere · 2016-12-30T17:05:10Z

Yes I'm noticing the same behavior as well, currently investigating although I think it would be better to just abandon the multiple workers implementation once we make Sanic WSGI compliant as pointed out in #250, so we can use Sanic with gunicorn, uwsgi, etc and use their multiple workers implementations.

dutradda · 2016-12-30T20:41:42Z

@seemethere, how are you running multiple workers?
You will abandon the stand alone web server implementation? Running with wsgi dont decrease the performance?

easydaniel · 2017-01-04T09:09:33Z

I wonder if the issue is that different process can't share same uvloop.
I made a try when not explicit define loop, each worker will create a new loop however when explicit define loop with specific loop, only the first worker success to create_server while others failed with this error message

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/sanic/server.py", line 287, in serve
    http_server = loop.run_until_complete(server_coroutine)
  File "uvloop/loop.pyx", line 1198, in uvloop.loop.Loop.run_until_complete (uvloop/loop.c:25480)
  File "uvloop/loop.pyx", line 1191, in uvloop.loop.Loop.run_until_complete (uvloop/loop.c:25324)
  File "uvloop/loop.pyx", line 1100, in uvloop.loop.Loop.run_forever (uvloop/loop.c:24056)
  File "uvloop/loop.pyx", line 363, in uvloop.loop.Loop._run (uvloop/loop.c:11491)
  File "uvloop/loop.pyx", line 216, in uvloop.loop.Loop._setup_signals (uvloop/loop.c:9069)
  File "uvloop/loop.pyx", line 570, in uvloop.loop.Loop._add_reader (uvloop/loop.c:14440)
  File "uvloop/handles/poll.pyx", line 30, in uvloop.loop.UVPoll.new (uvloop/loop.c:61297)
  File "uvloop/handles/poll.pyx", line 18, in uvloop.loop.UVPoll._init (uvloop/loop.c:61184)
OSError: [Errno 9] Bad file descriptor

My environment

Python 3.6.0
Darwin <hostname> 15.5.0 Darwin Kernel Version 15.5.0: Tue Apr 19 18:36:36 PDT 2016; root:xnu-3248.50.21~8/RELEASE_X86_64 x86_64

seemethere · 2017-01-11T15:56:22Z

I believe this was fixed with #276, if it hasn't I'll reopen the issue.

atungw · 2017-04-03T08:07:18Z

@seemethere

I believe this issue still exists on master. Try the reproduction steps to my comment in #594

r0fls · 2017-04-03T19:42:58Z

use wrk to test this @atungw

seemethere added advanced needs investigation labels Dec 30, 2016

This was referenced Jan 7, 2017

How can I have multiple asyncio processes listening on the same port? python/asyncio#481

Closed

fix multiple worker problem #276

Merged

seemethere closed this as completed Jan 11, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

workers problem #203

workers problem #203

wsbmilk commented Dec 21, 2016

edevil commented Dec 21, 2016

wsbmilk commented Dec 21, 2016

marcosfede commented Dec 24, 2016

blazzman commented Dec 24, 2016

neoblackcap commented Dec 25, 2016

marcosfede commented Dec 27, 2016

neoblackcap commented Dec 27, 2016 •

edited

Loading

seemethere commented Dec 30, 2016

dutradda commented Dec 30, 2016

easydaniel commented Jan 4, 2017

seemethere commented Jan 11, 2017

atungw commented Apr 3, 2017

r0fls commented Apr 3, 2017

workers problem #203

workers problem #203

Comments

wsbmilk commented Dec 21, 2016

edevil commented Dec 21, 2016

wsbmilk commented Dec 21, 2016

marcosfede commented Dec 24, 2016

blazzman commented Dec 24, 2016

neoblackcap commented Dec 25, 2016

marcosfede commented Dec 27, 2016

neoblackcap commented Dec 27, 2016 • edited Loading

seemethere commented Dec 30, 2016

dutradda commented Dec 30, 2016

easydaniel commented Jan 4, 2017

seemethere commented Jan 11, 2017

atungw commented Apr 3, 2017

r0fls commented Apr 3, 2017

neoblackcap commented Dec 27, 2016 •

edited

Loading