RustPython initialization is slow #1047

Activity

1. michelhe commented on Jun 19, 2019

   

   michelhe

   on Jun 19, 2019

   Last edited by michelhe

   ContributorAuthor

   More actions

   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 @windelbouwman

   Okay, 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 total

   Now 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 total

   If 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 total
2. coolreader18 commented on Jun 20, 2019

   

   coolreader18

   on Jun 20, 2019

   Last edited by coolreader18

   Member

   More actions

   That'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 total
   

   Maybe there was some other change in #1018 that caused this performance regression?
3. coolreader18 commented on Jun 20, 2019

   

   coolreader18

   on Jun 20, 2019

   Last edited by coolreader18

   Member

   More actions

   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.
4. coolreader18 commented on Jun 20, 2019

   

   coolreader18

   on Jun 20, 2019

   Member

   More actions

   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 total
   

   Most 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.
5. coolreader18 commented on Jun 20, 2019

   

   coolreader18

   on Jun 20, 2019

   Last edited by coolreader18

   Member

   More actions

   Ah, it is init_importlib causing the delay: https://asciinema.org/a/Dkk7w3Y1MvDWBYb8FGqRoU3sZ

   Edit: 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).
6. windelbouwman commented on Jun 20, 2019

   

   windelbouwman

   on Jun 20, 2019

   Contributor

   More actions

   I have not tried the rust profiling tools, but this might be a good moment to try them out!
7. michelhe

   changed the title [-]RustPython became extremely slow due to recent changes[/-] [+]RustPython initialization is slow[/+] on Jun 20, 2019
8. palaviv commented on Jun 20, 2019

   

   palaviv

   on Jun 20, 2019

   Contributor

   More actions

   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 😏

   👍React with 👍2Reacted by MichelOS and Boris Verkhovskiy
9. windelbouwman commented on Jul 6, 2019

   

   windelbouwman

   on Jul 6, 2019

   Contributor

   More actions

   Did 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?
10. youknowone

    closed this as completedon Jul 6, 2022