Add option to profile dynamic_functions

[arwedus]

Hi @danwos, we are experiencing slow build times in our project. A first profiling analysis with py-spy showed that a lot of time is spent in the write phase, and most of that time is spent in sphinx-needs. We suspect dynamic functions to be an issue, but we can't easily test because there is no "global dynamic function ignore" Option. So the first thing I want to do is to add a sphinx-internal profiler option for summarizing CPU time spent in dynamic functions:

https://sphinx-needs.readthedocs.io/en/latest/performance/index.html#profiling

• add NEEDS_DYNAMIC_FUNCTIONS as an option to NEEDS_PROFILING please :)

[danwos]

Using the profiler here will not be so easy, as there are multiple dynamic functions that need to get their own profiling.
Also the current implementation stores the profile of the last call only, so you don't get any information like:

• How often was the function executed?
• What are min, max and avg execution time?
• What are the given arguments for the max time?

I think the above information is more important for the beginning, to get an overview of what gets executed and where the bottleneck is. After that using profiling would be the next step.

So here is my technical concept proposal :)

Technical concept

• Provide a function and wrapper measure, which measures the execution amount and time of selected functions.

• measure() shall take the following parameters

  • name: Used name in documentation
  • *args: send to original function
  • **kwargs: send to original function

• Store the final results in a json file. Contains:

  • min, max, avg and ags/kwargs of max executed call

• Provide a new config option needs_debug_measurement. If True all implemented measurements will be activated. So no specific selection of an area, like for profiling.

• Implement measurements for the following features/functions:

  • dynamic functions. One measurement per function!
  • filter functions. One measurement per function!
  • needtable
  • needflow
  • Bigger blocks like Read & Write phase or events (not sure if easily doable)

• Add a new directive needmeasurments, which takes the json result and adds a small report to the sphinx documentation. Maybe the measurement keyword can be given.

[arwedus]

Using the profiler here will not be so easy, as there are multiple dynamic functions that need to get their own profiling. Also the current implementation stores the profile of the last call only, so you don't get any information like:

* How often was the function executed?
* What are min, max and avg execution time?
* What are the given arguments for the `max` time?

In my opinion, this is a huge pitfall... I'll open another issue to request that the needs profiler accumulates over all calls 😄

I think the above information is more important for the beginning, to get an overview of what gets executed and where the bottleneck is. After that using `profiling* would be the next step.

So here is my technical concept proposal :)

* Provide a function and wrapper `measure`, which measures the execution amount and time of selected functions.

Cool! Especially it would help to see which dynamic function is executed how often and how much time that costs. Regarding names: Maybe use measure_time() because you could also measure memory usage, number of printfs, etc... ;-)

Maybe you can use a decorator function for the dynamic functions to transparently add or remove the needs_debug_measurement feature.

The needmeasurements directive is a nice-to-have, imho, but not a must.

[danwos]

I created a first prototype, which can measure the execution time of internal functions.
But no support for dynamic functions, yet. But this should be done fast.
Draft PR #919

It allows the decoration of certain functions in the code via @measure_time().

And if needs_debug_measurement is set in conf.py to True, all of these functions will get measured and the following reporting is done:

• Small print out on console
• JSON file with all data, incl. function name, path, line number and docs. In build folder
• Ugly HTML report.. In build folder

Steps to do:

• Activate it for dynamic and filter functions
• Write documentaation
• Write test cases
• Figure out how big the overhead is if activated.
• Test it with bigger docs
• Solve all the linter problems....

Console output

HTML output

JSON Structure

[danwos]

Small update in the PR:

• Dynamic functions and filter functions get measured
• Measurements are now categorized and the source (internal, user) is stored
• Better HTML report with more data

From the function point of view, I'm happy with the current status.
Will finalize docs and tests and that's it :)