Repository navigation
RustPython initialization is slow #1047
Description
Activity
Well, sadly It's not as straightforward as doing a simple git-bisect to find what's causing this, because many commits are broken and either not compiling / panicking, and the "good" execution time for my little benchmark is inconsistent.
Anyways, I suspect that maybe some of the "importlib" changes are causing this because this is around the time that execution time skyrockets from ~0.120 to 0.7-2 for me
EDIT:
@palaviv @windelbouwmanOkay, it is indeed caused by this pull request: #1018.
before e88d6ac:
$ git checkout 7ff59b27d77941465226c4157614f5b210bf25de $ time target/debug/rustpython tests/snippets/strings.py target/debug/rustpython tests/snippets/strings.py 0.26s user 0.01s system 99% cpu 0.271 totalNow notice the increase
$ git checkout e88d6ac1ef5f7e683f9a993b5a613bd16e868afe $ time target/debug/rustpython tests/snippets/strings.py target/debug/rustpython tests/snippets/strings.py 0.56s user 0.00s system 99% cpu 0.562 totalIf we test the last commit of the PR, that we get the abnormal execution time again:
$ git checkout 1de9f73bd076b559189841de72446a96e1c7ffd2 $ time target/debug/rustpython tests/snippets/strings.py target/debug/rustpython tests/snippets/strings.py 2.85s user 0.04s system 99% cpu 2.918 totalThat's odd though, because import machinery itself only takes ~15% of the execution time, you can test by changing the top of the file to:
import time t1 = time.time() from testutils import assert_raises print(time.time() - t1)
$ time target/debug/rustpython tests/snippets/strings.py 0.333484411239624 Hurray! target/debug/rustpython tests/snippets/strings.py 2.19s user 0.00s system 99% cpu 2.203 totalMaybe there was some other change in #1018 that caused this performance regression?
Although, maybe it's importlib intialization, just running
vm.run_code_obj(<importlib>)Edit: No, that only takes ~300ms, and happens almost immediately; the majority of the delay occurs after.
Yeah, this is so weird! Look at this:
$ time target/debug/rustpython tests/snippets/strings.py top of main(): SystemTime { tv_sec: 1560999593, tv_nsec: 403368144 } top of _run_script(): SystemTime { tv_sec: 1560999594, tv_nsec: 477420455 } top of _run_string(): SystemTime { tv_sec: 1560999594, tv_nsec: 477691635 } top of strings.py: 1560999594.6324782 Hurray! target/debug/rustpython tests/snippets/strings.py 1.57s user 0.01s system 99% cpu 1.579 totalMost of the delay happens before the file is even loaded or parsed! Here's an asciinema to better illustrate the time at which they're logged.
Ah, it is
init_importlibcausing the delay: https://asciinema.org/a/Dkk7w3Y1MvDWBYb8FGqRoU3sZEdit: the two largest delays from the function come from
vm.invoke()ing functions exported from_frozen_importlib. I don't know if there's any real way to optimize this beyond just optimizing the vm in general, or maybe moving some importlib functionality to rust (at least temporarily).I have not tried the rust profiling tools, but this might be a good moment to try them out!
- changed the title
[-]RustPython became extremely slow due to recent changes[/-][+]RustPython initialization is slow[/+]on Jun 20, 2019 the two largest delays from the function come from
vm.invoke()ing functions exported from_frozen_importlib. I don't know if there's any real way to optimize this beyond just optimizing the vm in general, or maybe moving some importlib functionality to rust (at least temporarily).CPython also have some of the functions implemented in C for optimization. The better solution is probably trying to make RustPython faster 😏
Reacted by MichelOS and Boris VerkhovskiyDid anyone take a look at the logging? Each function invocation is logged using the rust logger. This might be overkill. Also, creation of exceptions is logged. Could this be causing the slow down?
A recent change probably made the interpreter extremely slow, this can be demonstrated by a simple benchmark:
I'm currently doing a
git-bisectto identify which change introduced the poor performance, and I'll update what I find.