Slow inspect.getmodule

[mdeck]

Bug report

inspect.getmodule is slow. It becomes slower as len(sys.modules) grows. It is slower with modules that don't resolve to valid file paths. This causes inspect.stack and others to be slow as well.

def run_test(module):
    # cols have stack depths
    # rows have len(sys.modules)

    def print_line(h, *vals):
        if not h:
            print("%5s" % h, *["%6i" % v for v in vals])
        else:
            print("%5s" % h, *["%6.1f" % v for v in vals])

    def add_modules(n):
        import random
        import sys
        for _ in range(n):
            sys.modules[f"foo_{random.randint(0,2**64)}"] = module

    def measure(depth):
        import inspect
        import timeit

        def nest(level):
            if level > 0:
                return nest(level-1)
            else:
                dur = timeit.timeit(lambda: inspect.stack(), number=1)
                return dur * 1000

        return nest(depth)

    import sys
    print_line("", *[2**e for e in range(7)])
    for i in range(1, 5):
        add_modules(n=10**i)
        times = [measure(depth=2**e) for e in range(7)]
        print_line(len(sys.modules), *times)

python 3.11.0a7+ optimized build ====

# sys has no __file__ and doesn't enter getmodule cache
>>> import sys
>>> run_test(sys)
           1      2      4      8     16     32     64
   87    2.1    0.8    1.0    1.3    2.0    3.3    6.1
  187    2.0    2.5    2.7    3.6    5.5    9.5   16.8
 1187   13.6   15.7   19.1   26.3   39.6   67.4  123.3
11187  134.1  150.3  183.4  252.0  383.5  750.3 1189.8
>>> exit()

>>> import random
>>> run_test(random)
           1      2      4      8     16     32     64
   87    2.1    0.7    0.9    1.2    1.7    2.9    5.6
  187    2.3    1.1    1.5    1.8    2.5    4.3    7.8
 1187   17.0    4.3    5.6    7.1   11.1   18.6   33.9
11187  164.6   37.4   45.7   61.6   94.7  161.0  297.7
>>> exit()

Tables show time in milliseconds for a single inspect.stack() call.
Rows show len(sys.modules)
Columns indicate stack depth

Your environment

• CPython versions tested on: 3.9, 3.11.0a7+
• Operating system and architecture: MacOS, Linux, x64

• PR: gh-92041: Improve performance of inspect.getmodule #92042

[mdeck]

Looking at the test data, we see inspect.stack (also inspect.getouterframes) can take over 1 second (!!) in worst case with many loaded fileless modules and a deep call stack.

Even the typical case performs poorly - 187 modules and 8 frame call stack takes almost 2 milliseconds. Note this is with code pasted into REPL, so all the frames are within uncached moduleless frames (the worst case)

#92042 reduces duration using simple caching to avoid recursion and repeated sys.modules iteration.

Here is before & after, running test from a file instead of REPL (a more typical use case)
Times are in microseconds.
Built with ./configure --enable-optimizations --with-lto && make

[user@web-mike cpython]$ ./python test2.py
            1       2       4       8      16      32      64
   84  1504.3   247.2   265.3   319.6   397.0   580.1   970.6
  184  1536.3   277.7   394.9   349.2   422.3   598.2   961.2
 1184 13072.9   609.7   623.0   707.7   755.6   930.5  1285.6
11184 128188.3  4158.7  4555.3  4520.9  4198.8  4621.4  5598.8


[user@web-mike cpython]$ ./python test2.py
            1       2       4       8      16      32      64
   84  1482.6   220.9   203.7   255.4   341.4   535.7   918.2
  184   177.0   173.3   206.0   238.2   333.1   521.5   893.3
 1184   169.5   174.8   195.4   236.5   335.7   507.6   890.7
11184   181.3   174.7   196.7   251.6   475.7   647.1   904.4

(updated to show test with random inserted into sys.modules rather than sys, more representative of typical case)

[mdeck]

Simply having the moduleless REPL frames somewhere in the stack has a profound effect on times:

[user@web-mike cpython]$ ./python 
Python 3.11.0a7+ (heads/fix_inspect:86299d7122, May  8 2022, 09:18:17) [GCC 11.2.1 20220127 (Red Hat 11.2.1-9)] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import test2
             1        2        4        8       16       32       64
   88   2173.5    744.0    752.5    786.6    884.1   1090.1   1436.8
  188   2190.7    971.2    985.1   1480.3   1154.5   1304.4   1641.8
 1188  15603.4   3451.0   3264.4   3621.6   3513.2   3515.2   3899.2
11188 149854.1  27962.3  27778.4  28494.4  27402.8  29099.0  29512.5
>>> import inspect
>>> len(inspect._moduleless)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
AttributeError: module 'inspect' has no attribute '_moduleless'
>>> exit()

[user@web-mike cpython]$ ./python 
Python 3.11.0a7+ (heads/fix_inspect:86299d7122, May  8 2022, 09:18:17) [GCC 11.2.1 20220127 (Red Hat 11.2.1-9)] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import test2
             1        2        4        8       16       32       64
   88   1934.9    339.8    332.1    366.6    473.4    659.9   1022.2
  188    301.6    300.5    336.0    368.7    468.4    627.7   1014.4
 1188    290.5    308.2    316.8    359.7    695.9    662.1   1010.0
11188    396.4    299.9    328.8    365.8    662.9    761.4    996.7
>>> import inspect
>>> len(inspect._moduleless)
8
>>> exit()

(updated to show test with random inserted into sys.modules rather than sys, more representative of typical case)

[asottile-sentry]

haven't tracked down the exact tracebacks that are being processed but this led to a huge slowdown for us at sentry moving from python 3.10 to python 3.11

in one worker type this went from inspect.stack taking 4% of execution time to 54%