using pyinstrument to log traceback of slow callbacks

[GitHK]

What do these changes do?

During the analysis of logs coming from production there were lots of entries similar to:

servicelib.monitor_slow_callbacks:instrumented(28) - Executing <Task finished coro=<Application._handle() done, defined at /home/scu/.venv/lib/python3.6/site-packages/aiohttp/web_app.py:428> result=<Response OK not prepared>> took 7.647 seconds

Adding pyinstrument.Profiler will help format the output of the slow callbacks. A full traceback of the call will be logged.

WARNING: there is a slight performance hit for running the profiler. I think this is worth it in order to have more meaningful log messages which will help debugging the stack.

Trivia

While looking for the current solution, aioprof was considered and in part used as inspiration. Our codebase already had most of the tests and implementation in place to easily integrate pyinstrument on top of which aioprof is built.

Related issue/s

How to test

Checklist

[codecov]

Codecov Report

Merging #2341 (56f5466) into master (36c96bf) will increase coverage by 0.0%.
The diff coverage is 100.0%.

@@          Coverage Diff           @@
##           master   #2341   +/-   ##
======================================
  Coverage    72.0%   72.1%           
======================================
  Files         509     509           
  Lines       20022   20025    +3     
  Branches     1969    1969           
======================================
+ Hits        14431   14445   +14     
+ Misses       5104    5097    -7     
+ Partials      487     483    -4     

Flag	Coverage Δ
integrationtests	62.0% <ø> (+<0.1%)	⬆️
unittests	67.5% <100.0%> (+<0.1%)	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

Impacted Files	Coverage Δ
...e-library/src/servicelib/monitor_slow_callbacks.py	100.0% <100.0%> (ø)
.../director/src/simcore_service_director/producer.py	61.7% <0.0%> (+1.0%)	⬆️
...ce_webserver/resource_manager/garbage_collector.py	77.6% <0.0%> (+1.8%)	⬆️
...webserver/computation_comp_tasks_listening_task.py	86.0% <0.0%> (+2.0%)	⬆️

[mguidon]

I like statistical profilers. I guess you checked joerick/pyinstrument#83?

[sanderegg]

the indentation to check maybe?

[pcrespov]

Since you add a new dependency in a library, you should compile the requirements of the services it includes

1. search which services are affected by

grep --include=\*.in -nrw  -e 'packages/service-library/requirements/_base.in'

2. compile upgrade each service

cd services/service/requirements
make touch
make reqs upgrade=pyinstrument

[GitHK]

Nice one, will do this.

[GitHK]

Ran this on all packages and no other packages require extra dependencies.
There are only some dependencies which are trying to be updated, like pytest-coverage etc... Those are out of the scope of this PR, will ignore them.

[pcrespov]

did you use upgrade=pyinstrument option?? That should not happen!

[GitHK]

I always forget about that option, usually I end up checking stuff manually.

[pcrespov]

@GitHK Please do not forget to upgrade the requirements of the services!
Right now it works because the servicelib setup is installing pyinstrument but the frozen requirements do not show all the dependencies

[GitHK]

I like statistical profilers. I guess you checked joerick/pyinstrument#83?

Sadly enough I've checked this. If there would be a big performance downfall I would remove the library and revert back to the previous implementation.