From ff50df3d636a1de8b618a3cc847ac17afc4aa6a9 Mon Sep 17 00:00:00 2001 From: danielbradburn Date: Mon, 24 Jul 2017 03:46:25 +0200 Subject: [PATCH] #33 organise cprofile output as a sortable table (#200) * add .venv* to .gitignore * made the profile output a sortable table with links to the appropriate source code * remove memoization of get_dot function since this was causing problem on python 2, and should probably be in a separate PR * removed python 3 only spitlines * fixed failing test due to PY3/2 differences in profile output * fixed failing test due difference in python 3.4 * fixed failing test due to floating point precision * fixed problem due to trying to import abs from math * reverted incorrect attempt to fix flaky test due to floating point precision --- project/test-requirements.txt | 1 + project/tests/test_code.py | 47 +++++++++++++++++++++ project/tests/test_profile_parser.py | 54 ++++++++++++++++++++++++ silk/models.py | 20 +++++++++ silk/templates/silk/profile_detail.html | 56 ++++++++++++++++++++++--- silk/utils/profile_parser.py | 21 ++++++++++ silk/views/code.py | 23 ++++++++-- silk/views/profile_detail.py | 13 ++++-- silk/views/profile_dot.py | 12 ++++-- silk/views/sql_detail.py | 23 +--------- 10 files changed, 231 insertions(+), 39 deletions(-) create mode 100644 project/tests/test_code.py create mode 100644 project/tests/test_profile_parser.py create mode 100644 silk/utils/profile_parser.py diff --git a/project/test-requirements.txt b/project/test-requirements.txt index b57f0714..441db8ea 100644 --- a/project/test-requirements.txt +++ b/project/test-requirements.txt @@ -13,3 +13,4 @@ factory-boy==2.8.1 freezegun==0.3.5 networkx==1.11 pydotplus==2.0.2 +contextlib2==0.5.5 diff --git a/project/tests/test_code.py b/project/tests/test_code.py new file mode 100644 index 00000000..99ea4acf --- /dev/null +++ b/project/tests/test_code.py @@ -0,0 +1,47 @@ +from collections import namedtuple +from django.test import TestCase +from silk.views.code import _code, _code_context, _code_context_from_request + + +FILE_PATH = __file__ +LINE_NUM = 5 +END_LINE_NUM = 10 + +with open(__file__) as f: + ACTUAL_LINES = [l + '\n' for l in f.read().split('\n')] + + +class CodeTestCase(TestCase): + + def assertActualLineEqual(self, actual_line, end_line_num=None): + expected_actual_line = ACTUAL_LINES[LINE_NUM - 1:end_line_num or LINE_NUM] + self.assertEqual(actual_line, expected_actual_line) + + def assertCodeEqual(self, code): + expected_code = [line.strip('\n') for line in ACTUAL_LINES[0:LINE_NUM + 10]] + [''] + self.assertEqual(code, expected_code) + + def test_code(self): + for end_line_num in None, END_LINE_NUM: + actual_line, code = _code(FILE_PATH, LINE_NUM, end_line_num) + self.assertActualLineEqual(actual_line, end_line_num) + self.assertCodeEqual(code) + + def test_code_context(self): + for end_line_num in None, END_LINE_NUM: + for prefix in '', 'salchicha_': + context = _code_context(FILE_PATH, LINE_NUM, end_line_num, prefix) + self.assertActualLineEqual(context[prefix + 'actual_line'], end_line_num) + self.assertCodeEqual(context[prefix + 'code']) + self.assertEqual(context[prefix + 'file_path'], FILE_PATH) + self.assertEqual(context[prefix + 'line_num'], LINE_NUM) + + def test_code_context_from_request(self): + for end_line_num in None, END_LINE_NUM: + for prefix in '', 'salchicha_': + request = namedtuple('Request', 'GET')(dict(file_path=FILE_PATH, line_num=LINE_NUM)) + context = _code_context_from_request(request, end_line_num, prefix) + self.assertActualLineEqual(context[prefix + 'actual_line'], end_line_num) + self.assertCodeEqual(context[prefix + 'code']) + self.assertEqual(context[prefix + 'file_path'], FILE_PATH) + self.assertEqual(context[prefix + 'line_num'], LINE_NUM) \ No newline at end of file diff --git a/project/tests/test_profile_parser.py b/project/tests/test_profile_parser.py new file mode 100644 index 00000000..2a69a9dc --- /dev/null +++ b/project/tests/test_profile_parser.py @@ -0,0 +1,54 @@ +# future +from __future__ import print_function +# std +import cProfile +import sys +# 3rd party +import contextlib2 as contextlib +from six import StringIO, PY3 +from django.test import TestCase +# silk +from silk.utils.profile_parser import parse_profile + + +class ProfileParserTestCase(TestCase): + + def test_profile_parser(self): + """ + Verify that the function parse_profile produces the expected output. + """ + with contextlib.closing(StringIO()) as stream: + with contextlib.redirect_stdout(stream): + cProfile.run('print()') + stream.seek(0) + actual = list(parse_profile(stream)) + if PY3: + if sys.version_info < (3,5): + expected = [ + ['ncalls', 'tottime', 'percall', 'cumtime', 'percall', 'filename:lineno(function)'], + ['1', '0.000', '0.000', '0.000', '0.000', ':1()'], + ['1', '0.000', '0.000', '0.000', '0.000', '{built-in method exec}'], + ['1', '0.000', '0.000', '0.000', '0.000', '{built-in method print}'], + ['1', '0.000', '0.000', '0.000', '0.000', "{method 'disable' of '_lsprof.Profiler' objects}"], + ] + else: + expected = [ + ['ncalls', 'tottime', 'percall', 'cumtime', 'percall', 'filename:lineno(function)'], + ['1', '0.000', '0.000', '0.000', '0.000', ':1()'], + ['1', '0.000', '0.000', '0.000', '0.000', '{built-in method builtins.exec}'], + ['1', '0.000', '0.000', '0.000', '0.000', '{built-in method builtins.print}'], + ['1', '0.000', '0.000', '0.000', '0.000', "{method 'disable' of '_lsprof.Profiler' objects}"], + ] + else: + expected = [ + ['ncalls', 'tottime', 'percall', 'cumtime', 'percall', 'filename:lineno(function)'], + ['1', '0.000', '0.000', '0.000', '0.000', ':1()'], + ['2', '0.000', '0.000', '0.000', '0.000', 'StringIO.py:208(write)'], + ['2', '0.000', '0.000', '0.000', '0.000', 'StringIO.py:38(_complain_ifclosed)'], + ['2', '0.000', '0.000', '0.000', '0.000', '{isinstance}'], + ['2', '0.000', '0.000', '0.000', '0.000', '{len}'], + ['2', '0.000', '0.000', '0.000', '0.000', "{method 'append' of 'list' objects}"], + ['1', '0.000', '0.000', '0.000', '0.000', "{method 'disable' of '_lsprof.Profiler' objects}"] + ] + + self.assertListEqual(actual, expected) \ No newline at end of file diff --git a/silk/models.py b/silk/models.py index 7fbbae77..eecc5784 100644 --- a/silk/models.py +++ b/silk/models.py @@ -2,6 +2,7 @@ import json import base64 import random +import re from django.core.files.storage import FileSystemStorage from django.db import models @@ -14,7 +15,9 @@ from django.db import transaction from uuid import uuid4 import sqlparse +from django.utils.safestring import mark_safe +from silk.utils.profile_parser import parse_profile from silk.config import SilkyConfig # Django 1.8 removes commit_on_success, django 1.5 does not have atomic @@ -85,6 +88,23 @@ class Request(models.Model): def total_meta_time(self): return (self.meta_time or 0) + (self.meta_time_spent_queries or 0) + @property + def profile_table(self): + for n, columns in enumerate(parse_profile(self.pyprofile)): + location = columns[-1] + if n and '{' not in location and '<' not in location: + r = re.compile('(?P.*\.py)\:(?P[0-9]+).*') + m = r.search(location) + group = m.groupdict() + src = group['src'] + num = group['num'] + name = 'c%d' % n + fmt = '{location}' + rep = fmt.format(**dict(group, **locals())) + yield columns[:-1] + [mark_safe(rep)] + else: + yield columns + # defined in atomic transaction within SQLQuery save()/delete() as well # as in bulk_create of SQLQueryManager # TODO: This is probably a bad way to do this, .count() will prob do? diff --git a/silk/templates/silk/profile_detail.html b/silk/templates/silk/profile_detail.html index 6a549ae2..0cc26546 100644 --- a/silk/templates/silk/profile_detail.html +++ b/silk/templates/silk/profile_detail.html @@ -7,6 +7,7 @@ {% block js %} + {{ block.super }} {% endblock %} @@ -67,6 +68,26 @@ svg { display: block; } + + .file-path { + font-size: 13px; + } + + .file-path>a { + color: black; + } + + .file-path>a:hover { + color: #9dd0ff; + } + + .file-path>a:active { + color: #594F4F; + } + + #pyprofile-table { + margin-top: 25px; + } {% endblock %} @@ -143,13 +164,38 @@
Python Profiler
+
- The below is a dump from the cPython profiler. + Below is a dump from the cPython profiler. + {% if silk_request.prof_file %} + Click here to download profile. + {% endif %}
- {% if silk_request.prof_file %} - Click here to download profile. - {% endif %} - 
{{ silk_request.pyprofile }}
+ + + {% for row in silk_request.profile_table %} + + {% for column in row %} + {% if forloop.parentloop.counter0 %} + + {% else %} + + {% endif %} + {% endfor %} + + {% endfor %} +
+ {% if forloop.counter0 == file_column %} +
+ {{ column }} +
+ {% if forloop.parentloop.counter0 == pos %} + {% code pyprofile_code pyprofile_actual_line %} + {% endif %} + {% else %} + {{ column }} + {% endif %} + 		{{ column }}
{% endif %} diff --git a/silk/utils/profile_parser.py b/silk/utils/profile_parser.py new file mode 100644 index 00000000..b593ccc0 --- /dev/null +++ b/silk/utils/profile_parser.py @@ -0,0 +1,21 @@ +from six import text_type +import re + + +_pattern = re.compile(' +') + + +def parse_profile(output): + """ + Parse the output of cProfile to a list of tuples. + """ + if isinstance(output, text_type): + output = output.split('\n') + for i, line in enumerate(output): + # ignore n function calls, total time and ordered by and empty lines + line = line.strip() + if i > 3 and line: + columns = _pattern.split(line)[0:] + function = ' '.join(columns[5:]) + columns = columns[:5] + [function] + yield columns diff --git a/silk/views/code.py b/silk/views/code.py index c42c67a0..814b16d0 100644 --- a/silk/views/code.py +++ b/silk/views/code.py @@ -4,8 +4,10 @@ def _code(file_path, line_num, end_line_num=None): + line_num = int(line_num) if not end_line_num: end_line_num = line_num + end_line_num = int(end_line_num) actual_line = [] lines = '' with open(file_path, 'r') as f: @@ -19,10 +21,23 @@ def _code(file_path, line_num, end_line_num=None): return actual_line, code -def _code_context(file_path, line_num): - actual_line, code = _code(file_path, line_num) - context = {'code': code, 'file_path': file_path, 'line_num': line_num, 'actual_line': actual_line} - return context +def _code_context(file_path, line_num, end_line_num=None, prefix=''): + actual_line, code = _code(file_path, line_num, end_line_num) + return { + prefix + 'code': code, + prefix + 'file_path': file_path, + prefix + 'line_num': line_num, + prefix + 'actual_line': actual_line + } + + +def _code_context_from_request(request, end_line_num=None, prefix=''): + file_path = request.GET.get('file_path') + line_num = request.GET.get('line_num') + result = {} + if file_path is not None and line_num is not None: + result = _code_context(file_path, line_num, end_line_num, prefix) + return result def _should_display_file_name(file_name): diff --git a/silk/views/profile_detail.py b/silk/views/profile_detail.py index 66513118..c9b77bce 100644 --- a/silk/views/profile_detail.py +++ b/silk/views/profile_detail.py @@ -3,7 +3,7 @@ from django.views.generic import View from silk.auth import login_possibly_required, permissions_possibly_required from silk.models import Profile -from silk.views.sql_detail import _code +from silk.views.code import _code_context, _code_context_from_request class ProfilingDetailView(View): @@ -18,16 +18,21 @@ def get(self, request, *_, **kwargs): profile = Profile.objects.get(pk=profile_id) file_path = profile.file_path line_num = profile.line_num + + context['pos'] = pos = int(request.GET.get('pos', 0)) + if pos: + context.update(_code_context_from_request(request, prefix='pyprofile_')) + context['profile'] = profile context['line_num'] = file_path context['file_path'] = line_num + context['file_column'] = 5 + if profile.request: context['silk_request'] = profile.request if file_path and line_num: try: - actual_line, code = _code(file_path, line_num, profile.end_line_num) - context['code'] = code - context['actual_line'] = actual_line + context.update(_code_context(file_path, line_num, profile.end_line_num)) except IOError as e: if e.errno == 2: context['code_error'] = e.filename + ' does not exist.' diff --git a/silk/views/profile_dot.py b/silk/views/profile_dot.py index 51d929a0..d40a83de 100644 --- a/silk/views/profile_dot.py +++ b/silk/views/profile_dot.py @@ -52,13 +52,17 @@ def _create_dot(profile, cutoff): return fp.getvalue() +def _get_dot(request_id, cutoff): + silk_request = get_object_or_404(Request, pk=request_id, prof_file__isnull=False) + profile = _create_profile(silk_request.prof_file) + result = dict(dot=_create_dot(profile, cutoff)) + return HttpResponse(json.dumps(result).encode('utf-8'), content_type='application/json') + + class ProfileDotView(View): @method_decorator(login_possibly_required) @method_decorator(permissions_possibly_required) def get(self, request, request_id): - silk_request = get_object_or_404(Request, pk=request_id, prof_file__isnull=False) cutoff = float(request.GET.get('cutoff', '') or 5) - profile = _create_profile(silk_request.prof_file) - result = dict(dot=_create_dot(profile, cutoff)) - return HttpResponse(json.dumps(result).encode('utf-8'), content_type='application/json') + return _get_dot(request_id, cutoff) diff --git a/silk/views/sql_detail.py b/silk/views/sql_detail.py index c820c865..c4e5430b 100644 --- a/silk/views/sql_detail.py +++ b/silk/views/sql_detail.py @@ -8,28 +8,7 @@ from silk.auth import login_possibly_required, permissions_possibly_required from silk.models import SQLQuery, Request, Profile - - -def _code(file_path, line_num, end_line_num=None): - if not end_line_num: - end_line_num = line_num - actual_line = [] - lines = '' - with open(file_path, 'r') as f: - r = range(max(0, line_num - 10), line_num + 10) - for i, line in enumerate(f): - if i in r: - lines += line - if i + 1 in range(line_num, end_line_num + 1): - actual_line.append(line) - code = lines.split('\n') - return actual_line, code - - -def _code_context(file_path, line_num): - actual_line, code = _code(file_path, line_num) - context = {'code': code, 'file_path': file_path, 'line_num': line_num, 'actual_line': actual_line} - return context +from silk.views.code import _code class SQLDetailView(View):