stlite icon indicating copy to clipboard operation
stlite copied to clipboard
verified publisher icon whitphx

Make boot-up faster

Open whitphx opened this issue 3 years ago • 5 comments

  • Parallelize the await-s in loadPyodideAndPackages that are now run sequentially.
  • Stop loading unnecessary packages
    • https://github.com/pyscript/pyscript/pull/234

Pyodide has a roadmap where it will try to speed up the initial set up: https://pyodide.org/en/stable/project/roadmap.html#reducing-download-sizes-and-initialization-times

whitphx avatar Aug 17 '22 08:08 whitphx

Don't refer to this result. #182 and #183 introduced the accurate logs

The console logs from the playground app opened in a private window of Brave (Chrome):

Error with Permissions-Policy header: Origin trial controlled feature not enabled: 'interest-cohort'.
21:45:17.642 pyodide.asm.js:10 Loading distutils
21:45:17.759 pyodide.asm.js:10 Loaded distutils
21:45:17.760 pyodide.asm.js:10 Python initialization complete
21:45:17.763 pyodide.asm.js:10 distutils already loaded from default channel
21:45:17.763 pyodide.asm.js:10 Loading micropip, pyparsing, packaging, ssl, openssl
21:45:17.954 pyodide.asm.js:10 Loaded openssl, ssl, micropip, pyparsing, packaging
21:45:18.560 /stlite/static/js/10.fec45d59.chunk.js:1 Invalid asm.js: Unexpected token
21:45:19.023 pyodide.asm.js:10 distutils already loaded from default channel
21:45:19.023 pyodide.asm.js:10 pyparsing already loaded from default channel
21:45:19.026 pyodide.asm.js:10 Loading numpy, pandas, python-dateutil, six, pytz, setuptools, pillow, typing-extensions, certifi, decorator, pygments, jinja2, markupsafe, toolz, jsonschema, attrs, pyrsistent
21:45:21.035 pyodide.asm.js:10 Loaded python-dateutil, six, pytz, setuptools, typing-extensions, certifi, decorator, pygments, jinja2, toolz, jsonschema, attrs, markupsafe, pyrsistent, pillow, numpy, pandas
21:45:21.538 pyodide.asm.js:10 six already loaded from default channel
21:45:21.538 pyodide.asm.js:10 distutils already loaded from default channel
21:45:21.538 pyodide.asm.js:10 numpy already loaded from default channel
21:45:21.538 pyodide.asm.js:10 packaging already loaded from default channel
21:45:21.539 pyodide.asm.js:10 pillow already loaded from default channel
21:45:21.539 pyodide.asm.js:10 pyparsing already loaded from default channel
21:45:21.539 pyodide.asm.js:10 python-dateutil already loaded from default channel
21:45:21.539 pyodide.asm.js:10 pytz already loaded from default channel
21:45:21.545 pyodide.asm.js:10 Loading matplotlib, cycler, fonttools, kiwisolver, beautifulsoup4, soupsieve, brotli, jedi, parso
21:45:23.126 pyodide.asm.js:10 Loaded cycler, fonttools, beautifulsoup4, soupsieve, jedi, parso, kiwisolver, brotli, matplotlib
21:45:29.919 pyodide.asm.js:10 Mixed Content: The page at 'blob:https://whitphx.github.io/b35dfad4-3b7f-486a-9181-954efc811bba' was loaded over HTTPS, but attempted to connect to the insecure WebSocket endpoint 'ws://8.8.8.8:1/'. This request has been blocked; this endpoint must be available over WSS.
21:45:29.927 b35dfad4-3b7f-486a-9181-954efc811bba:1 WARNING:streamlit.net_util:Did not auto detect external IP.
Please go to https://docs.streamlit.io/ for debugging hints.
21:45:29.929 pyodide.asm.js:10 
21:45:29.930 pyodide.asm.js:10   You can now view your Streamlit app in your browser.
21:45:29.930 pyodide.asm.js:10 
21:45:29.930 pyodide.asm.js:10   Network URL: http://127.0.0.1:8501
21:45:29.930 pyodide.asm.js:10 
21:45:29.930 pyodide.asm.js:10   For better performance, install the Watchdog module:
21:45:29.931 pyodide.asm.js:10 
21:45:29.931 pyodide.asm.js:10   $ pip install watchdog
21:45:29.931 pyodide.asm.js:10             
21:45:29.953 ConnectionManager.ts:51 The kernel has been loaded. Start connecting.
21:45:30.335 log.ts:58 Gather usage stats:  false
21:45:41.472 serviceWorkerRegistration.ts:95 Content is cached for offline use.

Elapsed time of each log (source: https://docs.google.com/spreadsheets/d/e/2PACX-1vSsAqwz0SzDQRe_oaA4VvLU-TdKg3IIrl6-epRq9hfsu5MZfqsOjLxt0jaWh5RTFPJLhCAvHZgd8B-q/pubhtml):

Log Time Elapsed Time since the first log Elapsed Time since the prev log Message
21:45:17642     pyodide.asm.js:10 Loading distutils
21:45:17759 0:00:00117 0:00:00117 pyodide.asm.js:10 Loaded distutils
21:45:17760 0:00:00118 0:00:00001 pyodide.asm.js:10 Python initialization complete
21:45:17763 0:00:00121 0:00:00003 pyodide.asm.js:10 distutils already loaded from default channel
21:45:17763 0:00:00121 0:00:00000 pyodide.asm.js:10 Loading micropip, pyparsing, packaging, ssl, openssl
21:45:17954 0:00:00312 0:00:00191 pyodide.asm.js:10 Loaded openssl, ssl, micropip, pyparsing, packaging
21:45:18560 0:00:00918 0:00:00606 /stlite/static/js/10.fec45d59.chunk.js:1 Invalid asm.js: Unexpected token
21:45:19023 0:00:01381 0:00:00463 pyodide.asm.js:10 distutils already loaded from default channel
21:45:19023 0:00:01381 0:00:00000 pyodide.asm.js:10 pyparsing already loaded from default channel
21:45:19026 0:00:01384 0:00:00003 pyodide.asm.js:10 Loading numpy, pandas, python-dateutil, six, pytz, setuptools, pillow, typing-extensions, certifi, decorator, pygments, jinja2, markupsafe, toolz, jsonschema, attrs, pyrsistent
21:45:21035 0:00:03393 0:00:02009 pyodide.asm.js:10 Loaded python-dateutil, six, pytz, setuptools, typing-extensions, certifi, decorator, pygments, jinja2, toolz, jsonschema, attrs, markupsafe, pyrsistent, pillow, numpy, pandas
21:45:21538 0:00:03896 0:00:00503 pyodide.asm.js:10 six already loaded from default channel
21:45:21538 0:00:03896 0:00:00000 pyodide.asm.js:10 distutils already loaded from default channel
21:45:21538 0:00:03896 0:00:00000 pyodide.asm.js:10 numpy already loaded from default channel
21:45:21538 0:00:03896 0:00:00000 pyodide.asm.js:10 packaging already loaded from default channel
21:45:21539 0:00:03897 0:00:00001 pyodide.asm.js:10 pillow already loaded from default channel
21:45:21539 0:00:03897 0:00:00000 pyodide.asm.js:10 pyparsing already loaded from default channel
21:45:21539 0:00:03897 0:00:00000 pyodide.asm.js:10 python-dateutil already loaded from default channel
21:45:21539 0:00:03897 0:00:00000 pyodide.asm.js:10 pytz already loaded from default channel
21:45:21545 0:00:03903 0:00:00006 pyodide.asm.js:10 Loading matplotlib, cycler, fonttools, kiwisolver, beautifulsoup4, soupsieve, brotli, jedi, parso
21:45:23126 0:00:05484 0:00:01581 pyodide.asm.js:10 Loaded cycler, fonttools, beautifulsoup4, soupsieve, jedi, parso, kiwisolver, brotli, matplotlib
21:45:29919 0:00:12277 0:00:06793 pyodide.asm.js:10 Mixed Content: The page at 'blob:https://whitphx.github.io/b35dfad4-3b7f-486a-9181-954efc811bba' was loaded over HTTPS, but attempted to connect to the insecure WebSocket endpoint 'ws://8.8.8.8:1/'. This request has been blocked; this endpoint must be available over WSS.
21:45:29927 0:00:12285 0:00:00008 b35dfad4-3b7f-486a-9181-954efc811bba:1 WARNING:streamlit.net_util:Did not auto detect external IP. Please go to https://docs.streamlit.io/ for debugging hints.
21:45:29929 0:00:12287 0:00:00002 pyodide.asm.js:10
21:45:29930 0:00:12288 0:00:00001 pyodide.asm.js:10 You can now view your Streamlit app in your browser.
21:45:29930 0:00:12288 0:00:00000 pyodide.asm.js:10
21:45:29930 0:00:12288 0:00:00000 pyodide.asm.js:10 Network URL: http://127.0.0.1:8501
21:45:29930 0:00:12288 0:00:00000 pyodide.asm.js:10
21:45:29930 0:00:12288 0:00:00000 pyodide.asm.js:10 For better performance, install the Watchdog module:
21:45:29931 0:00:12289 0:00:00001 pyodide.asm.js:10
21:45:29931 0:00:12289 0:00:00000 pyodide.asm.js:10 $ pip install watchdog
21:45:29931 0:00:12289 0:00:00000 pyodide.asm.js:10
21:45:29953 0:00:12311 0:00:00022 ConnectionManager.ts:51 The kernel has been loaded. Start connecting.
21:45:30335 0:00:12693 0:00:00382 log.ts:58 Gather usage stats: false
21:45:41472 0:00:23830 0:00:11137 serviceWorkerRegistration.ts:95 Content is cached for offline use.

whitphx avatar Aug 30 '22 12:08 whitphx

~~It looks like the external network access ( https://github.com/streamlit/streamlit/blob/8d490d016a42bd7c90d313952440b88f4aa973f3/lib/streamlit/web/bootstrap.py#L235 ) takes the longest time ( and it fails anyway)~~.

It actually took only 0.002sec.

The actual bottleneck is importing streamlit module (look below).

whitphx avatar Aug 30 '22 14:08 whitphx

With the debug logs introduced in #182 , the inspected logs are below, executed on localhost dev server with the playground app.

01:36:40.345 2ded76ba-c2e8-456e-b032-d5d95c8e3153:725 Loading Pyodide
01:36:42.182 2ded76ba-c2e8-456e-b032-d5d95c8e3153:730 Loaded Pyodide
01:36:42.183 2ded76ba-c2e8-456e-b032-d5d95c8e3153:734 Write a file "Hello.py"
01:36:42.185 2ded76ba-c2e8-456e-b032-d5d95c8e3153:734 Write a file "pages/1_Plotting_Demo.py"
01:36:42.185 2ded76ba-c2e8-456e-b032-d5d95c8e3153:734 Write a file "pages/Matplotlib_Demo.py"
01:36:42.186 2ded76ba-c2e8-456e-b032-d5d95c8e3153:734 Write a file "pages/Hiplot_Demo.py"
01:36:42.186 2ded76ba-c2e8-456e-b032-d5d95c8e3153:737 Loading the initially necessary packages
01:36:42.389 2ded76ba-c2e8-456e-b032-d5d95c8e3153:742 Loaded the initially necessary packages
01:36:42.389 2ded76ba-c2e8-456e-b032-d5d95c8e3153:743 Loading tornado, pyarrow, and streamlit
01:36:45.245 2ded76ba-c2e8-456e-b032-d5d95c8e3153:749 Loaded tornado, pyarrow, and streamlit
01:36:45.245 2ded76ba-c2e8-456e-b032-d5d95c8e3153:750 Installing the requirements: (2) ['matplotlib', 'hiplot']
01:36:47.127 2ded76ba-c2e8-456e-b032-d5d95c8e3153:758 Installed the requirements: (2) ['matplotlib', 'hiplot']
01:36:47.128 2ded76ba-c2e8-456e-b032-d5d95c8e3153:759 Setting the loggers
01:36:52.839 2ded76ba-c2e8-456e-b032-d5d95c8e3153:813 Set the loggers
01:36:52.839 2ded76ba-c2e8-456e-b032-d5d95c8e3153:814 Defining the bootstrap functions
01:36:53.300 2ded76ba-c2e8-456e-b032-d5d95c8e3153:898 Defined the bootstrap functions
01:36:53.300 2ded76ba-c2e8-456e-b032-d5d95c8e3153:899 Booting up the Streamlit server
01:36:53.326 2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:matplotlib.pyplot:Loaded backend agg version unknown.
01:36:53.328 2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.web.bootstrap:Setting up signal handler
01:36:53.333 2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.web.server.server:Starting server...
01:36:53.334 2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.web.server.server:Serving static content from /lib/python3.10/site-packages/streamlit/static
01:36:53.336 2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.web.server.server:Server started on port 8501
01:36:53.336 2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.web.server.server:Server state: State.INITIAL -> State.WAITING_FOR_FIRST_SESSION
01:36:53.550 2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:git.cmd:Popen(['git', 'version'], cwd=/home/pyodide, universal_newlines=False, shell=None, istream=None)
01:36:53.560 2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): checkip.amazonaws.com:80
01:36:53.563 2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.version:Skipping PyPI version check
01:36:53.564 2ded76ba-c2e8-456e-b032-d5d95c8e3153:915 Booted up the Streamlit server
01:36:53.564 2ded76ba-c2e8-456e-b032-d5d95c8e3153:916 Setting up the HTTP server
01:36:53.575 2ded76ba-c2e8-456e-b032-d5d95c8e3153:922 Set up the HTTP server
01:36:53.610 2ded76ba-c2e8-456e-b032-d5d95c8e3153:947 websocket:connect {path: 'stream'}
01:36:53.613 2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.runtime.app_session:AppSession initialized (id=c2085e72-6659-4edb-b056-7b530553aaee)
01:36:53.613 2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.web.server.server:Created new session for client 76291888. Session ID: c2085e72-6659-4edb-b056-7b530553aaee
01:36:53.614 2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.web.server.server:Server state: State.WAITING_FOR_FIRST_SESSION -> State.ONE_OR_MORE_SESSIONS_CONNECTED
01:36:53.615 2ded76ba-c2e8-456e-b032-d5d95c8e3153:973 websocket:send {payload: Uint8Array(10)}
01:36:53.616 2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.web.server.browser_websocket_handler:Received the following back message:
rerun_script {
  widget_states {
  }
}

01:36:53.988 2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.web.server.server:Script run finished successfully; removing expired entries from MessageCache (max_age=2)
Log Time Elapsed Time since the first log Elapsed Time since the prev log   Message
1:36:40345       2ded76ba-c2e8-456e-b032-d5d95c8e3153:725 Loading Pyodide
1:36:42182 0:00:01837 0:00:01837 0:00:01837 2ded76ba-c2e8-456e-b032-d5d95c8e3153:730 Loaded Pyodide
1:36:42183 0:00:00001 0:00:01838   2ded76ba-c2e8-456e-b032-d5d95c8e3153:734 Write a file "Hello.py"
1:36:42185 0:00:00002 0:00:01840   2ded76ba-c2e8-456e-b032-d5d95c8e3153:734 Write a file "pages/1_Plotting_Demo.py"
1:36:42185 0:00:00000 0:00:01840   2ded76ba-c2e8-456e-b032-d5d95c8e3153:734 Write a file "pages/Matplotlib_Demo.py"
1:36:42186 0:00:00001 0:00:01841   2ded76ba-c2e8-456e-b032-d5d95c8e3153:734 Write a file "pages/Hiplot_Demo.py"
1:36:42186 0:00:00000 0:00:01841   2ded76ba-c2e8-456e-b032-d5d95c8e3153:737 Loading the initially necessary packages
1:36:42389 0:00:00203 0:00:02044 0:00:00203 2ded76ba-c2e8-456e-b032-d5d95c8e3153:742 Loaded the initially necessary packages
1:36:42389 0:00:00000 0:00:02044   2ded76ba-c2e8-456e-b032-d5d95c8e3153:743 Loading tornado, pyarrow, and streamlit
1:36:45245 0:00:02856 0:00:04900 0:00:02856 2ded76ba-c2e8-456e-b032-d5d95c8e3153:749 Loaded tornado, pyarrow, and streamlit
1:36:45245 0:00:00000 0:00:04900   2ded76ba-c2e8-456e-b032-d5d95c8e3153:750 Installing the requirements: (2) ['matplotlib', 'hiplot']
1:36:47127 0:00:01882 0:00:06782 0:00:01882 2ded76ba-c2e8-456e-b032-d5d95c8e3153:758 Installed the requirements: (2) ['matplotlib', 'hiplot']
1:36:47128 0:00:00001 0:00:06783   2ded76ba-c2e8-456e-b032-d5d95c8e3153:759 Setting the loggers
1:36:52839 0:00:05711 0:00:12494 0:00:05711 2ded76ba-c2e8-456e-b032-d5d95c8e3153:813 Set the loggers
1:36:52839 0:00:00000 0:00:12494   2ded76ba-c2e8-456e-b032-d5d95c8e3153:814 Defining the bootstrap functions
1:36:53300 0:00:00461 0:00:12955 0:00:00461 2ded76ba-c2e8-456e-b032-d5d95c8e3153:898 Defined the bootstrap functions
1:36:53300 0:00:00000 0:00:12955   2ded76ba-c2e8-456e-b032-d5d95c8e3153:899 Booting up the Streamlit server
1:36:53326 0:00:00026 0:00:12981   2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:matplotlib.pyplot:Loaded backend agg version unknown.
1:36:53328 0:00:00002 0:00:12983   2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.web.bootstrap:Setting up signal handler
1:36:53333 0:00:00005 0:00:12988   2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.web.server.server:Starting server...
1:36:53334 0:00:00001 0:00:12989   2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.web.server.server:Serving static content from /lib/python3.10/site-packages/streamlit/static
1:36:53336 0:00:00002 0:00:12991   2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.web.server.server:Server started on port 8501
1:36:53336 0:00:00000 0:00:12991   2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.web.server.server:Server state: State.INITIAL -> State.WAITING_FOR_FIRST_SESSION
1:36:53550 0:00:00214 0:00:13205   2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:git.cmd:Popen(['git', 'version'], cwd=/home/pyodide, universal_newlines=False, shell=None, istream=None)
1:36:53560 0:00:00010 0:00:13215   2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): checkip.amazonaws.com:80
1:36:53563 0:00:00003 0:00:13218   2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.version:Skipping PyPI version check
1:36:53564 0:00:00001 0:00:13219 0:00:00264 2ded76ba-c2e8-456e-b032-d5d95c8e3153:915 Booted up the Streamlit server
1:36:53564 0:00:00000 0:00:13219   2ded76ba-c2e8-456e-b032-d5d95c8e3153:916 Setting up the HTTP server
1:36:53575 0:00:00011 0:00:13230 0:00:00011 2ded76ba-c2e8-456e-b032-d5d95c8e3153:922 Set up the HTTP server
1:36:53610 0:00:00035 0:00:13265   2ded76ba-c2e8-456e-b032-d5d95c8e3153:947 websocket:connect {path: 'stream'}
1:36:53613 0:00:00003 0:00:13268   2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.runtime.app_session:AppSession initialized (id=c2085e72-6659-4edb-b056-7b530553aaee)
1:36:53613 0:00:00000 0:00:13268   2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.web.server.server:Created new session for client 76291888. Session ID: c2085e72-6659-4edb-b056-7b530553aaee
1:36:53614 0:00:00001 0:00:13269   2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.web.server.server:Server state: State.WAITING_FOR_FIRST_SESSION -> State.ONE_OR_MORE_SESSIONS_CONNECTED
1:36:53615 0:00:00001 0:00:13270   2ded76ba-c2e8-456e-b032-d5d95c8e3153:973 websocket:send {payload: Uint8Array(10)}
1:36:53616 0:00:00001 0:00:13271   2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.web.server.browser_websocket_handler:Received the following back message:rerun_script { widget_states { }}
1:36:53988 0:00:00372 0:00:13643   2ded76ba-c2e8-456e-b032-d5d95c8e3153:783 DEBUG:streamlit.web.server.server:Script run finished successfully; removing expired entries from MessageCache (max_age=2)

whitphx avatar Aug 30 '22 16:08 whitphx

The most important bottleneck is importing the streamlit package, but parallelizing it with other processings did not work; https://docs.google.com/spreadsheets/d/1sxwF2mdzl26__x-xqRyaCAds5ECBJd7_2ZRcZoLttdI/edit#gid=2112516876 maybe because it took 100% CPU anyway.

whitphx avatar Aug 30 '22 18:08 whitphx

So, #163 may contribute this issue as it reduces the package size to load.

whitphx avatar Aug 31 '22 11:08 whitphx