search

jupyterhub / jupyterhub

Multi-user server for Jupyter notebooks
https://jupyterhub.readthedocs.io
Other
7.79k stars 2.02k forks source link

Python 2 kernel takes over 60 seconds to become ready #1028

Closed johnnyplaydrums closed 7 years ago

johnnyplaydrums commented 7 years ago

Hello there, my python 2 kernels are taking a very long time to become ready. The kernel is "connected" within a couple seconds, but then takes another 60 seconds or longer to become "ready". Once it's ready the websockets are speedy. I'm scratching my head because I had JupyterHub deployed on EC2 in our staging aws account and everything was zipping along. Now I've deployed a virtually identical setup in our production account and python 2 kernels have slowed way down. The python 3 kernel however, which is the default for our anaconda3 setup, starts up and becomes ready within a couple seconds.

Once the python 2 kernel becomes ready it's quite fast. Any thoughts? I'm not sure what kinds of things slow down the kernel becoming ready. Let me know if you need additional information. Thank you!

willingc commented 7 years ago

Hi @johnplaydrums,

Hmm...could you share a log of the startup process running in debug? Thanks.

minrk commented 7 years ago

Can you show pip list or conda list in the Python 2 and 3 envs? Something like this could be due to an old version of one of the kernel packages in Python 2.

johnnyplaydrums commented 7 years ago

Hey! @minrk to start, here's pip2 list:

amqp (1.4.9)
ansible (2.2.1.0)
anyjson (0.3.3)
appdirs (1.4.3)
apt-xapian-index (0.45)
asn1crypto (0.22.0)
astroid (1.4.8)
awscli (1.11.65)
Babel (2.3.4)
backports.functools-lru-cache (1.3)
backports.shutil-get-terminal-size (1.0.0)
backports.ssl-match-hostname (3.5.0.1)
billiard (3.3.0.23)
bleach (2.0.0)
boto (2.42.0)
boto3 (1.4.0)
botocore (1.4.93)
celery (3.1.24)
certifi (2016.9.26)
cffi (1.10.0)
chardet (2.0.1)
Cheetah (2.4.4)
cloud-init (0.7.5)
colorama (0.3.7)
configobj (4.7.2)
configparser (3.5.0)
credstash (1.12.0)
cryptography (1.8.1)
CurrencyConverter (0.10)
decorator (4.0.11)
docutils (0.12)
email (4.0.2)
entrypoints (0.2.2)
enum34 (1.1.6)
facebookads (2.7.1)
flower (0.9.1)
functools32 (3.2.3.post2)
futures (3.0.5)
googleads (4.5.1)
gspread (0.4.1)
gyp (0.1)
html5lib (0.999999999)
httplib2 (0.9.2)
idna (2.5)
iniherit (0.3.4)
ipaddress (1.0.18)
ipykernel (4.5.2)
ipython (5.3.0)
ipython-genutils (0.2.0)
isort (4.2.5)
Jinja2 (2.7.2)
jmespath (0.9.0)
jsonpatch (1.3)
jsonpointer (1.0)
jsonschema (2.6.0)
jupyter-client (5.0.0)
jupyter-core (4.3.0)
kombu (3.0.36)
Landscape-Client (14.12)
lazy-object-proxy (1.2.2)
MarkupSafe (0.18)
mccabe (0.5.2)
meld3 (0.6.10)
mistune (0.7.4)
nbconvert (5.1.1)
nbformat (4.3.0)
nose (1.3.7)
notebook (4.4.1)
numpy (1.11.1)
oauth (1.0.1)
oauth2client (4.0.0)
openexchangerates (0.1.1)
packaging (16.8)
PAM (0.4.2)
pandas (0.19.2)
pandocfilters (1.4.1)
paramiko (1.10.1)
pathlib2 (2.2.1)
pexpect (4.2.1)
pickleshare (0.7.4)
pip (9.0.1)
prettytable (0.7.2)
prompt-toolkit (1.0.13)
psycopg2 (2.6.2)
ptyprocess (0.5.1)
pyaml (16.11.4)
pyasn1 (0.1.9)
pyasn1-modules (0.0.8)
pycparser (2.17)
pycrypto (2.6.1)
pycurl (7.19.3)
Pygments (2.2.0)
pyinotify (0.9.4)
pylint (1.6.4)
pyOpenSSL (0.13)
pyparsing (2.2.0)
pyserial (2.6)
PySocks (1.5.7)
python-apt (0.9.3.5ubuntu2)
python-dateutil (2.5.3)
python-debian (0.1.21-nmu2ubuntu2)
python-slugify (1.2.1)
pytz (2016.7)
PyYAML (3.12)
pyzmq (16.0.2)
rauth (0.7.2)
redis (2.10.5)
requests (2.11.1)
rsa (3.4.2)
s3transfer (0.1.5)
scandir (1.5)
setuptools (34.3.2)
simplegeneric (0.8.1)
six (1.10.0)
ssh-import-id (3.21)
suds-jurko (0.6)
supervisor (3.0b2)
terminado (0.6)
testpath (0.3)
tornado (4.2)
traitlets (4.3.2)
Twisted-Core (13.2.0)
Twisted-Names (13.2.0)
Twisted-Web (13.2.0)
Unidecode (0.4.19)
urllib3 (1.7.1)
virtualenv (15.1.0)
wcwidth (0.1.7)
webencodings (0.5)
wheel (0.24.0)
workdays (1.4)
wrapt (1.10.8)
xmltodict (0.10.2)
yahoo-oauth (0.1.9)
zope.interface (4.0.5)

And pip list:

amqp (1.4.9)
ansible (2.2.1.0)
anyjson (0.3.3)
appdirs (1.4.3)
apt-xapian-index (0.45)
asn1crypto (0.22.0)
astroid (1.4.8)
awscli (1.11.65)
Babel (2.3.4)
backports.functools-lru-cache (1.3)
backports.shutil-get-terminal-size (1.0.0)
backports.ssl-match-hostname (3.5.0.1)
billiard (3.3.0.23)
bleach (2.0.0)
boto (2.42.0)
boto3 (1.4.0)
botocore (1.4.93)
celery (3.1.24)
certifi (2016.9.26)
cffi (1.10.0)
chardet (2.0.1)
Cheetah (2.4.4)
cloud-init (0.7.5)
colorama (0.3.7)
configobj (4.7.2)
configparser (3.5.0)
credstash (1.12.0)
cryptography (1.8.1)
CurrencyConverter (0.10)
decorator (4.0.11)
docutils (0.12)
email (4.0.2)
entrypoints (0.2.2)
enum34 (1.1.6)
facebookads (2.7.1)
flower (0.9.1)
functools32 (3.2.3.post2)
futures (3.0.5)
googleads (4.5.1)
gspread (0.4.1)
gyp (0.1)
html5lib (0.999999999)
httplib2 (0.9.2)
idna (2.5)
iniherit (0.3.4)
ipaddress (1.0.18)
ipykernel (4.5.2)
ipython (5.3.0)
ipython-genutils (0.2.0)
isort (4.2.5)
Jinja2 (2.7.2)
jmespath (0.9.0)
jsonpatch (1.3)
jsonpointer (1.0)
jsonschema (2.6.0)
jupyter-client (5.0.0)
jupyter-core (4.3.0)
kombu (3.0.36)
Landscape-Client (14.12)
lazy-object-proxy (1.2.2)
MarkupSafe (0.18)
mccabe (0.5.2)
meld3 (0.6.10)
mistune (0.7.4)
nbconvert (5.1.1)
nbformat (4.3.0)
nose (1.3.7)
notebook (4.4.1)
numpy (1.11.1)
oauth (1.0.1)
oauth2client (4.0.0)
openexchangerates (0.1.1)
packaging (16.8)
PAM (0.4.2)
pandas (0.19.2)
pandocfilters (1.4.1)
paramiko (1.10.1)
pathlib2 (2.2.1)
pexpect (4.2.1)
pickleshare (0.7.4)
pip (9.0.1)
prettytable (0.7.2)
prompt-toolkit (1.0.13)
psycopg2 (2.6.2)
ptyprocess (0.5.1)
pyaml (16.11.4)
pyasn1 (0.1.9)
pyasn1-modules (0.0.8)
pycparser (2.17)
pycrypto (2.6.1)
pycurl (7.19.3)
Pygments (2.2.0)
pyinotify (0.9.4)
pylint (1.6.4)
pyOpenSSL (0.13)
pyparsing (2.2.0)
pyserial (2.6)
PySocks (1.5.7)
python-apt (0.9.3.5ubuntu2)
python-dateutil (2.5.3)
python-debian (0.1.21-nmu2ubuntu2)
python-slugify (1.2.1)
pytz (2016.7)
PyYAML (3.12)
pyzmq (16.0.2)
rauth (0.7.2)
redis (2.10.5)
requests (2.11.1)
rsa (3.4.2)
s3transfer (0.1.5)
scandir (1.5)
setuptools (34.3.2)
simplegeneric (0.8.1)
six (1.10.0)
ssh-import-id (3.21)
suds-jurko (0.6)
supervisor (3.0b2)
terminado (0.6)
testpath (0.3)
tornado (4.2)
traitlets (4.3.2)
Twisted-Core (13.2.0)
Twisted-Names (13.2.0)
Twisted-Web (13.2.0)
Unidecode (0.4.19)
urllib3 (1.7.1)
virtualenv (15.1.0)
wcwidth (0.1.7)
webencodings (0.5)
wheel (0.24.0)
workdays (1.4)
wrapt (1.10.8)
xmltodict (0.10.2)
yahoo-oauth (0.1.9)
zope.interface (4.0.5)
minrk commented 7 years ago

I don't see anything obvious. Do you perhaps have any IPython extensions (not notebook extensions) or startup files? Maybe these are doing something that takes a bit of time at startup.

johnnyplaydrums commented 7 years ago

Nope, just double checked and I haven't installed any iPython or notebook extensions, and don't have any startup scripts. I'm using a pretty vanilla jupyterhub setup. I'm trying to figure out what's changed in the environment from our staging and production aws accounts, because python 2 kernels run fine in staging. I run the exact same playbook to deploy jupyterhub in production and that's when the python kernel 2 issue appears. I'm going to try some more debugging in our production environment. Any other ideas of what to look for? Here's the log from startup with --debug. At 18:46:29 the kernel starts and at 18:47:30 it becomes ready. Thanks again for the help!

$ jupyterhub --debug
[D 2017-03-28 18:45:03.178 JupyterHub application:555] Looking for jupyterhub_config in /opt/jupyterhub
[D 2017-03-28 18:45:03.178 JupyterHub application:577] Loaded config file: /opt/jupyterhub/jupyterhub_config.py
[I 2017-03-28 18:45:03.185 JupyterHub app:724] Loading cookie_secret from /opt/jupyterhub/jupyterhub_cookie_secret
[D 2017-03-28 18:45:03.185 JupyterHub app:796] Connecting to db: sqlite:///jupyterhub.sqlite
[W 2017-03-28 18:45:03.226 JupyterHub app:365]
    Generating CONFIGPROXY_AUTH_TOKEN. Restarting the Hub will require restarting the proxy.
    Set CONFIGPROXY_AUTH_TOKEN env or JupyterHub.proxy_auth_token config to avoid this message.

{'value': '~/notebooks', 'owner': <sudospawner.spawner.SudoSpawner object at 0x7fd949580400>, 'trait': <traitlets.traitlets.Unicode object at 0x7fd94765ab38>}
[D 2017-03-28 18:45:03.267 JupyterHub app:1085] Loading state for johnplaydrums from db
[D 2017-03-28 18:45:03.268 JupyterHub app:1097] johnplaydrums not running.
[D 2017-03-28 18:45:03.298 JupyterHub app:1102] Loaded users:
    johnplaydrums admin
[I 2017-03-28 18:45:03.305 JupyterHub app:1453] Hub API listening on http://127.0.0.1:8081/hub/
[W 2017-03-28 18:45:03.307 JupyterHub app:1174] Running JupyterHub without SSL.  I hope there is SSL termination happening somewhere else...
[I 2017-03-28 18:45:03.307 JupyterHub app:1176] Starting proxy @ http://*:80/
[D 2017-03-28 18:45:03.308 JupyterHub app:1177] Proxy cmd: ['configurable-http-proxy', '--ip', '', '--port', '80', '--api-ip', '127.0.0.1', '--api-port', '81', '--default-target', 'http://127.0.0.1:8081', '--error-target', 'http://127.0.0.1:8081/hub/error']
18:45:03.398 - info: [ConfigProxy] Proxying http://*:80 to http://127.0.0.1:8081
18:45:03.400 - info: [ConfigProxy] Proxy API at http://127.0.0.1:81/api/routes
[D 2017-03-28 18:45:03.417 JupyterHub app:1205] Proxy started and appears to be up
[I 2017-03-28 18:45:03.417 JupyterHub app:1485] JupyterHub is now running at http://127.0.0.1:80/
[I 2017-03-28 18:46:18.363 JupyterHub log:100] 302 GET / (@10.3.0.186) 0.87ms
[I 2017-03-28 18:46:18.383 JupyterHub log:100] 302 GET /hub (@10.3.0.186) 0.81ms
[D 2017-03-28 18:46:18.404 JupyterHub pages:53] User is not running: /hub/home
[I 2017-03-28 18:46:18.408 JupyterHub log:100] 302 GET /hub/ (johnplaydrums@10.3.0.186) 3.16ms
[I 2017-03-28 18:46:18.435 JupyterHub log:100] 200 GET /hub/home (johnplaydrums@10.3.0.186) 9.09ms
[I 2017-03-28 18:46:18.460 JupyterHub log:100] 302 GET / (@10.3.0.186) 1.31ms
[I 2017-03-28 18:46:18.477 JupyterHub log:100] 302 GET /hub (@10.3.0.186) 1.15ms
[D 2017-03-28 18:46:18.495 JupyterHub pages:53] User is not running: /hub/home
[I 2017-03-28 18:46:18.499 JupyterHub log:100] 302 GET /hub/ (johnplaydrums@10.3.0.186) 3.38ms
[I 2017-03-28 18:46:18.522 JupyterHub log:100] 200 GET /hub/home (johnplaydrums@10.3.0.186) 4.68ms
[D 2017-03-28 18:46:18.602 JupyterHub log:100] 200 GET /hub/static/css/style.min.css?v=d96e0760e0c2b7356ce89635b646c350 (@10.3.0.186) 5.86ms
[D 2017-03-28 18:46:18.604 JupyterHub log:100] 200 GET /hub/static/components/requirejs/require.js?v=6da8be361b9ee26c5e721e76c6d4afce (@10.3.0.186) 1.68ms
[D 2017-03-28 18:46:18.922 JupyterHub log:100] 200 GET /hub/static/components/font-awesome/fonts/fontawesome-webfont.woff?v=4.1.0 (@10.3.0.186) 1.94ms
[D 2017-03-28 18:46:18.956 JupyterHub log:100] 200 GET /hub/static/js/home.js?v=(& (@10.3.0.186) 1.56ms
[D 2017-03-28 18:46:19.032 JupyterHub log:100] 200 GET /hub/static/components/jquery/jquery.min.js?v=(& (@10.3.0.186) 2.45ms
[D 2017-03-28 18:46:19.033 JupyterHub log:100] 200 GET /hub/static/js/jhapi.js?v=(& (@10.3.0.186) 1.01ms
[D 2017-03-28 18:46:19.140 JupyterHub log:100] 200 GET /hub/static/js/utils.js?v=(& (@10.3.0.186) 1.73ms
[I 2017-03-28 18:46:20.229 JupyterHub log:100] 302 GET /hub/spawn (johnplaydrums@10.3.0.186) 4.07ms
[I 2017-03-28 18:46:20.255 JupyterHub log:100] 302 GET /user/johnplaydrums (@10.3.0.186) 1.29ms
[I 170328 18:46:20 mediator:75] Spawning /opt/anaconda/bin/jupyterhub-singleuser '--user="johnplaydrums"' '--cookie-name="jupyter-hub-token-johnplaydrums"' '--base-url="/user/johnplaydrums"' '--hub-host=""' '--hub-prefix="/hub/"' '--hub-api-url="http://127.0.0.1:8081/hub/api"' '--ip="127.0.0.1"' --port=41675 '--notebook-dir="~/notebooks"'
[D 2017-03-28 18:46:21.568 JupyterHub spawner:584] Polling subprocess every 30s
[I 2017-03-28 18:46:21.960 johnplaydrums manager:32] [nb_conda_kernels] enabled, 2 kernels found
[W 2017-03-28 18:46:22.242 johnplaydrums login:222] All authentication is disabled.  Anyone who can connect to this server will be able to run code.
[I 2017-03-28 18:46:22.357 johnplaydrums handlers:73] [nb_anacondacloud] enabled
[I 2017-03-28 18:46:22.361 johnplaydrums handlers:290] [nb_conda] enabled
[I 2017-03-28 18:46:22.424 johnplaydrums __init__:35] ✓ nbpresent HTML export ENABLED
[W 2017-03-28 18:46:22.424 johnplaydrums __init__:43] ✗ nbpresent PDF export DISABLED: No module named 'nbbrowserpdf'
[I 2017-03-28 18:46:22.427 johnplaydrums notebookapp:1201] Serving notebooks from local directory: /home/johnplaydrums/notebooks
[I 2017-03-28 18:46:22.427 johnplaydrums notebookapp:1201] 0 active kernels
[I 2017-03-28 18:46:22.428 johnplaydrums notebookapp:1201] The Jupyter Notebook is running at: http://127.0.0.1:41675/user/johnplaydrums/
[I 2017-03-28 18:46:22.428 johnplaydrums notebookapp:1202] Use Control-C to stop this server and shut down all kernels (twice to skip confirmation).
[D 2017-03-28 18:46:22.431 JupyterHub utils:84] Server at http://127.0.0.1:41675/user/johnplaydrums responded with 302
[I 2017-03-28 18:46:22.431 JupyterHub base:322] User johnplaydrums server took 2.157 seconds to start
[I 2017-03-28 18:46:22.432 JupyterHub orm:188] Adding user johnplaydrums to proxy /user/johnplaydrums => http://127.0.0.1:41675
[D 2017-03-28 18:46:22.433 JupyterHub orm:146] Fetching POST http://127.0.0.1:81/api/routes/user/johnplaydrums
[I 2017-03-28 18:46:22.434 johnplaydrums log:47] 302 GET /user/johnplaydrums (127.0.0.1) 4.29ms
[D 2017-03-28 18:46:22.438 JupyterHub base:236] Setting cookie for johnplaydrums: jupyter-hub-token-johnplaydrums, {}
[I 2017-03-28 18:46:22.446 JupyterHub log:100] 302 GET /hub/user/johnplaydrums (johnplaydrums@10.3.0.186) 2172.73ms
[I 2017-03-28 18:46:22.466 johnplaydrums log:47] 302 GET /user/johnplaydrums (10.3.0.186) 0.83ms
[I 2017-03-28 18:46:22.550 JupyterHub log:100] 200 GET /hub/api/authorizations/cookie/jupyter-hub-token-johnplaydrums/[secret] (johnplaydrums@127.0.0.1) 15.16ms
[I 2017-03-28 18:46:27.486 johnplaydrums handlers:170] Creating new notebook in
[I 2017-03-28 18:46:29.909 johnplaydrums kernelmanager:89] Kernel started: cee6b1c1-342a-4748-b756-f8420d8a0273
[W 2017-03-28 18:46:40.000 johnplaydrums handlers:232] Timeout waiting for kernel_info reply from cee6b1c1-342a-4748-b756-f8420d8a0273
minrk commented 7 years ago

Strange. I'm running out of ideas, but what is zmq.zmq_version() in both the notebook and Python 2 kernel environments?

johnnyplaydrums commented 7 years ago

zmq.zmq_version() is 4.1.6.

So I found the cause. I use s3fs fuse to mount s3 buckets on each users notebooks directory, so their data will be saved if an instance needs to be terminated. When I unmount the buckets, python 2 kernels start up great. When I mount the buckets again, it slows down. Haven't quite figured out why, yet. Any help is appreciated!

I don't think it could be a security group or iam issue, since all permissions are working and there's just a latency issue with the kernels becoming ready. Something in our networking infrastructure must have changed from staging to production.

Anyway, if you want to close issue this that'd be fine, since this isn't a jupyterhub problem.

willingc commented 7 years ago

@johnplaydrums Great job finding the cause. You may wish to check if settings for caching changed between staging and production.

I'll leave this open since @minrk may have some ideas. Also @zonca may have some thoughts re: s3 as well.

minrk commented 7 years ago

@johnplaydrums ah, then it might be all of the stat calls triggered during Python's initialization / imports. I believe that Python 3 improved the efficiency of this, reducing the number of redundant calls that are made. If those calls are slow on s3fs, it may make a big difference.

You can also test by trying to start a regular IPython session in the same working directory that the notebook servers are starting in. If you see that IPython starts similarly slowly in Python 2, that's probably it (it could still be it if you don't find that, but it can be one indicator).

willingc commented 7 years ago

Closing this issue since it appears to be resolved. Please leave a comment requesting this issue be reopened if you have additional questions on this issue. Thanks to all! :sunny: