Trace a gunicorn worker performance with pyinstrument

config.py

from pyinstrument import Profiler
from pyinstrument.renderers import JSONRenderer


def pre_request(worker, req):
    worker.profiler = Profiler()
    worker.profiler.start()


def post_request(worker, req, environ, resp):
    worker.profiler.stop()
    print(JSONRenderer().render(session=worker.profiler.last_session))
    print(worker.profiler.output_text(unicode=True, color=True))

gistfile1.txt

gunicorn pong:app --config=config.py --workers=1 --timeout 1000000
[2020-05-03 00:02:36 +0800] [22865] [INFO] Starting gunicorn 20.0.4
[2020-05-03 00:02:36 +0800] [22865] [INFO] Listening at: http://127.0.0.1:8000 (22865)
[2020-05-03 00:02:36 +0800] [22865] [INFO] Using worker: sync
[2020-05-03 00:02:36 +0800] [22867] [INFO] Booting worker with pid: 22867
{"start_time": 1588435357.814816,"duration": 1.003257,"sample_count": 2,"program": "Envs/twsgi/bin/gunicorn pong:app --config=config.py --workers=1 --timeout 1000000","cpu_time": 0.002044,"root_frame": {"function": "handle_request","file_path_short": "gunicorn/workers/sync.py","file_path": "Envs/twsgi/lib/python3.8/site-packages/gunicorn/workers/sync.py","line_no": 159,"time": 1.003180,"is_application_code": false,"children": [{"function": "__call__","file_path_short": "flask/app.py","file_path": "Envs/twsgi/lib/python3.8/site-packages/flask/app.py","line_no": 2460,"time": 1.002034,"is_application_code": false,"children": [{"function": "wsgi_app","file_path_short": "flask/app.py","file_path": "Envs/twsgi/lib/python3.8/site-packages/flask/app.py","line_no": 2417,"time": 1.002034,"is_application_code": false,"children": [{"function": "full_dispatch_request","file_path_short": "flask/app.py","file_path": "/Users/ryan/Envs/twsgi/lib/python3.8/site-packages/flask/app.py","line_no": 1938,"time": 1.002034,"is_application_code": false,"children": [{"function": "dispatch_request","file_path_short": "flask/app.py","file_path": "/Users/ryan/Envs/twsgi/lib/python3.8/site-packages/flask/app.py","line_no": 1914,"time": 1.002034,"is_application_code": false,"children": [{"function": "pong","file_path_short": "pong/__init__.py","file_path": "/Users/ryan/Dev/twsgi/examples/pong/pong/__init__.py","line_no": 8,"time": 1.002034,"is_application_code": true,"children": []}],"group_id": "0bda00b4-3145-4f53-af0b-96330e758593"}],"group_id": "0bda00b4-3145-4f53-af0b-96330e758593"}],"group_id": "0bda00b4-3145-4f53-af0b-96330e758593"}],"group_id": "0bda00b4-3145-4f53-af0b-96330e758593"}]}}


  _     ._   __/__   _ _  _  _ _/_   Recorded: 00:02:37  Samples:  2
 /_//_/// /_\ / //_// / //_'/ //     Duration: 1.003     CPU time: 0.002
/   _/                      v3.1.3

Program: /Users/ryan/Envs/twsgi/bin/gunicorn pong:app --config=config.py --workers=1 --timeout 1000000

1.003 handle_request  gunicorn/workers/sync.py:159
└─ 1.002 __call__  flask/app.py:2460
      [4 frames hidden]  flask
         1.002 dispatch_request  flask/app.py:1914
         └─ 1.002 pong  pong/__init__.py:8

pong.py

import os
from flask import Flask
from functools import reduce
import time

app = Flask(__name__)

@app.route('/')
def pong():
    time.sleep(1)
    return "pong"

wsgi_app = app.wsgi_app

if __name__ == "__main__":
    app.run(host=os.getenv("HOST", "0.0.0.0"), port=os.getenv("PORT", 8000))