Visualize profile result (jazzband#192)

* started working on showing a graph of the profile output which helps to quickly see the slow path through the profiled code

* further work on profile graph visualization

* finished backend and frontend work for displaying a graph of the profile and added some tests to verify dot generation

* updated requirements for graph rendering

* Fixed error in python 2 due to no mock library

* update travis file to also install test requirements

* removed double reference to mock in test-requirements

* Fixed broken version number

* Update profile_dot.py

Fixed bug under python 2. StringIO is not a context manager

* Open temp file in binary mode

* fixed failing test on python 2 due to string encoding

* added travis_retry to pip install steps since the pip install was causing the build to fail on python 3.4 while downloading pytz

.travis.yml

@@ -37,8 +37,9 @@ matrix:
   fast_finish: true
 
 install:
-    - pip install -q $DJANGO
-    - pip install -r requirements.txt
+    - travis_retry pip install -q $DJANGO
+    - travis_retry pip install -r requirements.txt
+    - travis_retry pip install -r project/test-requirements.txt
 
     # Handle PostgreSQL
     - if [[ "$DB" = "postgresql" ]]; then pip install psycopg2; fi

project/test-requirements.txt

@@ -11,3 +11,5 @@ mock==1.0.1
 Pillow==2.5.1
 factory-boy==2.8.1
 freezegun==0.3.5
+networkx==1.11
+pydotplus==2.0.2

project/tests/test_profile_dot.py

@@ -0,0 +1,105 @@
+# std
+import os
+import cProfile
+import tempfile
+from contextlib import contextmanager
+from six import PY3
+if PY3:
+    from unittest.mock import MagicMock
+else:
+    from mock import MagicMock
+# 3rd party
+from django.test import TestCase
+from networkx.drawing.nx_pydot import read_dot
+# silk
+from silk.views.profile_dot import _create_profile, _create_dot, _temp_file_from_file_field
+
+
+class ProfileDotViewTestCase(TestCase):
+
+    @classmethod
+    @contextmanager
+    def _stats_file(cls):
+        """
+        Context manager to create some arbitrary profiling stats in a temp file, returning the filename on enter,
+        and removing the temp file on exit.
+        """
+        try:
+            with tempfile.NamedTemporaryFile(delete=False) as stats:
+                pass
+            cProfile.run('1+1', stats.name)
+            yield stats.name
+        finally:
+            os.unlink(stats.name)
+
+    @classmethod
+    @contextmanager
+    def _stats_data(cls):
+        """
+        Context manager to create some arbitrary profiling stats in a temp file, returning the data on enter,
+        and removing the temp file on exit.
+        """
+        with cls._stats_file() as filename:
+            with open(filename, 'rb') as f:
+                yield f.read()
+
+    @classmethod
+    def _profile(cls):
+        """Create some arbitrary profiling stats."""
+        with cls._stats_file() as filename:
+            # create profile - we don't need to convert a django file field to a temp file
+            # just use the filename of the temp file already created
+            @contextmanager
+            def dummy(_): yield filename
+            return _create_profile(filename, dummy)
+
+    @classmethod
+    def _mock_file(cls, data):
+        """
+        Get a mock object that looks like a file but returns data when read is called.
+        """
+        i = [0]
+        def read(n):
+            if not i[0]:
+                i[0] += 1
+                return data
+
+        stream = MagicMock()
+        stream.open = lambda: None
+        stream.read = read
+
+        return stream
+
+    def test_create_dot(self):
+        """
+        Verify that a dot file is correctly created from pstats data stored in a file field.
+        """
+        with self._stats_file() as filename:
+
+            try:
+                # create dot
+                with tempfile.NamedTemporaryFile(delete=False) as dotfile:
+                    dot = _create_dot(self._profile(), 5)
+                    dot = dot.encode('utf-8') if PY3 else dot
+                    dotfile.write(dot)
+
+                # verify generated dot is valid
+                G = read_dot(dotfile.name)
+                self.assertGreater(len(G.nodes()), 0)
+
+            finally:
+                os.unlink(dotfile.name)
+
+    def test_temp_file_from_file_field(self):
+        """
+        Verify that data held in a file like object is copied to a temp file.
+        """
+        dummy_data = 'dummy data'.encode('utf-8')
+        stream = self._mock_file(dummy_data)
+
+        with _temp_file_from_file_field(stream) as filename:
+            with open(filename, 'rb') as f:
+                self.assertEqual(f.read(), dummy_data)
+
+        # file should have been removed on exit
+        self.assertFalse(os.path.exists(filename))

requirements.txt

@@ -10,3 +10,4 @@ Pillow>=3.2
 django>=1.8
 freezegun>=0.3
 factory-boy>=2.8.1
+gprof2dot>=2016.10.13

silk/templates/silk/profile_detail.html

@@ -5,6 +5,8 @@
 {% load staticfiles %}
 
 {% block js %}
+    <script type="text/javascript" src="{% static 'silk/lib/viz-lite.js' %}"></script>
+    <script type="text/javascript" src="{% static 'silk/lib/svg-pan-zoom.min.js' %}"></script>
     {{ block.super }}
 {% endblock %}
 
@@ -21,6 +23,12 @@
 
         }
 
+        #pyprofile-div {
+            display: block;
+            margin: auto;
+            width: 960px;
+        }
+
         .pyprofile {
             text-align: left;
         }
@@ -40,6 +48,26 @@
         a:active {
             color: #594F4F;
         }
+
+        #graph-div {
+            padding: 25px;
+            background-color: white;
+            display: block;
+            margin-left: auto;
+            margin-right: auto;
+            margin-top: 25px;
+            width: 960px;
+            text-align: center;
+        }
+
+        #percent {
+            width: 20px;
+        }
+
+        svg {
+          display: block;
+        }
+
     </style>
 {% endblock %}
 
@@ -63,7 +91,7 @@
                 </div>
             </div>
             <div class="description">
-                The below shows where in your code this profile was defined. If your profile was defined dynamically (i.e in your settings.py),
+                Below shows where in your code this profile was defined. If your profile was defined dynamically (i.e in your settings.py),
                 then this will show the range of lines that are covered by the profiling.
             </div>
             {% if code %}
@@ -74,19 +102,57 @@
                 </div>
             {% endif %}
 
-            {% if silk_request.pyprofile %}
+            {% if silk_request.prof_file %}
             <div class="heading">
-                <div class="inner-heading">Python Profiler</div>
+                <div class="inner-heading">Profile graph</div>
             </div>
             <div class="description">
-                The below is a dump from the cPython profiler.
+                Below is a graph of the profile, with the nodes coloured by the time taken (red is more time). This should give a good indication of the slowest path through the profiled code.</div>
+
+                <span>Prune nodes taking up less than </span>
+                <input id='percent' type="text" value='5'
+                       onkeypress='return event.charCode >= 48 && event.charCode <= 57 && $("#percent").val().length < 2'
+                       oninput="createViz()"
+                >
+
+                </input>
+                <span>% of the total time</span>
+
             </div>
-            {% if silk_request.prof_file %}
-            Click <a href="{% url 'silk:request_profile_download' request_id=silk_request.pk %}">here</a> to download profile.
-            {% endif %}
-            <pre class="pyprofile">{{ silk_request.pyprofile }}</pre>
+            <div id="graph-div">
+            </div>
+            <script>
+                function createViz() {
+                    $.get(
+                        "{% url 'silk:request_profile_dot' request_id=silk_request.pk %}",
+                        { cutoff: $('#percent').val() },
+                        function (response) {
+                            var svg = '#graph-div';
+                            $(svg).html(Viz(response.dot));
+                            $(svg + ' svg').attr('width', 960).attr('height', 480);
+                            svgPanZoom(svg + ' svg', { controlIconsEnabled: true });
+                        }
+                    );
+                }
+                createViz();
+            </script>
             {% endif %}
 
+            {% if silk_request.pyprofile %}
+            <div id="pyprofile-div">
+                <div class="heading">
+                    <div class="inner-heading">Python Profiler</div>
+                </div>
+                <div class="description">
+                    The below is a dump from the cPython profiler.
+                </div>
+                {% if silk_request.prof_file %}
+                Click <a href="{% url 'silk:request_profile_download' request_id=silk_request.pk %}">here</a> to download profile.
+                {% endif %}
+                <pre class="pyprofile">{{ silk_request.pyprofile }}</pre>
+                {% endif %}
+            </div>
+
         </div>
     </div>
 

silk/urls.py

@@ -2,6 +2,7 @@
 
 from silk.views.profile_detail import ProfilingDetailView
 from silk.views.profile_download import ProfileDownloadView
+from silk.views.profile_dot import ProfileDotView
 from silk.views.profiling import ProfilingView
 from silk.views.raw import Raw
 from silk.views.request_detail import RequestView
@@ -38,6 +39,11 @@
         ProfileDownloadView.as_view(),
         name='request_profile_download'
     ),
+    url(
+        r'^request/(?P<request_id>[a-zA-Z0-9\-]+)/json/$',
+        ProfileDotView.as_view(),
+        name='request_profile_dot'
+    ),
     url(
         r'^request/(?P<request_id>[a-zA-Z0-9\-]+)/profiling/$',
         ProfilingView.as_view(),

silk/views/profile_dot.py

@@ -0,0 +1,64 @@
+# std
+import os
+import json
+import tempfile
+import shutil
+from contextlib import closing, contextmanager
+# 3rd party
+from six import StringIO
+from django.shortcuts import get_object_or_404
+from django.utils.decorators import method_decorator
+from django.views.generic import View
+from django.http import HttpResponse
+from gprof2dot import DotWriter, PstatsParser, Profile, TEMPERATURE_COLORMAP
+# silk
+from silk.auth import login_possibly_required, permissions_possibly_required
+from silk.models import Request
+
+
+@contextmanager
+def _temp_file_from_file_field(source):
+    """
+    Create a temp file containing data from a django file field.
+    """
+    source.open()
+    with closing(source):
+        try:
+            with tempfile.NamedTemporaryFile(delete=False) as destination:
+                shutil.copyfileobj(source, destination)
+            yield destination.name
+        finally:
+            os.unlink(destination.name)
+
+
+def _create_profile(source, get_filename=_temp_file_from_file_field):
+    """
+    Parse a profile from a django file field source.
+    """
+    with get_filename(source) as filename:
+        return PstatsParser(filename).parse()
+
+
+def _create_dot(profile, cutoff):
+    """
+    Create a dot file from pstats data stored in a django file field.
+    """
+    node_cutoff = cutoff / 100.0
+    edge_cutoff = 0.1 / 100.0
+    profile.prune(node_cutoff, edge_cutoff, False)
+
+    with closing(StringIO()) as fp:
+        DotWriter(fp).graph(profile, TEMPERATURE_COLORMAP)
+        return fp.getvalue()
+
+
+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')