Slow Tracebacks for Large Files

[mlucool]

IPython 8's tracebacks are much slower than IPython 7's for large files.

Reproducer:

$ cat make_repro.py 
#!/usr/bin/env python

fn = '''
def f():
   1/0
'''

for module, lines in [('r0', 0), ('r4', 1e4), ('r5', 1e5), ('r6', 1e6)]:
    with open(f'{module}.py', "w") as f:
        f.write(fn)
        f.write("\n'''\n")
        line = "x"*79 + "\n"
        for i in range(int(lines)):
            f.write(line)
        f.write("\n'''\n")

$ for r in r*.py; do module=`basename -s .py $r`; time ipython -c "from $module import f; f()"; done

IPython 8.4.0:

---------------------------------------------------------------------------
ZeroDivisionError                         Traceback (most recent call last)
Input In [1], in <cell line: 1>()
----> 1 from r0 import f; f()

File /var/tmp/udoff/r0.py:3, in f()
      2 def f():
----> 3    1/0

ZeroDivisionError: division by zero

real    0m1.426s
user    0m1.054s
sys 0m0.083s
---------------------------------------------------------------------------
ZeroDivisionError                         Traceback (most recent call last)
Input In [1], in <cell line: 1>()
----> 1 from r4 import f; f()

File /var/tmp/udoff/r4.py:3, in f()
      2 def f():
----> 3    1/0

ZeroDivisionError: division by zero

real    0m1.315s
user    0m1.142s
sys 0m0.087s
---------------------------------------------------------------------------
ZeroDivisionError                         Traceback (most recent call last)
Input In [1], in <cell line: 1>()
----> 1 from r5 import f; f()

File /var/tmp/udoff/r5.py:3, in f()
      2 def f():
----> 3    1/0

ZeroDivisionError: division by zero

real    0m2.212s
user    0m1.934s
sys 0m0.190s
---------------------------------------------------------------------------
ZeroDivisionError                         Traceback (most recent call last)
Input In [1], in <cell line: 1>()
----> 1 from r6 import f; f()

File /var/tmp/udoff/r6.py:3, in f()
      2 def f():
----> 3    1/0

ZeroDivisionError: division by zero

real    0m12.551s
user    0m10.453s
sys 0m1.999s

IPython 7.34.0:

---------------------------------------------------------------------------
ZeroDivisionError                         Traceback (most recent call last)
<ipython-input-1-71f710d9a180> in <cell line: 1>()
----> 1 from r0 import f; f()

/var/tmp/udoff/r0.py in f()
      1 
      2 def f():
----> 3    1/0
      4 
      5 '''

ZeroDivisionError: division by zero

real    0m0.652s
user    0m0.500s
sys 0m0.072s
---------------------------------------------------------------------------
ZeroDivisionError                         Traceback (most recent call last)
<ipython-input-1-be51f15d008d> in <cell line: 1>()
----> 1 from r4 import f; f()

/var/tmp/udoff/r4.py in f()
      1 
      2 def f():
----> 3    1/0
      4 
      5 '''

ZeroDivisionError: division by zero

real    0m0.638s
user    0m0.492s
sys 0m0.059s
---------------------------------------------------------------------------
ZeroDivisionError                         Traceback (most recent call last)
<ipython-input-1-7ac18e0836d0> in <cell line: 1>()
----> 1 from r5 import f; f()

/var/tmp/udoff/r5.py in f()
      1 
      2 def f():
----> 3    1/0
      4 
      5 '''

ZeroDivisionError: division by zero

real    0m0.688s
user    0m0.526s
sys 0m0.075s
---------------------------------------------------------------------------
ZeroDivisionError                         Traceback (most recent call last)
<ipython-input-1-dcfb9d2b4330> in <cell line: 1>()
----> 1 from r6 import f; f()

/var/tmp/udoff/r6.py in f()
      1 
      2 def f():
----> 3    1/0
      4 
      5 '''

ZeroDivisionError: division by zero

real    0m0.944s
user    0m0.689s
sys 0m0.167s

Can this be fixed (aside from making our files smaller)? We have seen these slow tracebacks in some larger real world modules due to their file size (e.g. Pandas.Seriesis 6.4k LOC).

[Carreau]

Hum, it looks like it's in Python tokenize itself:

In [2]: %%timeit
   ...: buf.seek(0)
   ...: list(generate_tokens(buf.readline))
7.46 s ± 25.8 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)

The chain dependency is long ipython->stack_data->executing->asttokens->python's generate_token, but it seem to be called greedily, i'll see if I can make lazy, or optimized.

[Carreau]

I can potentially see another place that is slow, and that would be easier to improve for complex ast trees which might be a better read world example.

[Carreau]

@alexmojaki I've tracked that down to a few things (depending of the type of files you try it on):

• asttokens' mark_tokens functions that is greedily called in ASTTokens's contructors,
• _expand_to_matching_pairs, and in particular for tok in self._code.token_range(first_token, last_token)
• patched_generate_tokens(original_tokens), but it's own timing seem to often be the tokenize module of CPython being slow.

I'll see if I can com up with improvements, but I thought it might be of interest, and maybe you have better ideas as to whether mark_tokens can be made lazy maybe?

[alexmojaki]

I actually think the way forward is to stop using asttokens in stack_data for Python >= 3.8. All that's needed is the range of source positions. It's not quite as simple as ast.get_source_segment, but it's close.

Sorry for not replying sooner :disappointed: But optimisations in asttokens are still appreciated :pray:

[Carreau]

No worries, If you have thoughts or another issue, I can have a look and try to implement it.

[alexmojaki]

@Carreau see link above

[mlucool]

As another option, would it be possible to add an opt-out flag somewhere that would save most of this time?

[Carreau]

This was part of a large refactor for 8.0 and would be quite hard to put behind a flag, I'll look into the link that @alexmojaki posted and see what difference this makes. I've also seen tokenize perf improvement on Python 3.11 that should also speedup tracebacks.

[alexmojaki]

@Carreau you don't have to actually do anything, I just thought I should keep you in the loop a bit. There's still work to do that will take a bit of time, but it should all be within stack_data and asttokens and not require any changes in IPython. The result should be no tokenizing being done at all.

I can definitely imagine a flag which switches to entirely plain traces using the standard traceback module still being useful sometimes for various reasons.

[alexmojaki]

Finally done! pip install -U asttokens. For me, it's more than twice as fast as before.