Add profiling functionality to jobs.

[Kircheneer]

Closes: #DNE - discussed verbally

What's Changed

Add cProfile profiling flag to jobs when DEBUG is set in the config. Example output:

# nautobot-server runjob plugins/example_plugin.jobs/ExampleLoggingJob --data '{"interval": 2}' --profile --local
[15:57:31] Running plugins/example_plugin.jobs/ExampleLoggingJob...
15:57:31.012 INFO    nautobot.jobs.ExampleLoggingJob jobs.py                                run_job() :
  Running job (commit=False)
15:57:31.019 INFO    nautobot.jobs.ExampleLoggingJob jobs.py                                    log() :
  Running for 2 seconds.
15:57:32.021 INFO    nautobot.jobs.ExampleLoggingJob jobs.py                                    log() :
  Step 1
15:57:33.039 INFO    nautobot.jobs.ExampleLoggingJob jobs.py                                    log() :
  Step 2
15:57:33.049 INFO    nautobot.jobs.ExampleLoggingJob jobs.py                                    log() :
  None
15:57:33.059 INFO    nautobot.jobs.ExampleLoggingJob jobs.py                                    log() :
  Wrote profiling information to /tmp/5c4bc8c1-5fe8-4a67-9116-70d4d943e944.pstats.
15:57:33.059 INFO    nautobot.jobs.ExampleLoggingJob jobs.py                               _run_job() :
  job completed successfully
15:57:33.061 INFO    nautobot.jobs.ExampleLoggingJob jobs.py                                    log() :
  Database changes have been reverted automatically.
15:57:33.065 INFO    nautobot.jobs.ExampleLoggingJob jobs.py                               _run_job() :
  Job completed in 0 minutes, 2.06 seconds
        run: 1 success, 4 info, 0 warning, 0 failure
                default: Running for 2 seconds.
                info: Step 1
                info: Step 2
                success: None
                info: Wrote profiling information to /tmp/5c4bc8c1-5fe8-4a67-9116-70d4d943e944.pstats.
                info: Database changes have been reverted automatically.

Ran for 2 seconds
[15:57:33] plugins/example_plugin.jobs/ExampleLoggingJob: SUCCESS
[15:57:33] plugins/example_plugin.jobs/ExampleLoggingJob: Duration 0 minutes, 2.06 seconds
[15:57:33] Finished
# python
>>> import pstats
>>> stats = pstats.Stats("/tmp/5c4bc8c1-5fe8-4a67-9116-70d4d943e944.pstats")
>>> stats.sort_stats(pstats.SortKey.CUMULATIVE).print_stats(10)
Fri Mar 24 15:57:33 2023    /tmp/5c4bc8c1-5fe8-4a67-9116-70d4d943e944.pstats

         5860 function calls (5718 primitive calls) in 2.036 seconds

   Ordered by: cumulative time
   List reduced from 438 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    2.036    2.036 /source/examples/example_plugin/example_plugin/jobs.py:46(run)
        2    2.006    1.003    2.006    1.003 {built-in method time.sleep}
        4    0.000    0.000    0.029    0.007 /source/nautobot/extras/jobs.py:531(_log)
        4    0.000    0.000    0.029    0.007 /source/nautobot/extras/models/jobs.py:769(log)
        4    0.000    0.000    0.026    0.006 /usr/local/lib/python3.7/site-packages/django/db/models/base.py:685(save)
        4    0.000    0.000    0.025    0.006 /usr/local/lib/python3.7/site-packages/django/db/models/base.py:743(save_base)
        4    0.000    0.000    0.024    0.006 /usr/local/lib/python3.7/site-packages/django/db/models/base.py:822(_save_table)
        4    0.000    0.000    0.024    0.006 /usr/local/lib/python3.7/site-packages/django/db/models/base.py:914(_do_insert)
        4    0.000    0.000    0.024    0.006 /usr/local/lib/python3.7/site-packages/django/db/models/manager.py:84(manager_method)
        4    0.000    0.000    0.024    0.006 /usr/local/lib/python3.7/site-packages/django/db/models/query.py:1260(_insert)


<pstats.Stats object at 0xffffbb207e90>
>>> 

Open questions

• Should I make this available via
  • the API endpoint for running jobs?
  • the management command for running jobs?
  • the running of scheduled jobs?
• Is the way I'm outputting this to disk okay? Should it be configurable as to what the path is? I wanted to keep it as simple as possible.

TODO

• Explanation of Change(s)
• Added change log fragment(s) (for more information see the documentation)
• Attached Screenshots, Payload Example
• Unit, Integration Tests
• Documentation Updates (when adding/changing features)
• Outline Remaining Work, Constraints from Design

[glennmatthews]

Looks very cool!

Should I make this available via
the API endpoint for running jobs?
the management command for running jobs?
the running of scheduled jobs?

I think exposing it to the run_job management command would make the most sense. Since it's a debug-only feature I don't think there's any great need to add it to the API or to scheduled jobs.

Is the way I'm outputting this to disk okay? Should it be configurable as to what the path is? I wanted to keep it as simple as possible.

Seems fine as a local-development feature.

[glennmatthews]

Nits only. Nice feature!

[Kircheneer]

How should we handle job hook receivers? The CI is failing because (I believe) the way the forms are set up the _profile field is passed into job hook receivers as well. I guess people may want to profile job hook receivers as well, so should we support it? (CI Link: https://github.com/nautobot/nautobot/actions/runs/4594538893/jobs/8113771851?pr=3484#step:7:159)

[Kircheneer]

Decided not to handle that case for now and just fixed the unit test.

[bryanculver]

@jathanism @gsnider2195 Can you do a quick look of this to figure out how this will impact the code written for #765

[bryanculver]

A few comments @Kircheneer reviewed with fresh eyes.

I'd still like this to be on @gsnider2195's radar with the recent work in 2.0 for Jobs overhaul how this will need to be merged up.

[bryanculver]

Sorry for the late review @Kircheneer but I'm curious if we can assume /tmp is writable.

[gsnider2195]

Just a bit of feedback around testing but otherwise looks good and shouldn't cause any problems with 2.0

[gsnider2195]

Nice!