Opened 18 months ago

Closed 17 months ago

Last modified 17 months ago

#26908 closed defect (fixed)

py3: Speed up deprecated_function_alias

Reported by: embray Owned by:
Priority: critical Milestone: sage-8.6
Component: python3 Keywords:
Cc: chapoton, jdemeyer Merged in:
Authors: Erik Bray Reviewers: Simon King
Report Upstream: N/A Work issues:
Branch: 6131b10 (Commits) Commit:
Dependencies: Stopgaps:

Description

In profiling areas of slowdown during import, one culprit (of likely several) I found was deprecated_function_alias.

This was called 80 times during import sage.all, and profiling suggests that a pretty absurd amount time in this, particularly on the line

frame1 = inspect.getouterframes(inspect.currentframe())[1][0]

On Python 2 kernprof gives:

   513        80        365.0      4.6      0.0      _check_trac_number(trac_number)
   514        80    1400403.0  17505.0     99.7      frame1 = inspect.getouterframes(inspect.currentframe())[1][0]
   515        80       2378.0     29.7      0.2      module_name = inspect.getmodulename(frame1.f_code.co_filename)
   516        80         78.0      1.0      0.0      if module_name is None:
   517                                                   module_name = '__main__'
   518        80       1944.0     24.3      0.1      return DeprecatedFunctionAlias(trac_number, func, module_name)

(where times are in microseconds). This shows we're spending at least 1.5 seconds in this function alone which is not great even for Python 2, and is something worth looking into. But on Python 3 it's absurd:

   513        80        354.0      4.4      0.0      _check_trac_number(trac_number)
   514        80   42581328.0 532266.6    100.0      frame1 = inspect.getouterframes(inspect.currentframe())[1][0]
   515        80       3287.0     41.1      0.0      module_name = inspect.getmodulename(frame1.f_code.co_filename)
   516        80         96.0      1.2      0.0      if module_name is None:
   517                                                   module_name = '__main__'
   518        80       2856.0     35.7      0.0      return DeprecatedFunctionAlias(trac_number, func, module_name)

Change History (20)

comment:1 Changed 18 months ago by embray

Marvelous--just replacing inspect.getouterframes(inspect.currentframe())[1][0], which was needlessly cumbersome, with inspect.currentframe().f_back speeds this up by about 10000x 🤣

Last edited 18 months ago by embray (previous) (diff)

comment:2 Changed 18 months ago by embray

  • Authors set to Erik Bray
  • Branch set to u/embray/python3/misc/deprecated-function-alias
  • Commit set to 6131b10e15eb12ee1cbc29cd68e3433829f30f44
  • Milestone changed from sage-8.6 to sage-8.5
  • Priority changed from major to critical
  • Status changed from new to needs_review

New commits:

3843114py3: speed up deprecated_function_alias
6131b10misc minor cleanup

comment:3 Changed 18 months ago by chapoton

Can you explain the removal of

-    _check_trac_number(trac_number)

?

comment:4 Changed 18 months ago by embray

It's redundant.

comment:5 Changed 18 months ago by chapoton

green bot. Ok for me.

Your opinion, Jeroen ?

comment:6 follow-up: Changed 18 months ago by SimonKing

Do I understand correctly: Much time is spent on inspecting stack frames, in order to find out module names? Is that necessary at all? Or *if* it is: Could it perhaps be made more lazily, so that stack frame inspection will only happen if a deprecated function actually is used?

You said the profiling of Sage startup was done with kernprof. How exactly, i.e., what command?

comment:7 in reply to: ↑ 6 ; follow-up: Changed 18 months ago by embray

Replying to SimonKing:

Do I understand correctly: Much time is spent on inspecting stack frames, in order to find out module names? Is that necessary at all? Or *if* it is: Could it perhaps be made more lazily, so that stack frame inspection will only happen if a deprecated function actually is used?

This has to do with figuring out where the DeprecatedFunctionAlias was defined, so it's has to happen at definition time. The way it's used is not actually very important and I thought about trying to do away with it entirely. But getting the previous stack frame (if one exists) is trivial to do, and the only problem with the existing code is that it was needlessly examining and constructing a data structure out of the entire stack.

You said the profiling of Sage startup was done with kernprof. How exactly, i.e., what command?

It's not that simple. kernprof alone can't analyze Sage startup times--this was just for line-profiling deprecated_function_alias itself since I had narrowed that down as a culprit for some slow to import modules.

comment:8 in reply to: ↑ 7 ; follow-up: Changed 18 months ago by SimonKing

Replying to embray:

Replying to SimonKing:

Do I understand correctly: Much time is spent on inspecting stack frames, in order to find out module names? Is that necessary at all? Or *if* it is: Could it perhaps be made more lazily, so that stack frame inspection will only happen if a deprecated function actually is used?

This has to do with figuring out where the DeprecatedFunctionAlias was defined,

What do you mean by that? Do you mean you want to find out the module of the function that is being deprecated? Why isn't that module determined in the same way that the module is determined for, say, CachedFunction?

You said the profiling of Sage startup was done with kernprof. How exactly, i.e., what command?

It's not that simple. kernprof alone can't analyze Sage startup times--this was just for line-profiling deprecated_function_alias itself since I had narrowed that down as a culprit for some slow to import modules.

I see. Anyway, if I understand correctly what module is being determined (namely the one of the function that is being deprecated), I don't see why a stack frame is relevant at all.

comment:9 follow-up: Changed 18 months ago by SimonKing

First of all, I can confirm a speedup for py2 (I am not testing py3): sage --startuptime gives 1103.930ms without the ticket and 798.564ms with the ticket.

One of the slowest imports without the ticket was

   24.867     24.946         35  sage.rings.finite_rings.integer_mod

With the ticket, importing integer_mod doesn't appear in the list of slowest imports at all -- and deprecated_function_alias only appears a single time in that module!

So, it is impressive.

And I think meanwhile I understand the problem that is solved by inspecting the stack: I thought when you do f = deprecated_function_alias(1234, g) then f.__module__ is supposed to be equal to g.__module__ (which wouldn't involve stack inspection). But now I realise that f.__module__ is supposed to be the module in which deprecated_function_alias is called, and that's of course something where inspecting the stack totally makes sense.

Last edited 18 months ago by SimonKing (previous) (diff)

comment:10 Changed 18 months ago by SimonKing

It would in principle be possible to replace the call to inspect.getmodulename(frame1.f_code.co_filename) by something faster:

sage: import inspect
sage: frame0 = inspect.currentframe()
sage: frame1 = frame0.f_back
sage: %timeit inspect.getmodulename(frame1.f_code.co_filename)
The slowest run took 4.96 times longer than the fastest. This could mean that an intermediate result is being cached.
100000 loops, best of 3: 6.06 µs per loop
sage: cython('''
....: import os
....: cdef str slash = os.path.sep
....: cdef str dot = os.path.extsep
....: def extract(str name):
....:     return name[name.rfind(slash)+1:name.rfind(dot)]
....: ''')
sage: extract(frame1.f_code.co_filename)
'interactiveshell'
sage: %timeit extract(frame1.f_code.co_filename)
The slowest run took 17.48 times longer than the fastest. This could mean that an intermediate result is being cached.
1000000 loops, best of 3: 341 ns per loop
sage: inspect.getmodulename(frame1.f_code.co_filename) == extract(frame1.f_code.co_filename)
True

However, I am not sure if enough deprecated function aliases are created so that an improvement from 6µs to 341ns could be noticed in startup time. Also I am not sure if the above implementation of the name extraction is 100% correct.

comment:11 in reply to: ↑ 9 ; follow-up: Changed 18 months ago by SimonKing

Replying to SimonKing:

But now I realise that f.__module__ is supposed to be the module in which deprecated_function_alias is called, and that's of course something where inspecting the stack totally makes sense.

On the other hand: Couldn't that simply be passed as a parameter? Granted, it would mean to change

king@klap:~/Sage/git/sage$ grep "deprecated_function_alias(" -R src/sage | wc -l
123

places in the sage library. But a change from deprecated_function_alias(1234, f) to deprecated_function_alias(1234, f, __name__) could easily be done with a little script. And since __name__ is the name of the module in which deprecated_function_alias is currently being executed, it would solve the problem without any slow introspection.

So, would adding ..., __name__) in 123 places be acceptable?

comment:12 in reply to: ↑ 11 Changed 18 months ago by SimonKing

Replying to SimonKing:

So, would adding ..., __name__) in 123 places be acceptable?

Too bad. Even if it was acceptable, it turns out that doing the change (I just did) only improves the startup time by 6ms or so.

comment:13 follow-up: Changed 18 months ago by chapoton

Thanks a lot, Simon, for taking the time to do an analysis in depth. Can we now set this to positive without further delay ?

comment:14 in reply to: ↑ 13 ; follow-up: Changed 18 months ago by SimonKing

Replying to chapoton:

Thanks a lot, Simon, for taking the time to do an analysis in depth. Can we now set this to positive without further delay ?

Yes, of course!

Replying to embray:

Replying to SimonKing:

You said the profiling of Sage startup was done with kernprof. How exactly, i.e., what command?

It's not that simple. kernprof alone can't analyze Sage startup times--this was just for line-profiling deprecated_function_alias itself since I had narrowed that down as a culprit for some slow to import modules.

I still would like to understand how you found out that deprecated_function_alias was responsible for slow startup time. sage --startuptime <module_name> only tells what modules are slow to import, but not why. I somehow feel challenged to try to improve startup time further...

comment:15 in reply to: ↑ 8 Changed 18 months ago by embray

Replying to SimonKing:

Replying to embray:

Replying to SimonKing:

Do I understand correctly: Much time is spent on inspecting stack frames, in order to find out module names? Is that necessary at all? Or *if* it is: Could it perhaps be made more lazily, so that stack frame inspection will only happen if a deprecated function actually is used?

This has to do with figuring out where the DeprecatedFunctionAlias was defined,

What do you mean by that? Do you mean you want to find out the module of the function that is being deprecated? Why isn't that module determined in the same way that the module is determined for, say, CachedFunction?

I mean, I didn't write the code, so it's not about what I want. But it's just determining what module the actual DeprecatedFunctionAlias was created in, and it uses this information to determine whether or not it's in the same module as the deprecated function. It's not very important, but this is a normal (albeit CPython-specific) way to do this.

comment:16 in reply to: ↑ 14 Changed 18 months ago by embray

Replying to SimonKing:

I still would like to understand how you found out that deprecated_function_alias was responsible for slow startup time. sage --startuptime <module_name> only tells what modules are slow to import, but not why. I somehow feel challenged to try to improve startup time further...

Perhaps when I have more time I will write up something on this subject. Profiling module-level code and import times in Python turns out to be surprisingly difficult, as most Python profiling tools are geared toward just profiling individual functions, and it's not always trivial to just wrap up the contents of a module in a function, especially with Cython.

However, there's no good technical reason for this: Modules can be profiled just the same as functions, there just isn't good tooling for it. I would like, when I have more time, to develop better tooling since it would be very helpful for large projects like Sage.

Another somewhat useful tool for this was added in Python 3.7: python -X importtime which prints a report of all time spent in module imports. Prior to this there was a package called import-profiler, but it does not work as well in all cases, whereas the new feature included in Python is built right into the import system and works better overall. In order to help with this I backported that feature to Python 3.6 and added a patch for it. This might be worth including with Sage until we upgrade to Python 3.7, or at very least I can make my patch available somewhere.

comment:17 Changed 18 months ago by embray

  • Reviewers set to Simon King
  • Status changed from needs_review to positive_review

comment:18 Changed 18 months ago by embray

I didn't even know about sage --startuptime. Or rather, I did know about it at one time (I know I've used it before) but completely forgot about it. It seems to work similarly to import-profiler (by replacing __import__). The new import profiler baked into Python is still better in some ways, though I'm not wild about its output format, which could use improvement. It would also be nice if it collected the raw data into an object that was available somewhere, perhaps either in the sys module or in importlib. Perhaps I'll suggest that upstream...

comment:19 Changed 17 months ago by vbraun

  • Branch changed from u/embray/python3/misc/deprecated-function-alias to 6131b10e15eb12ee1cbc29cd68e3433829f30f44
  • Resolution set to fixed
  • Status changed from positive_review to closed

comment:20 Changed 17 months ago by embray

  • Commit 6131b10e15eb12ee1cbc29cd68e3433829f30f44 deleted
  • Milestone changed from sage-8.5 to sage-8.6
Note: See TracTickets for help on using tickets.