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

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?

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 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.

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).

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

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 😏

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?