notebooks/Mining performance HotSpots with JProfiler, jQAssistant, Neo4j and Pandas.ipynb

{
 "cells": [
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "# Mining performance hotspots with JProfiler, jQAssistant, Neo4j and Pandas"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "TL;DR I show how I determine the parts of an application that trigger unnecessary SQL statements by using graph analysis of a call tree."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "# Introduction\n",
    "## General claim\n",
    "We don't need more tools that show use more problems in our software. We need ways to determine the right problem to solve. But often we just fix the symptoms on the surface rather than the underlying problems. I find that approach non-professional and want to do my part to improve this situation by delivering root cause analysis of symptoms to get to the real problems in our software."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## What you will see\n",
    "\n",
    "In this notebook, I'll show you one of my approaches for mining performance problems based on application runtime performance analysis. In general, I use this approach to make the point that there are severe design errors that have a negative influence on the application's overall performance. In this example, I show you how I determine the reasons behind a massive amount of executed SQL statements in an application step by step.\n",
    "\n",
    "The key idea is to use graph analysis to analyze call stacks that were created by a profiling tool. With this approach, I'm not only able to show the **hotspot**s that are involved in the performance issue (because the hotspots show that some SQL statements take long to execute or are executed too often), but also the reasons behind these hotspots. I achieve this by extracting various additional information like the web **request**s, application's **entry** points and the **trigger**s within the application causing the hotspots.\n",
    "\n",
    "This is very helpful to determine the most critical parts in the application and gives you a hint where you could start improving immediately. I use this analysis at work to determine the biggest performance bottleneck in a medium sized application (~700 kLOCs). Based on the results, we work out possible improvements for that specific hotspot, create a prototypical fix for it, measure the fix's impact and, if the results are convincing, roll out the fix for that problem application wide (and work on the next performance bottleneck and so on).\n",
    "\n",
    "I hope you'll see that this is a very reasonable approach albeit the simplified use case that I show in this blog post/notebook."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Used software\n",
    "Before we start, I want to briefly introduce you to the setup that I use for this analysis:\n",
    "\n",
    "* [Fork of the Spring sample project PetClinic](https://buschmais.github.io/spring-petclinic/) as application to torture\n",
    "* [Tomcat 8](https://tomcat.apache.org/download-80.cgi) installation as servlet container for the application (standalone, for easier integration of the profiling tool)\n",
    "* [JMeter](http://jmeter.apache.org/) load testing tool for executing some requests\n",
    "* [JProfiler](https://www.ej-technologies.com/products/jprofiler/overview.html) profiler for recording performance measures\n",
    "* [jQAssistant](http://jqassistant.org/) static analysis tool for reading in call trees\n",
    "* [Neo4j](https://neo4j.com/) graph database and [Cypher](https://neo4j.com/developer/cypher-query-language/) graph query language for executing the graph analysis\n",
    "* [Pandas](http://pandas.pydata.org/), [py2neo](http://py2neo.org/) and [Bokeh](http://bokeh.pydata.org) on [Jupyter\\*](http://jupyter.org/) as documentation, execution and analysis environment\n",
    "\n",
    "The first ones are dependent on the environment and programming language you use. jQAssistant, Neo4j and Pandas are my default environment for software analytics so far. I'll show your how all those tools fit together.\n",
    "\n",
    "So let's get started!\n",
    "\n",
    "\\**actually, what you see here, is the result of an executed Jupyter notebook, too. You can find that notebook on [GitHub](https://github.com/feststelltaste/software-analytics/blob/master/notebooks/Mining%20performance%20HotSpots%20with%20JProfiler%2C%20jQAssistant%2C%20Neo4j%20and%20Pandas.ipynb).*"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "# Performance Profiling\n",
    "As a prerequisite for this analysis, we need performance profiling data gathered by a profiler. A profiler will be integrated into the runtime environment (e. g. Java Virtual Machine) of your application and measures diverse properties like method execution time, number of web service calls, executed SQL statements etc. Additionally, we need something that uses or clicks through our application to get some numbers. In my case, I run the [Spring PetClinic performance test](https://github.com/buschmais/spring-petclinic/tree/master/src/test/jmeter) using JMeter.\n",
    "\n",
    " As profiling tool, I use JProfiler to record some performance measures while the test was running.  \n",
    "<p><tt>&lt;advertisment&gt;</tt><br />\n",
    "At this point, I want to thank ej-technologies for providing me with a [free open-source license](https://www.ej-technologies.com/buy/jprofiler/openSource) for JProfiler that enables this blog post in exchange of mentioning their product:\n",
    "\n",
    "<a href=\"http://www.ej-technologies.com/products/jprofiler/overview.html\">\n",
    "![](https://www.ej-technologies.com/images/product_banners/jprofiler_large.png)</a>\n",
    "\n",
    "JProfiler is a great commercial tool for profiling Java application and costs around 400 €. It really worth the money because it gives you deep insights how your application performs under the hood.\n",
    "<tt>&lt;/advertisment&gt;</tt>\n",
    "</p>\n",
    "\n",
    "Also outside the advertisement block, I personally like JProfiler a lot because it does what it does very very good. Back to the article.\n",
    "\n",
    "The recording of the measures starts before the execution of the performance test and stops after the test has finished successfully. The result is stored in a file as so-called \"snapshot\". The use of a snapshot enables you to repeat your analysis over and over again with exactly the same performance measures.\n",
    "\n",
    "What we usually need for performance analysis is a recorded runtime stack of all method calls as a call tree. A call tree shows you a tree of the called methods. Below, you can see the call tree for the called methods with their measured CPU wall clock time (aka the real time that is spent in that method) and the number of invocations for a complete test run:\n",
    "\n",
    "![](resources/jprofiler_cpu_call_tree.png)\n",
    "  \n",
    "With such a view, you see which parts of your application call which classes and methods by drilling down the hierarchy by hand:\n",
    "  \n",
    "![](resources/jprofiler_cpu_call_tree_leaf.png)\n",
    "\n",
    "But there is more: You can also \"turn around\" the call tree and list all the so-called \"HotSpots\". Technically, e. g. for CPU HotSpots, JProfiler sums up all the measurements for the method call leafs that take longer than 0.1% of all method calls. With this view, you see the application's hotspots immediately:\n",
    "\n",
    "![](resources/jprofiler_cpu_hot_spots.png)\n",
    "\n",
    "These views are also available for other measures like web service calls, file accesses or DB calls, that is shown below:\n",
    "\n",
    "![](resources/jprofiler_jdbc_hot_spots.png)\n",
    "\n",
    "This is the data that we need for our SQL statement analysis. The big problem is, that we can't easily see where all those SQL statements come from because we just see the isolated SQL statements.\n",
    "\n",
    "And this is where our journey begins..."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "# Reading XML into Neo4j"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## The input data\n",
    "For further processing, we export such a call tree into a XML file (via the JProfiler GUI or the command line tool jpexport). If we export the data of the SQL hotspots (incl. the complete call tree) with JProfiler, we'll get a XML file like the following:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 1,
   "metadata": {
    "scrolled": true
   },
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "<?xml version=\"1.0\" encoding=\"UTF-8\"?>\n",
      "...\n",
      "<tree type=\"Probe Hot Spots\" probe=\"JDBC\" threadSelection=\"All thread groups\" threadStatus=\"All s...\n",
      "  <hotspot leaf=\"false\" value=\"SELECT pets.id, name, birth_date, type_id, owner_id, visits.id as ...\n",
      "    <node leaf=\"false\" class=\"java.sql.PreparedStatement\" methodName=\"executeQuery\" methodSignatu...\n",
      "      <node leaf=\"false\" class=\"org.springframework.jdbc.core.JdbcTemplate$1\" methodName=\"doInPre...\n",
      "        <node leaf=\"false\" class=\"org.springframework.jdbc.core.JdbcTemplate\" methodName=\"execute...\n",
      "          <node leaf=\"false\" class=\"org.springframework.jdbc.core.JdbcTemplate\" methodName=\"query...\n",
      "            <node leaf=\"false\" class=\"org.springframework.jdbc.core.JdbcTemplate\" methodName=\"que...\n",
      "              <node leaf=\"false\" class=\"org.springframework.jdbc.core.namedparam.NamedParameterJd...\n",
      "                <node leaf=\"false\" class=\"org.springframework.jdbc.core.namedparam.NamedParameter...\n"
     ]
    }
   ],
   "source": [
    "with open (r'input/spring-petclinic/JDBC_Probe_Hot_Spots_jmeter_test.xml') as log:\n",
    "    [print(line[:97] + \"...\") for line in log.readlines()[:10]]"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "For a full version of this file, see GitHub: https://github.com/feststelltaste/software-analytics/blob/master/notebooks/input/spring-petclinic/JDBC_Probe_Hot_Spots_jmeter_test.xml\n",
    "\n",
    "This file consists of all the information that we've seen in the JProfiler GUI, but as XML elements and attributes. And here comes the great part: The content itself is graph-like because the XML elements are nested! So the <tt>&lt;tree&gt;</tt> element contains the <tt>&lt;hotspot&gt;</tt> elements that contain the <tt>&lt;node&gt;</tt> elements and so on. A case for a graph database like Neo4j!\n",
    "\n",
    "But how do we get that XML file into our Neo4j database? jQAssistant to the rescue!"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Scanning with jQAssistant\n",
    "jQAssistant is a great and versatile tool for scanning various graph-like structured data into Neo4j (see [my experiences with jQAssistant so far](https://www.feststelltaste.de/my-experiences-with-jqassistant-so-far/) for more information). I just downloaded the version 1.1.3, added the binary to my <tt>PATH</tt> system variable and executed the following command (works for jQAssistant versions prior to 1.2.0, I haven't figured it out how to do it with newer versions yet):\n",
    "\n",
    "<pre>\n",
    "jqassistant scan -f xml:document::JDBC_Probe_Hot_Spots_jmeter_test.xml\n",
    "</pre>\n",
    "\n",
    "This will import the XML structure as a graph into the Neo4j graph database that is used by jQAssistant under the hood."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Exploring the data\n",
    "So, if we want to have a quick look at the stored data, we can start jQAssistant's Neo4j embedded instance via \n",
    "\n",
    "<pre>\n",
    "jqassistant server\n",
    "</pre>\n",
    "\n",
    "open <tt>http://localhost:7474</tt>, click in the overview menu at the label <tt>File</tt>, click on some nodes and you will see something like this:\n",
    "\n",
    "![](resources/jprofiler_xml_as_neo4j_graph_cut.png)\n",
    "\n",
    "It shows the content of the XML file from above as a graph in Neo4j:\n",
    "* The pink node is the entry point &ndash; the XML file. \n",
    "* To the right, there is the first XML element <tt>&lt;tree&gt;</tt> in that file, connected by the <tt>HAS_ROOT_ELEMENT</tt> relationship. \n",
    "* The <tt>&lt;tree&gt;</tt> element has some attributes, connected by <tt>HAS_ATTRIBUTE</tt>. \n",
    "* From the <tt>&lt;tree&gt;</tt> element, there are multiple outgoing relationships with various <tt>&lt;hotspot&gt;</tt> nodes, containing some information about the executed SQLs in the referenced attributes. \n",
    "* The attributes that are connected to these elements contain the values that we need for our purpose later on. \n",
    "\n",
    "So, for example the attribute with the name <tt>value</tt> contains the executed SQL statement:\n",
    "\n",
    "![](resources/jprofiler_xml_as_neo4j_graph_value_sql.png)\n",
    "\n",
    "The attribute with the name <tt>count</tt> contains the number of executions of a SQL statement:\n",
    "\n",
    "![](resources/jprofiler_xml_as_neo4j_graph_count_value.png)\n",
    "\n",
    "Each element or attribute is also labeled correspondingly with <tt>Element</tt> or <tt>Attribute</tt>."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Looking at real data"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "I want to show you the data from the database in a more nicer way. So, we load our main libraries and initialize the connection to Neo4j database by creating a <tt>Graph</tt> object (for more details on this have a look at this [blog post](https://www.feststelltaste.de/a-simple-demo-on-how-to-use-python-pandas-with-jqassistant-neo4j/))"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 2,
   "metadata": {
    "collapsed": true
   },
   "outputs": [],
   "source": [
    "import pandas as pd\n",
    "from py2neo import Graph\n",
    "\n",
    "graph = Graph()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "We execute a simple query for one XML element and it's relationships to its attributes.\n",
    "\n",
    "For example, if we want to display the data of this <tt>&lt;hotspot</tt> element\n",
    "\n",
    "```xml\n",
    "<hotspot \n",
    "    leaf=\"false\" \n",
    "    value=\"SELECT id, name FROM types ORDER BY name\" \n",
    "    time=\"78386\" \n",
    "    count=\"107\">\n",
    "```\n",
    "\n",
    "as graph, we get that information from all the attributes of an element (don't worry about the syntax of the following two Cypher statements. They are just there to show you the underlying data as an example)."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 3,
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/html": [
       "<div>\n",
       "<table border=\"1\" class=\"dataframe\">\n",
       "  <thead>\n",
       "    <tr style=\"text-align: right;\">\n",
       "      <th></th>\n",
       "      <th>all.name</th>\n",
       "      <th>all.value</th>\n",
       "    </tr>\n",
       "  </thead>\n",
       "  <tbody>\n",
       "    <tr>\n",
       "      <th>0</th>\n",
       "      <td>count</td>\n",
       "      <td>107</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>1</th>\n",
       "      <td>time</td>\n",
       "      <td>78386</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>2</th>\n",
       "      <td>value</td>\n",
       "      <td>SELECT id, name FROM types ORDER BY name</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>3</th>\n",
       "      <td>leaf</td>\n",
       "      <td>false</td>\n",
       "    </tr>\n",
       "  </tbody>\n",
       "</table>\n",
       "</div>"
      ],
      "text/plain": [
       "  all.name                                 all.value\n",
       "0    count                                       107\n",
       "1     time                                     78386\n",
       "2    value  SELECT id, name FROM types ORDER BY name\n",
       "3     leaf                                     false"
      ]
     },
     "execution_count": 3,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "query=\"\"\"\n",
    "MATCH (e:Element)-[:HAS_ATTRIBUTE]->(a:Attribute)\n",
    "WHERE a.value = \"SELECT id, name FROM types ORDER BY name\"\n",
    "WITH e as node\n",
    "MATCH (node)-[:HAS_ATTRIBUTE]->(all:Attribute)\n",
    "RETURN all.name, all.value\n",
    "\"\"\"\n",
    "pd.DataFrame(graph.run(query).data())"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "As seen in the picture with the huge graph above, each <tt>&lt;hotspot&gt;</tt> node refers to the further <tt>&lt;node&gt;</tt>s, that call the hotspots. In our case, these nodes are the methods in our application that are responsible for the executions of the  SQL statements.\n",
    "\n",
    "![](resources/jprofiler_xml_as_neo4j_graph_class_value.png)\n",
    "\n",
    "If we list all attributes of such a node, we've got plenty of information of the callees of the hotspots. For example these nodes contain information about the method name (<tt>method</tt>) or the number of executed SQL statements (<tt>count</tt>):"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 4,
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/html": [
       "<div>\n",
       "<table border=\"1\" class=\"dataframe\">\n",
       "  <thead>\n",
       "    <tr style=\"text-align: right;\">\n",
       "      <th></th>\n",
       "      <th>a.name</th>\n",
       "      <th>a.value</th>\n",
       "    </tr>\n",
       "  </thead>\n",
       "  <tbody>\n",
       "    <tr>\n",
       "      <th>0</th>\n",
       "      <td>lineNumber</td>\n",
       "      <td>-1</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>1</th>\n",
       "      <td>percent</td>\n",
       "      <td>28.4</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>2</th>\n",
       "      <td>time</td>\n",
       "      <td>84203</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>3</th>\n",
       "      <td>count</td>\n",
       "      <td>107</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>4</th>\n",
       "      <td>methodSignature</td>\n",
       "      <td>()Ljava/sql/ResultSet;</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>5</th>\n",
       "      <td>methodName</td>\n",
       "      <td>executeQuery</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>6</th>\n",
       "      <td>class</td>\n",
       "      <td>java.sql.PreparedStatement</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>7</th>\n",
       "      <td>leaf</td>\n",
       "      <td>false</td>\n",
       "    </tr>\n",
       "  </tbody>\n",
       "</table>\n",
       "</div>"
      ],
      "text/plain": [
       "            a.name                     a.value\n",
       "0       lineNumber                          -1\n",
       "1          percent                        28.4\n",
       "2             time                       84203\n",
       "3            count                         107\n",
       "4  methodSignature      ()Ljava/sql/ResultSet;\n",
       "5       methodName                executeQuery\n",
       "6            class  java.sql.PreparedStatement\n",
       "7             leaf                       false"
      ]
     },
     "execution_count": 4,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "query=\"\"\"\n",
    "MATCH (e:Element)-[:HAS_ATTRIBUTE]->(a:Attribute)\n",
    "WHERE id(e) = 12 //just select an arbitrary node\n",
    "RETURN a.name, a.value\n",
    "\"\"\"\n",
    "pd.DataFrame(graph.run(query).data())"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "# Prepare performance analysis\n",
    "Because it's a bit cumbersome to work at the abstraction level of the XML file, let's enrich this graph with a few better concepts for mining performance problems."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Clean up (optional)\n",
    "Before executing the first statements, we clean up any preexisting data from previous queries. This is only necessary when you execute this notebook several times on the same data store (like me). It makes the results repeatable and thus more reproducible (a property we should generally strive for!)."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 5,
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/plain": [
       "[{'COUNT(n)': 4854, 'COUNT(r)': 4854}]"
      ]
     },
     "execution_count": 5,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "query=\"\"\"\n",
    "MATCH (n:Node)-[r:CALLS|CREATED_FROM|LEADS_TO]->()\n",
    "DELETE r, n\n",
    "RETURN COUNT(r), COUNT(n)\"\"\"\n",
    "graph.run(query).data()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Consolidate the data\n",
    "\n",
    "We create some new nodes that contain all the information from the XML part of the graph that we need. We simply copy the values of some attributes to new <tt>Call</tt> nodes.\n",
    "\n",
    "In our Cypher query, we first retrieve all <tt>&lt;node&gt;</tt> elements (identified by their \"name\" property) and some attributes that we need for our analysis. For each relevant information item, we create a variable to retrieve the information later on:\n",
    "\n",
    "```cypher\n",
    "MATCH (n:Element {name: \"node\"}),\n",
    "    (n)-[:HAS_ATTRIBUTE]->(classAttribut:Attribute {name : \"class\"}),\n",
    "    (n)-[:HAS_ATTRIBUTE]->(methodAttribut:Attribute {name : \"methodName\"}),\n",
    "    (n)-[:HAS_ATTRIBUTE]->(countAttribut:Attribute {name : \"count\"}),\n",
    "    (n)-[:HAS_ATTRIBUTE]->(timeAttribut:Attribute {name : \"time\"})\n",
    "```\n",
    "\n",
    "For each <tt>&lt;node&gt;</tt> element we've found, we tag the nodes with the label <tt>Node</tt> to have a general marker for the JProfiler measurements (which is \"node\" by coincidence) and mark all nodes that contain information about the calling classes and methods with the label <tt>Call</tt>:\n",
    "\n",
    "```cypher\n",
    "CREATE \n",
    "   (x:Node:Call {\n",
    "```\n",
    "\n",
    "We also copy the relevant information from the <tt>&lt;node&gt;</tt> element's attributes into the new nodes. We put the value of the class attribute (that consists of the Java package name and the class name) into the <tt>fqn</tt> (full qualified name) property and add just the name of the class in the <tt>class</tt> property (just for displaying reasons in the end). The rest is copied as well, including some type conversions for <tt>count</tt> and <tt>time</tt>:\n",
    "\n",
    "```cypher\n",
    "        fqn: classAttribut.value,\n",
    "        class: SPLIT(classAttribut.value,\".\")[-1], \n",
    "        method: methodAttribut.value,\n",
    "        count: toFloat(countAttribut.value), \n",
    "        time: toFloat(timeAttribut.value)\n",
    "        })\n",
    "```\n",
    "\n",
    "Additionally, we track the origin of the information by a <tt>CREATED_FROM</tt> relationship to connect the new nodes later on:\n",
    "\n",
    "```cypher\n",
    "     -[r:CREATED_FROM]->(n)\n",
    "```\n",
    "\n",
    "So, the complete query looks like the following and will be executed against the Neo4j data store:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 6,
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/plain": [
       "[{'COUNT(r)': 2358, 'COUNT(x)': 2358}]"
      ]
     },
     "execution_count": 6,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "query = \"\"\"\n",
    "MATCH (n:Element {name: \"node\"}),\n",
    "    (n)-[:HAS_ATTRIBUTE]->(classAttribut:Attribute {name : \"class\"}),\n",
    "    (n)-[:HAS_ATTRIBUTE]->(methodAttribut:Attribute {name : \"methodName\"}),\n",
    "    (n)-[:HAS_ATTRIBUTE]->(countAttribut:Attribute {name : \"count\"}),\n",
    "    (n)-[:HAS_ATTRIBUTE]->(timeAttribut:Attribute {name : \"time\"})\n",
    "CREATE \n",
    "   (x:Node:Call {\n",
    "        fqn: classAttribut.value,\n",
    "        class: SPLIT(classAttribut.value,\".\")[-1], \n",
    "        method: methodAttribut.value,\n",
    "        count: toFloat(countAttribut.value), \n",
    "        time: toFloat(timeAttribut.value)\n",
    "        })-[r:CREATED_FROM]->(n)\n",
    "RETURN COUNT(x), COUNT(r)\n",
    "\"\"\"\n",
    "graph.run(query).data()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "We do the same for the <tt>&lt;hotspot&gt;</tt> elements. Here, the attributes are a little bit different, because we are gathering data from the hotspots that contain information about the executed SQL statements:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 7,
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/plain": [
       "[{'COUNT(r)': 73, 'COUNT(x)': 73}]"
      ]
     },
     "execution_count": 7,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "query = \"\"\"\n",
    "MATCH (n:Element { name: \"hotspot\"}),\n",
    "    (n)-[:HAS_ATTRIBUTE]->(valueAttribut:Attribute {name : \"value\"}),\n",
    "    (n)-[:HAS_ATTRIBUTE]->(countAttribut:Attribute {name : \"count\"}),\n",
    "    (n)-[:HAS_ATTRIBUTE]->(timeAttribut:Attribute {name : \"time\"})\n",
    "    \n",
    "WHERE n.name = \"hotspot\"\n",
    "CREATE \n",
    "   (x:Node:HotSpot {\n",
    "        value: valueAttribut.value,\n",
    "        count: toFloat(countAttribut.value), \n",
    "        time: toFloat(timeAttribut.value)\n",
    "        })-[r:CREATED_FROM]->(n)\n",
    "RETURN COUNT(x), COUNT(r)\n",
    "\"\"\"\n",
    "graph.run(query).data()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Now, we have many new nodes in our database that are aren't directly connected. E. g. a <tt>Call</tt> node looks like this:\n",
    "\n",
    "![](resources/jprofiler_xml_as_neo4j_graph_call_nodes.png)\n",
    "\n",
    "So, let's connect them. How? We've saved that information with our <tt>CREATED_FROM</tt> relationship:\n",
    "\n",
    "![](resources/jprofiler_xml_as_neo4j_graph_calls_not_connected.png)\n",
    "\n",
    "This information can be used to connect the <tt>Call</tt> nodes as well as the <tt>HotSpot</tt> nodes."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 8,
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/plain": [
       "[{'COUNT(r)': 2358}]"
      ]
     },
     "execution_count": 8,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "query=\"\"\"\n",
    "MATCH (outerNode:Node)-[:CREATED_FROM]->\n",
    "      (outerElement:Element)-[:HAS_ELEMENT]->\n",
    "      (innerElement:Element)<-[:CREATED_FROM]-(innerNode:Node)\n",
    "CREATE (outerNode)<-[r:CALLS]-(innerNode)\n",
    "RETURN COUNT(r)\n",
    "\"\"\"\n",
    "graph.run(query).data()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "![](resources/jprofiler_xml_as_neo4j_graph_calls_connected.png)\n",
    "\n",
    "And there we have it! Just click in the Neo4j browser on the relationship CALLS and the you'll see our call tree from JProfiler as call graph in Neo4j, ready for root cause analysis!\n",
    "\n",
    "![](resources/jprofiler_xml_as_neo4j_graph_call_tree.png)"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {
    "collapsed": true
   },
   "outputs": [],
   "source": []
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "# Root Cause Analysis\n",
    "\n",
    "## Conceptual model\n",
    "All the work before was just there to get a nice graph model that feels more natural. Now comes the analysis part: As mentioned in the introduction, we don't only want the **hotspot**s that signal that something awkward happened, but also \n",
    "* the **trigger** in our application of the hotspot combined with \n",
    "* the information about the **entry** point (e. g. where in our application does the problem happen) and\n",
    "* (optionally) the **request** that causes the problem (to be able to localize the problem)\n",
    "\n",
    "Speaking in graph terms, we need some specific nodes of our call tree graph with the following information:\n",
    "* <tt>HotSpot</tt>: The executed SQL statement aka the <tt>HotSpot</tt> node\n",
    "* <tt>Trigger</tt>: The executor of the SQL statement in our application aka the <tt>Call</tt> node with the last class/method call that starts with our application's package name\n",
    "* <tt>Entry</tt>: The first call of our own application code aka the <tt>Call</tt> node that starts also with our application's package name\n",
    "* <tt>Request</tt>: The <tt>Call</tt> node with the information about the HTTP request (optional, but because JProfiler delivers this information as well, we use it here in this example)\n",
    "\n",
    "These points in the call tree should give us enough information that we can determine where to look for improvements in our application. "
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Challenges\n",
    "There is one thing that is a little bit tricky to implement: It's to model what we see as \"last\" and \"first\" in Neo4j / Cypher. Because we are using the package name of a class to identify our own application, there are many <tt>Call</tt> nodes in one call graph part that have that package name. Neo4j would (rightly) return too many results (for us) because it would deliver one result for each match. And a match is also given when a <tt>Call</tt> node within our application matches the package name. So, how do we mark the first and last nodes of our application code? \n",
    "\n",
    "Well, take one step at a time. Before we are doing anything awkward, we are trying to store all the information that we know into the graph before executing our analysis. I always favor this approach instead of trying to find a solution with complicated cypher queries, where you'll probably mix up things easily."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Preparing the query\n",
    "First, we can identify the **request**, that triggers the SQL statement, because we configured JProfiler to include that information in our call tree. We simply label them with the label <tt>Request</tt>."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "### Identifying all request"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 9,
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/plain": [
       "[{'COUNT(x)': 38}]"
      ]
     },
     "execution_count": 9,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "query=\"\"\"\n",
    "MATCH (x)\n",
    "WHERE x.fqn = \"_jprofiler_annotation_class\" AND x.method STARTS WITH \"HTTP\"\n",
    "SET x:Request\n",
    "RETURN COUNT(x)\n",
    "\"\"\"\n",
    "graph.run(query).data()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "### Identifying all entry points into the application"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Next, we identify the **entry** points aka first nodes of our application. We can achieve this by first searching all the shortest paths between the already existing <tt>Request</tt> nodes and all the nodes that have our package name. From all these subgraphs, we take only the single subgraph that has only a single node with the package name of our application. This is the first node that occurs in the call graph when starting from the request (I somehow can feel that there is a more elegant way to do this. If so, please let me know!). We mark that nodes as <tt>Entry</tt> nodes. "
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 10,
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/plain": [
       "[{'COUNT(entry)': 38}]"
      ]
     },
     "execution_count": 10,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "query=\"\"\"\n",
    "MATCH \n",
    "    request_to_entry=shortestPath((request:Request)-[:CALLS*]->(entry:Call))\n",
    "WHERE\n",
    "    entry.fqn STARTS WITH \"org.springframework.samples.petclinic\"\n",
    "AND \n",
    "    SINGLE(n IN NODES(request_to_entry) \n",
    "        WHERE exists(n.fqn) AND n.fqn STARTS WITH \"org.springframework.samples.petclinic\")\n",
    "SET \n",
    "    entry:Entry\n",
    "RETURN COUNT(entry)\n",
    "\"\"\"\n",
    "graph.run(query).data()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "With the same approach, we can mark all the calls that **trigger** the execution of the SQL statements with the label <tt>Trigger</tt>."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 11,
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/plain": [
       "[{'count(trigger)': 21}]"
      ]
     },
     "execution_count": 11,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "query=\"\"\"\n",
    "MATCH\n",
    "    trigger_to_hotspot=shortestPath((trigger:Call)-[:CALLS*]->(hotspot:HotSpot))\n",
    "WHERE \n",
    "    trigger.fqn STARTS WITH \"org.springframework.samples.petclinic\"\n",
    "AND \n",
    "    SINGLE(n IN NODES(trigger_to_hotspot) \n",
    "        WHERE exists(n.fqn) AND n.fqn STARTS WITH \"org.springframework.samples.petclinic\")\n",
    "SET \n",
    "    trigger:Trigger\n",
    "RETURN count(trigger)\n",
    "\"\"\"\n",
    "graph.run(query).data()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "After marking all the relevant nodes, we connect them via a new relationshop <tt>LEADS_TO</tt> to enable more elegant queries later on."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 12,
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/plain": [
       "[{'count(leads1)': 29, 'count(leads2)': 29, 'count(leads3)': 29}]"
      ]
     },
     "execution_count": 12,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "query=\"\"\"\n",
    "MATCH\n",
    "   (request:Request)-[:CALLS*]->\n",
    "       (entry:Entry)-[:CALLS*]->\n",
    "           (trigger:Trigger)-[:CALLS*]->\n",
    "               (hotspot:HotSpot)\n",
    "CREATE UNIQUE\n",
    "    (request)-[leads1:LEADS_TO]->\n",
    "        (entry)-[leads2:LEADS_TO]->\n",
    "            (trigger)-[leads3:LEADS_TO]->(hotspot)\n",
    "RETURN count(leads1), count(leads2), count(leads3)\n",
    "\"\"\"\n",
    "graph.run(query).data()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Getting results\n",
    "All the previous steps where needed to enable this simple query, that gives us the spots in the application, that lead eventually to the hotspots!"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 13,
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/html": [
       "<div>\n",
       "<table border=\"1\" class=\"dataframe\">\n",
       "  <thead>\n",
       "    <tr style=\"text-align: right;\">\n",
       "      <th></th>\n",
       "      <th>entry_class</th>\n",
       "      <th>entry_method</th>\n",
       "      <th>request</th>\n",
       "      <th>sql</th>\n",
       "      <th>sql_count</th>\n",
       "      <th>sql_count_sum</th>\n",
       "      <th>trigger_class</th>\n",
       "      <th>trigger_method</th>\n",
       "    </tr>\n",
       "  </thead>\n",
       "  <tbody>\n",
       "    <tr>\n",
       "      <th>0</th>\n",
       "      <td>OwnerController</td>\n",
       "      <td>initUpdateOwnerForm</td>\n",
       "      <td>HTTP: /petclinic/owners/1/edit.html</td>\n",
       "      <td>SELECT pets.id, name, birth_date, type_id, own...</td>\n",
       "      <td>1.0</td>\n",
       "      <td>107.0</td>\n",
       "      <td>JdbcOwnerRepositoryImpl</td>\n",
       "      <td>loadPetsAndVisits</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>1</th>\n",
       "      <td>OwnerController</td>\n",
       "      <td>showOwner</td>\n",
       "      <td>HTTP: /petclinic/owners/1</td>\n",
       "      <td>SELECT pets.id, name, birth_date, type_id, own...</td>\n",
       "      <td>2.0</td>\n",
       "      <td>107.0</td>\n",
       "      <td>JdbcOwnerRepositoryImpl</td>\n",
       "      <td>loadPetsAndVisits</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>2</th>\n",
       "      <td>OwnerController</td>\n",
       "      <td>showOwner</td>\n",
       "      <td>HTTP: /petclinic/owners/1.html</td>\n",
       "      <td>SELECT pets.id, name, birth_date, type_id, own...</td>\n",
       "      <td>2.0</td>\n",
       "      <td>107.0</td>\n",
       "      <td>JdbcOwnerRepositoryImpl</td>\n",
       "      <td>loadPetsAndVisits</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>3</th>\n",
       "      <td>OwnerController</td>\n",
       "      <td>processFindForm</td>\n",
       "      <td>HTTP: /petclinic/owners.html</td>\n",
       "      <td>SELECT pets.id, name, birth_date, type_id, own...</td>\n",
       "      <td>100.0</td>\n",
       "      <td>107.0</td>\n",
       "      <td>JdbcOwnerRepositoryImpl</td>\n",
       "      <td>loadPetsAndVisits</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>4</th>\n",
       "      <td>VisitController</td>\n",
       "      <td>loadPetWithVisit</td>\n",
       "      <td>HTTP: /petclinic/owners/1/pets/1/visits/new</td>\n",
       "      <td>SELECT pets.id, name, birth_date, type_id, own...</td>\n",
       "      <td>1.0</td>\n",
       "      <td>107.0</td>\n",
       "      <td>JdbcOwnerRepositoryImpl</td>\n",
       "      <td>loadPetsAndVisits</td>\n",
       "    </tr>\n",
       "  </tbody>\n",
       "</table>\n",
       "</div>"
      ],
      "text/plain": [
       "       entry_class         entry_method  \\\n",
       "0  OwnerController  initUpdateOwnerForm   \n",
       "1  OwnerController            showOwner   \n",
       "2  OwnerController            showOwner   \n",
       "3  OwnerController      processFindForm   \n",
       "4  VisitController     loadPetWithVisit   \n",
       "\n",
       "                                       request  \\\n",
       "0          HTTP: /petclinic/owners/1/edit.html   \n",
       "1                    HTTP: /petclinic/owners/1   \n",
       "2               HTTP: /petclinic/owners/1.html   \n",
       "3                 HTTP: /petclinic/owners.html   \n",
       "4  HTTP: /petclinic/owners/1/pets/1/visits/new   \n",
       "\n",
       "                                                 sql  sql_count  \\\n",
       "0  SELECT pets.id, name, birth_date, type_id, own...        1.0   \n",
       "1  SELECT pets.id, name, birth_date, type_id, own...        2.0   \n",
       "2  SELECT pets.id, name, birth_date, type_id, own...        2.0   \n",
       "3  SELECT pets.id, name, birth_date, type_id, own...      100.0   \n",
       "4  SELECT pets.id, name, birth_date, type_id, own...        1.0   \n",
       "\n",
       "   sql_count_sum            trigger_class     trigger_method  \n",
       "0          107.0  JdbcOwnerRepositoryImpl  loadPetsAndVisits  \n",
       "1          107.0  JdbcOwnerRepositoryImpl  loadPetsAndVisits  \n",
       "2          107.0  JdbcOwnerRepositoryImpl  loadPetsAndVisits  \n",
       "3          107.0  JdbcOwnerRepositoryImpl  loadPetsAndVisits  \n",
       "4          107.0  JdbcOwnerRepositoryImpl  loadPetsAndVisits  "
      ]
     },
     "execution_count": 13,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "query=\"\"\"\n",
    "MATCH \n",
    "   (request:Request)-[:LEADS_TO]->\n",
    "       (entry:Entry)-[:LEADS_TO]->\n",
    "           (trigger:Trigger)-[:LEADS_TO]->\n",
    "               (hotspot:HotSpot)\n",
    "RETURN  \n",
    "    request.method as request, \n",
    "    request.count as sql_count, \n",
    "    entry.class as entry_class,\n",
    "    entry.method as entry_method,    \n",
    "    trigger.class as trigger_class,    \n",
    "    trigger.method as trigger_method,\n",
    "    hotspot.value as sql, \n",
    "    hotspot.count as sql_count_sum\n",
    "\"\"\"\n",
    "hotspots = pd.DataFrame(graph.run(query).data())\n",
    "hotspots.head()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "The returned data consists of\n",
    "* <tt>request</tt>: the name of the HTTP request \n",
    "* <tt>sql_count</tt>: the number of SQL statements caused by this HTTP request \n",
    "* <tt>entry_class</tt>: the class name of the entry point into our application\n",
    "* <tt>entry_method</tt>: the method name of the entry point into our application   \n",
    "* <tt>trigger_class</tt>: the class name of the exit point out of our application\n",
    "* <tt>trigger_method</tt>: the method name of the exit point out of our application\n",
    "* <tt>sql</tt>: the executed SQL statement\n",
    "* <tt>sql_count_sum</tt>: the amount of all executed SQL statements of the same kind"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## A look at a subgraph\n",
    "If we take a look at the Neo4j browser and execute the statement from above but returning the nodes, aka\n",
    "\n",
    "```cypher\n",
    "MATCH \n",
    "   (request:Request)-[:LEADS_TO]->\n",
    "       (entry:Entry)-[:LEADS_TO]->\n",
    "           (trigger:Trigger)-[:LEADS_TO]->\n",
    "               (hotspot:HotSpot)\n",
    "RETURN  \n",
    "    request, entry, trigger, hotspot\n",
    "```\n",
    "\n",
    "we get a nice overview of all our performance hotspots, e. g.  \n",
    "![](resources/neo4j_result.png)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "With this graphical view, it's easy to see the connection between the requests, our application code and the hotspots.\n",
    "\n",
    "Albeit this view is nice for exploration, it's not actionable. So let's use Pandas to shape the data to knowledge!"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## In-depth analysis\n",
    "First, we have a look which parts in the application trigger all the SQLs. We simply group some columns to get a more dense overview:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 14,
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/html": [
       "<div>\n",
       "<table border=\"1\" class=\"dataframe\">\n",
       "  <thead>\n",
       "    <tr style=\"text-align: right;\">\n",
       "      <th></th>\n",
       "      <th></th>\n",
       "      <th></th>\n",
       "      <th></th>\n",
       "      <th></th>\n",
       "      <th>request</th>\n",
       "      <th>sql_count</th>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>request</th>\n",
       "      <th>entry_class</th>\n",
       "      <th>entry_method</th>\n",
       "      <th>trigger_class</th>\n",
       "      <th>trigger_method</th>\n",
       "      <th></th>\n",
       "      <th></th>\n",
       "    </tr>\n",
       "  </thead>\n",
       "  <tbody>\n",
       "    <tr>\n",
       "      <th rowspan=\"3\" valign=\"top\">HTTP: /petclinic/owners.html</th>\n",
       "      <th rowspan=\"3\" valign=\"top\">OwnerController</th>\n",
       "      <th rowspan=\"3\" valign=\"top\">processFindForm</th>\n",
       "      <th rowspan=\"3\" valign=\"top\">JdbcOwnerRepositoryImpl</th>\n",
       "      <th>findByLastName</th>\n",
       "      <td>1</td>\n",
       "      <td>1.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>getPetTypes</th>\n",
       "      <td>1</td>\n",
       "      <td>100.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>loadPetsAndVisits</th>\n",
       "      <td>1</td>\n",
       "      <td>100.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th rowspan=\"3\" valign=\"top\">HTTP: /petclinic/owners/1</th>\n",
       "      <th rowspan=\"3\" valign=\"top\">OwnerController</th>\n",
       "      <th rowspan=\"3\" valign=\"top\">showOwner</th>\n",
       "      <th rowspan=\"3\" valign=\"top\">JdbcOwnerRepositoryImpl</th>\n",
       "      <th>findById</th>\n",
       "      <td>1</td>\n",
       "      <td>2.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>getPetTypes</th>\n",
       "      <td>1</td>\n",
       "      <td>2.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>loadPetsAndVisits</th>\n",
       "      <td>1</td>\n",
       "      <td>2.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th rowspan=\"3\" valign=\"top\">HTTP: /petclinic/owners/1.html</th>\n",
       "      <th rowspan=\"3\" valign=\"top\">OwnerController</th>\n",
       "      <th rowspan=\"3\" valign=\"top\">showOwner</th>\n",
       "      <th rowspan=\"3\" valign=\"top\">JdbcOwnerRepositoryImpl</th>\n",
       "      <th>findById</th>\n",
       "      <td>1</td>\n",
       "      <td>2.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>getPetTypes</th>\n",
       "      <td>1</td>\n",
       "      <td>2.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>loadPetsAndVisits</th>\n",
       "      <td>1</td>\n",
       "      <td>2.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th rowspan=\"4\" valign=\"top\">HTTP: /petclinic/owners/1/edit.html</th>\n",
       "      <th rowspan=\"4\" valign=\"top\">OwnerController</th>\n",
       "      <th rowspan=\"3\" valign=\"top\">initUpdateOwnerForm</th>\n",
       "      <th rowspan=\"3\" valign=\"top\">JdbcOwnerRepositoryImpl</th>\n",
       "      <th>findById</th>\n",
       "      <td>1</td>\n",
       "      <td>1.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>getPetTypes</th>\n",
       "      <td>1</td>\n",
       "      <td>1.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>loadPetsAndVisits</th>\n",
       "      <td>1</td>\n",
       "      <td>1.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>processUpdateOwnerForm</th>\n",
       "      <th>JdbcOwnerRepositoryImpl</th>\n",
       "      <th>save</th>\n",
       "      <td>1</td>\n",
       "      <td>1.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th rowspan=\"5\" valign=\"top\">HTTP: /petclinic/owners/1/pets/1/visits/new</th>\n",
       "      <th rowspan=\"5\" valign=\"top\">VisitController</th>\n",
       "      <th rowspan=\"4\" valign=\"top\">loadPetWithVisit</th>\n",
       "      <th rowspan=\"3\" valign=\"top\">JdbcOwnerRepositoryImpl</th>\n",
       "      <th>findById</th>\n",
       "      <td>2</td>\n",
       "      <td>2.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>getPetTypes</th>\n",
       "      <td>2</td>\n",
       "      <td>2.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>loadPetsAndVisits</th>\n",
       "      <td>2</td>\n",
       "      <td>2.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>JdbcPetRepositoryImpl</th>\n",
       "      <th>findById</th>\n",
       "      <td>2</td>\n",
       "      <td>2.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>processNewVisitForm</th>\n",
       "      <th>JdbcVisitRepositoryImpl</th>\n",
       "      <th>save</th>\n",
       "      <td>5</td>\n",
       "      <td>5.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>HTTP: /petclinic/vets.html</th>\n",
       "      <th>VetController</th>\n",
       "      <th>showVetList</th>\n",
       "      <th>JdbcVetRepositoryImpl</th>\n",
       "      <th>findAll</th>\n",
       "      <td>3</td>\n",
       "      <td>12.0</td>\n",
       "    </tr>\n",
       "  </tbody>\n",
       "</table>\n",
       "</div>"
      ],
      "text/plain": [
       "                                                                                                                              request  \\\n",
       "request                                     entry_class     entry_method           trigger_class           trigger_method               \n",
       "HTTP: /petclinic/owners.html                OwnerController processFindForm        JdbcOwnerRepositoryImpl findByLastName           1   \n",
       "                                                                                                           getPetTypes              1   \n",
       "                                                                                                           loadPetsAndVisits        1   \n",
       "HTTP: /petclinic/owners/1                   OwnerController showOwner              JdbcOwnerRepositoryImpl findById                 1   \n",
       "                                                                                                           getPetTypes              1   \n",
       "                                                                                                           loadPetsAndVisits        1   \n",
       "HTTP: /petclinic/owners/1.html              OwnerController showOwner              JdbcOwnerRepositoryImpl findById                 1   \n",
       "                                                                                                           getPetTypes              1   \n",
       "                                                                                                           loadPetsAndVisits        1   \n",
       "HTTP: /petclinic/owners/1/edit.html         OwnerController initUpdateOwnerForm    JdbcOwnerRepositoryImpl findById                 1   \n",
       "                                                                                                           getPetTypes              1   \n",
       "                                                                                                           loadPetsAndVisits        1   \n",
       "                                                            processUpdateOwnerForm JdbcOwnerRepositoryImpl save                     1   \n",
       "HTTP: /petclinic/owners/1/pets/1/visits/new VisitController loadPetWithVisit       JdbcOwnerRepositoryImpl findById                 2   \n",
       "                                                                                                           getPetTypes              2   \n",
       "                                                                                                           loadPetsAndVisits        2   \n",
       "                                                                                   JdbcPetRepositoryImpl   findById                 2   \n",
       "                                                            processNewVisitForm    JdbcVisitRepositoryImpl save                     5   \n",
       "HTTP: /petclinic/vets.html                  VetController   showVetList            JdbcVetRepositoryImpl   findAll                  3   \n",
       "\n",
       "                                                                                                                              sql_count  \n",
       "request                                     entry_class     entry_method           trigger_class           trigger_method                \n",
       "HTTP: /petclinic/owners.html                OwnerController processFindForm        JdbcOwnerRepositoryImpl findByLastName           1.0  \n",
       "                                                                                                           getPetTypes            100.0  \n",
       "                                                                                                           loadPetsAndVisits      100.0  \n",
       "HTTP: /petclinic/owners/1                   OwnerController showOwner              JdbcOwnerRepositoryImpl findById                 2.0  \n",
       "                                                                                                           getPetTypes              2.0  \n",
       "                                                                                                           loadPetsAndVisits        2.0  \n",
       "HTTP: /petclinic/owners/1.html              OwnerController showOwner              JdbcOwnerRepositoryImpl findById                 2.0  \n",
       "                                                                                                           getPetTypes              2.0  \n",
       "                                                                                                           loadPetsAndVisits        2.0  \n",
       "HTTP: /petclinic/owners/1/edit.html         OwnerController initUpdateOwnerForm    JdbcOwnerRepositoryImpl findById                 1.0  \n",
       "                                                                                                           getPetTypes              1.0  \n",
       "                                                                                                           loadPetsAndVisits        1.0  \n",
       "                                                            processUpdateOwnerForm JdbcOwnerRepositoryImpl save                     1.0  \n",
       "HTTP: /petclinic/owners/1/pets/1/visits/new VisitController loadPetWithVisit       JdbcOwnerRepositoryImpl findById                 2.0  \n",
       "                                                                                                           getPetTypes              2.0  \n",
       "                                                                                                           loadPetsAndVisits        2.0  \n",
       "                                                                                   JdbcPetRepositoryImpl   findById                 2.0  \n",
       "                                                            processNewVisitForm    JdbcVisitRepositoryImpl save                     5.0  \n",
       "HTTP: /petclinic/vets.html                  VetController   showVetList            JdbcVetRepositoryImpl   findAll                 12.0  "
      ]
     },
     "execution_count": 14,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "sqls_per_method = hotspots.groupby([\n",
    "    'request',\n",
    "    'entry_class', \n",
    "    'entry_method', \n",
    "    'trigger_class', \n",
    "    'trigger_method']).agg(\n",
    "        {'sql_count' : 'sum',\n",
    "         'request' : 'count'})\n",
    "sqls_per_method"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "We see immediately that we have an issue with the loading of the pet's owners via the <tt>OwnerController</tt>. Let's look at the problem from another perspective: What kind of data is loaded by whom from the tables. We simply chop the SQL and extract just the name of the database table (in fact, the regex is so simple that some of the tables weren't identified. But because these are special cases, we can ignore them):"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 15,
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/plain": [
       "PETS               8\n",
       "OWNERS             7\n",
       "TYPES              6\n",
       "                   3\n",
       "SPECIALTIES        1\n",
       "VETS               1\n",
       "VISITS             1\n",
       "VET_SPECIALTIES    1\n",
       "Name: table, dtype: int64"
      ]
     },
     "execution_count": 15,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "hotspots['table'] = hotspots['sql'].\\\n",
    "    str.upper().str.extract(\n",
    "        r\".*(FROM|INTO|UPDATE) ([\\w\\.]*)\",\n",
    "        expand=True)[1]\n",
    "hotspots['table'].value_counts()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "And group the hotspots accordingly."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 16,
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/html": [
       "<div>\n",
       "<table border=\"1\" class=\"dataframe\">\n",
       "  <thead>\n",
       "    <tr style=\"text-align: right;\">\n",
       "      <th></th>\n",
       "      <th></th>\n",
       "      <th>sql_count</th>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>entry_class</th>\n",
       "      <th>table</th>\n",
       "      <th></th>\n",
       "    </tr>\n",
       "  </thead>\n",
       "  <tbody>\n",
       "    <tr>\n",
       "      <th rowspan=\"3\" valign=\"top\">OwnerController</th>\n",
       "      <th>OWNERS</th>\n",
       "      <td>7.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>PETS</th>\n",
       "      <td>105.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>TYPES</th>\n",
       "      <td>105.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th rowspan=\"3\" valign=\"top\">VetController</th>\n",
       "      <th>SPECIALTIES</th>\n",
       "      <td>1.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>VETS</th>\n",
       "      <td>1.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>VET_SPECIALTIES</th>\n",
       "      <td>10.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th rowspan=\"5\" valign=\"top\">VisitController</th>\n",
       "      <th></th>\n",
       "      <td>3.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>OWNERS</th>\n",
       "      <td>2.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>PETS</th>\n",
       "      <td>4.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>TYPES</th>\n",
       "      <td>2.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>VISITS</th>\n",
       "      <td>1.0</td>\n",
       "    </tr>\n",
       "  </tbody>\n",
       "</table>\n",
       "</div>"
      ],
      "text/plain": [
       "                                 sql_count\n",
       "entry_class     table                     \n",
       "OwnerController OWNERS                 7.0\n",
       "                PETS                 105.0\n",
       "                TYPES                105.0\n",
       "VetController   SPECIALTIES            1.0\n",
       "                VETS                   1.0\n",
       "                VET_SPECIALTIES       10.0\n",
       "VisitController                        3.0\n",
       "                OWNERS                 2.0\n",
       "                PETS                   4.0\n",
       "                TYPES                  2.0\n",
       "                VISITS                 1.0"
      ]
     },
     "execution_count": 16,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "grouped_by_entry_class_and_table = hotspots.groupby(['entry_class', 'table'])[['sql_count']].sum()\n",
    "grouped_by_entry_class_and_table"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Now we made the problem more obvious: The class <tt>OwnerController</tt> works heavily with the <tt>PETS</tt> table and the pet's <tt>TYPES</tt> table. Surely an error in our program.\n",
    "\n",
    "Let's visualize the problem with a nice donut chart in Bokeh:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 17,
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/html": [
       "\n",
       "    <div class=\"bk-root\">\n",
       "        <a href=\"http://bokeh.pydata.org\" target=\"_blank\" class=\"bk-logo bk-logo-small bk-logo-notebook\"></a>\n",
       "        <span id=\"7079aeea-6782-40b9-82ca-7cedd06ff21c\">Loading BokehJS ...</span>\n",
       "    </div>"
      ]
     },
     "metadata": {},
     "output_type": "display_data"
    },
    {
     "data": {
      "application/javascript": [
       "\n",
       "(function(global) {\n",
       "  function now() {\n",
       "    return new Date();\n",
       "  }\n",
       "\n",
       "  if (typeof (window._bokeh_onload_callbacks) === \"undefined\") {\n",
       "    window._bokeh_onload_callbacks = [];\n",
       "  }\n",
       "\n",
       "  function run_callbacks() {\n",
       "    window._bokeh_onload_callbacks.forEach(function(callback) { callback() });\n",
       "    delete window._bokeh_onload_callbacks\n",
       "    console.info(\"Bokeh: all callbacks have finished\");\n",
       "  }\n",
       "\n",
       "  function load_libs(js_urls, callback) {\n",
       "    window._bokeh_onload_callbacks.push(callback);\n",
       "    if (window._bokeh_is_loading > 0) {\n",
       "      console.log(\"Bokeh: BokehJS is being loaded, scheduling callback at\", now());\n",
       "      return null;\n",
       "    }\n",
       "    if (js_urls == null || js_urls.length === 0) {\n",
       "      run_callbacks();\n",
       "      return null;\n",
       "    }\n",
       "    console.log(\"Bokeh: BokehJS not loaded, scheduling load and callback at\", now());\n",
       "    window._bokeh_is_loading = js_urls.length;\n",
       "    for (var i = 0; i < js_urls.length; i++) {\n",
       "      var url = js_urls[i];\n",
       "      var s = document.createElement('script');\n",
       "      s.src = url;\n",
       "      s.async = false;\n",
       "      s.onreadystatechange = s.onload = function() {\n",
       "        window._bokeh_is_loading--;\n",
       "        if (window._bokeh_is_loading === 0) {\n",
       "          console.log(\"Bokeh: all BokehJS libraries loaded\");\n",
       "          run_callbacks()\n",
       "        }\n",
       "      };\n",
       "      s.onerror = function() {\n",
       "        console.warn(\"failed to load library \" + url);\n",
       "      };\n",
       "      console.log(\"Bokeh: injecting script tag for BokehJS library: \", url);\n",
       "      document.getElementsByTagName(\"head\")[0].appendChild(s);\n",
       "    }\n",
       "  };\n",
       "\n",
       "  var js_urls = ['https://cdn.pydata.org/bokeh/release/bokeh-0.12.0.min.js', 'https://cdn.pydata.org/bokeh/release/bokeh-widgets-0.12.0.min.js', 'https://cdn.pydata.org/bokeh/release/bokeh-compiler-0.12.0.min.js'];\n",
       "\n",
       "  var inline_js = [\n",
       "    function(Bokeh) {\n",
       "      Bokeh.set_log_level(\"info\");\n",
       "    },\n",
       "    \n",
       "    function(Bokeh) {\n",
       "      Bokeh.$(\"#7079aeea-6782-40b9-82ca-7cedd06ff21c\").text(\"BokehJS successfully loaded\");\n",
       "    },\n",
       "    function(Bokeh) {\n",
       "      console.log(\"Bokeh: injecting CSS: https://cdn.pydata.org/bokeh/release/bokeh-0.12.0.min.css\");\n",
       "      Bokeh.embed.inject_css(\"https://cdn.pydata.org/bokeh/release/bokeh-0.12.0.min.css\");\n",
       "      console.log(\"Bokeh: injecting CSS: https://cdn.pydata.org/bokeh/release/bokeh-widgets-0.12.0.min.css\");\n",
       "      Bokeh.embed.inject_css(\"https://cdn.pydata.org/bokeh/release/bokeh-widgets-0.12.0.min.css\");\n",
       "    }\n",
       "  ];\n",
       "\n",
       "  function run_inline_js() {\n",
       "    for (var i = 0; i < inline_js.length; i++) {\n",
       "      inline_js[i](window.Bokeh);\n",
       "    }\n",
       "  }\n",
       "\n",
       "  if (window._bokeh_is_loading === 0) {\n",
       "    console.log(\"Bokeh: BokehJS loaded, going straight to plotting\");\n",
       "    run_inline_js();\n",
       "  } else {\n",
       "    load_libs(js_urls, function() {\n",
       "      console.log(\"Bokeh: BokehJS plotting callback run at\", now());\n",
       "      run_inline_js();\n",
       "    });\n",
       "  }\n",
       "}(this));"
      ]
     },
     "metadata": {},
     "output_type": "display_data"
    },
    {
     "data": {
      "text/html": [
       "\n",
       "\n",
       "    <div class=\"bk-root\">\n",
       "        <div class=\"plotdiv\" id=\"a8d64175-3009-4a57-9078-e607caa2cb10\"></div>\n",
       "    </div>\n",
       "<script type=\"text/javascript\">\n",
       "  \n",
       "  (function(global) {\n",
       "    function now() {\n",
       "      return new Date();\n",
       "    }\n",
       "  \n",
       "    if (typeof (window._bokeh_onload_callbacks) === \"undefined\") {\n",
       "      window._bokeh_onload_callbacks = [];\n",
       "    }\n",
       "  \n",
       "    function run_callbacks() {\n",
       "      window._bokeh_onload_callbacks.forEach(function(callback) { callback() });\n",
       "      delete window._bokeh_onload_callbacks\n",
       "      console.info(\"Bokeh: all callbacks have finished\");\n",
       "    }\n",
       "  \n",
       "    function load_libs(js_urls, callback) {\n",
       "      window._bokeh_onload_callbacks.push(callback);\n",
       "      if (window._bokeh_is_loading > 0) {\n",
       "        console.log(\"Bokeh: BokehJS is being loaded, scheduling callback at\", now());\n",
       "        return null;\n",
       "      }\n",
       "      if (js_urls == null || js_urls.length === 0) {\n",
       "        run_callbacks();\n",
       "        return null;\n",
       "      }\n",
       "      console.log(\"Bokeh: BokehJS not loaded, scheduling load and callback at\", now());\n",
       "      window._bokeh_is_loading = js_urls.length;\n",
       "      for (var i = 0; i < js_urls.length; i++) {\n",
       "        var url = js_urls[i];\n",
       "        var s = document.createElement('script');\n",
       "        s.src = url;\n",
       "        s.async = false;\n",
       "        s.onreadystatechange = s.onload = function() {\n",
       "          window._bokeh_is_loading--;\n",
       "          if (window._bokeh_is_loading === 0) {\n",
       "            console.log(\"Bokeh: all BokehJS libraries loaded\");\n",
       "            run_callbacks()\n",
       "          }\n",
       "        };\n",
       "        s.onerror = function() {\n",
       "          console.warn(\"failed to load library \" + url);\n",
       "        };\n",
       "        console.log(\"Bokeh: injecting script tag for BokehJS library: \", url);\n",
       "        document.getElementsByTagName(\"head\")[0].appendChild(s);\n",
       "      }\n",
       "    };var element = document.getElementById(\"a8d64175-3009-4a57-9078-e607caa2cb10\");\n",
       "    if (element == null) {\n",
       "      console.log(\"Bokeh: ERROR: autoload.js configured with elementid 'a8d64175-3009-4a57-9078-e607caa2cb10' but no matching script tag was found. \")\n",
       "      return false;\n",
       "    }\n",
       "  \n",
       "    var js_urls = [];\n",
       "  \n",
       "    var inline_js = [\n",
       "      function(Bokeh) {\n",
       "        Bokeh.$(function() {\n",
       "            var docs_json = {\"ec521b87-396f-4217-8b09-509a083f106f\":{\"roots\":{\"references\":[{\"attributes\":{\"location\":\"top_left\",\"plot\":{\"id\":\"db4d03d9-8fcd-4a54-8dcc-95d25c420e6e\",\"subtype\":\"Chart\",\"type\":\"Plot\"}},\"id\":\"cc1d30eb-dc02-47f9-95fb-812e54f0d4ab\",\"type\":\"Legend\"},{\"attributes\":{\"axis_label\":null,\"formatter\":{\"id\":\"a8ee85c1-c2d8-4af5-8315-a80c1d8b5360\",\"type\":\"BasicTickFormatter\"},\"plot\":{\"id\":\"db4d03d9-8fcd-4a54-8dcc-95d25c420e6e\",\"subtype\":\"Chart\",\"type\":\"Plot\"},\"ticker\":{\"id\":\"12530972-3057-421f-8861-0e0dfa6a9eda\",\"type\":\"BasicTicker\"},\"visible\":false},\"id\":\"68928a0c-3af3-4c63-aa1b-e18f5e405d7b\",\"type\":\"LinearAxis\"},{\"attributes\":{},\"id\":\"a8ee85c1-c2d8-4af5-8315-a80c1d8b5360\",\"type\":\"BasicTickFormatter\"},{\"attributes\":{},\"id\":\"bbf70639-9676-4d47-a6d2-7e6e887ae70a\",\"type\":\"BasicTicker\"},{\"attributes\":{\"plot\":{\"id\":\"db4d03d9-8fcd-4a54-8dcc-95d25c420e6e\",\"subtype\":\"Chart\",\"type\":\"Plot\"}},\"id\":\"7a9e8712-a99e-4d0e-842c-8b943c98eb07\",\"type\":\"WheelZoomTool\"},{\"attributes\":{\"data_source\":{\"id\":\"3857eece-3eb6-4d43-81b2-0de701fb76c3\",\"type\":\"ColumnDataSource\"},\"glyph\":{\"id\":\"80bfd777-b859-43d2-ae1c-c1598e5118d0\",\"type\":\"Text\"},\"hover_glyph\":null,\"nonselection_glyph\":null,\"selection_glyph\":null},\"id\":\"c2516fd5-476a-4a8b-aca9-4d8a261f8617\",\"type\":\"GlyphRenderer\"},{\"attributes\":{\"angle\":{\"field\":\"text_angle\",\"units\":\"rad\"},\"text_align\":\"center\",\"text_baseline\":\"middle\",\"text_font_size\":{\"value\":\"8pt\"},\"x\":{\"field\":\"x\"},\"y\":{\"field\":\"y\"}},\"id\":\"80bfd777-b859-43d2-ae1c-c1598e5118d0\",\"type\":\"Text\"},{\"attributes\":{\"bottom_units\":\"screen\",\"fill_alpha\":{\"value\":0.5},\"fill_color\":{\"value\":\"lightgrey\"},\"left_units\":\"screen\",\"level\":\"overlay\",\"line_alpha\":{\"value\":1.0},\"line_color\":{\"value\":\"black\"},\"line_dash\":[4,4],\"line_width\":{\"value\":2},\"plot\":null,\"render_mode\":\"css\",\"right_units\":\"screen\",\"top_units\":\"screen\"},\"id\":\"ee0559b9-792b-4ba6-81a3-467e019b5da2\",\"type\":\"BoxAnnotation\"},{\"attributes\":{\"data_source\":{\"id\":\"307f4012-8753-42e9-b683-a7417554e706\",\"type\":\"ColumnDataSource\"},\"glyph\":{\"id\":\"b136a0cf-e609-4cf7-b81e-cdee279b82f6\",\"type\":\"AnnularWedge\"},\"hover_glyph\":null,\"nonselection_glyph\":null,\"selection_glyph\":null},\"id\":\"8735887f-e2b5-4b3f-806a-97c29a24514d\",\"type\":\"GlyphRenderer\"},{\"attributes\":{\"callback\":null,\"column_names\":[\"text\",\"text_angle\",\"x\",\"y\"],\"data\":{\"text\":[\"OwnerController\",\"OWNERS\",\"PETS\",\"TYPES\",\"VetController\",\"SPECIALTIES\",\"VETS\",\"VET_SPECIALTIES\",\"VisitController\",\"VisitController\",\"OWNERS\",\"PETS\",\"TYPES\",\"VISITS\"],\"text_angle\":[0.0,0.09124957914991101,1.5512428455484872,7.43032287363561,0.0,5.670509561458756,5.696580869787301,5.839973065594304,0.0,6.0094365697298535,6.074614840551218,6.1528287655368565,6.231042690522495,6.270149653015315],\"x\":[-1.0703908484900446,2.240639201510986,0.04399252933881191,-0.9249716024134575,1.0033790959849969,1.840752535138142,1.873856348665837,2.0326022488715942,1.11126385358098,2.1662194964359194,2.20123781025998,2.2309101241221763,2.2469419839212508,2.249808833392647],\"y\":[0.34624908876235694,0.20502675106485768,2.249569882747005,-2.051079602240898,-0.5087783306513068,-1.29388179691288,-1.2454566971857097,-0.9648979727837224,-0.17526450788551057,-0.6082705756987689,-0.46588850885362015,-0.2924722518277187,-0.1172677316742905,-0.02932939120431268]}},\"id\":\"3857eece-3eb6-4d43-81b2-0de701fb76c3\",\"type\":\"ColumnDataSource\"},{\"attributes\":{\"callback\":null,\"end\":3.1500000000000004,\"start\":-3.1500000000000004},\"id\":\"97479932-7aff-403b-945f-950a4b1867c6\",\"type\":\"Range1d\"},{\"attributes\":{},\"id\":\"20a5151e-1ec5-4a44-bee7-b4748ab036fc\",\"type\":\"ToolEvents\"},{\"attributes\":{\"plot\":{\"id\":\"db4d03d9-8fcd-4a54-8dcc-95d25c420e6e\",\"subtype\":\"Chart\",\"type\":\"Plot\"}},\"id\":\"2608d879-a054-40f4-9a11-91b741ab7eb6\",\"type\":\"SaveTool\"},{\"attributes\":{\"plot\":{\"id\":\"db4d03d9-8fcd-4a54-8dcc-95d25c420e6e\",\"subtype\":\"Chart\",\"type\":\"Plot\"}},\"id\":\"fd8f79d5-8327-474d-9279-a29762766299\",\"type\":\"HelpTool\"},{\"attributes\":{},\"id\":\"4b9fb647-4799-4ad8-8ec9-ffaea131a054\",\"type\":\"BasicTickFormatter\"},{\"attributes\":{\"end_angle\":{\"field\":\"end\",\"units\":\"rad\"},\"fill_alpha\":{\"value\":0.8},\"fill_color\":{\"field\":\"color\"},\"inner_radius\":{\"field\":\"inners\",\"units\":\"data\"},\"line_color\":{\"value\":\"White\"},\"outer_radius\":{\"field\":\"outers\",\"units\":\"data\"},\"start_angle\":{\"field\":\"start\",\"units\":\"rad\"},\"x\":{\"value\":0},\"y\":{\"value\":0}},\"id\":\"b136a0cf-e609-4cf7-b81e-cdee279b82f6\",\"type\":\"AnnularWedge\"},{\"attributes\":{\"callback\":null,\"end\":3.1500000000000004,\"start\":-3.1500000000000004},\"id\":\"495a37b6-175f-4570-b9ce-005cb473d543\",\"type\":\"Range1d\"},{\"attributes\":{},\"id\":\"12530972-3057-421f-8861-0e0dfa6a9eda\",\"type\":\"BasicTicker\"},{\"attributes\":{\"plot\":null,\"text\":null},\"id\":\"d4cdf2c1-732e-48bd-b08d-76e730ce87cf\",\"type\":\"Title\"},{\"attributes\":{\"below\":[{\"id\":\"68928a0c-3af3-4c63-aa1b-e18f5e405d7b\",\"type\":\"LinearAxis\"}],\"left\":[{\"id\":\"5ab5d755-3f25-4b73-87ec-3cad37d51e8c\",\"type\":\"LinearAxis\"}],\"plot_height\":400,\"plot_width\":400,\"renderers\":[{\"id\":\"ee0559b9-792b-4ba6-81a3-467e019b5da2\",\"type\":\"BoxAnnotation\"},{\"id\":\"8735887f-e2b5-4b3f-806a-97c29a24514d\",\"type\":\"GlyphRenderer\"},{\"id\":\"c2516fd5-476a-4a8b-aca9-4d8a261f8617\",\"type\":\"GlyphRenderer\"},{\"id\":\"cc1d30eb-dc02-47f9-95fb-812e54f0d4ab\",\"type\":\"Legend\"},{\"id\":\"68928a0c-3af3-4c63-aa1b-e18f5e405d7b\",\"type\":\"LinearAxis\"},{\"id\":\"5ab5d755-3f25-4b73-87ec-3cad37d51e8c\",\"type\":\"LinearAxis\"}],\"title\":{\"id\":\"d4cdf2c1-732e-48bd-b08d-76e730ce87cf\",\"type\":\"Title\"},\"tool_events\":{\"id\":\"20a5151e-1ec5-4a44-bee7-b4748ab036fc\",\"type\":\"ToolEvents\"},\"toolbar\":{\"id\":\"f8b16930-30ca-44a9-bd11-ad36d054197e\",\"type\":\"Toolbar\"},\"x_mapper_type\":\"auto\",\"x_range\":{\"id\":\"97479932-7aff-403b-945f-950a4b1867c6\",\"type\":\"Range1d\"},\"y_mapper_type\":\"auto\",\"y_range\":{\"id\":\"495a37b6-175f-4570-b9ce-005cb473d543\",\"type\":\"Range1d\"}},\"id\":\"db4d03d9-8fcd-4a54-8dcc-95d25c420e6e\",\"subtype\":\"Chart\",\"type\":\"Plot\"},{\"attributes\":{\"active_drag\":\"auto\",\"active_scroll\":\"auto\",\"active_tap\":\"auto\",\"tools\":[{\"id\":\"fc5f6e34-8b72-4dc3-a858-f05b7e1f0c28\",\"type\":\"PanTool\"},{\"id\":\"7a9e8712-a99e-4d0e-842c-8b943c98eb07\",\"type\":\"WheelZoomTool\"},{\"id\":\"5ff25e80-18e6-40a8-9305-4e8901441621\",\"type\":\"BoxZoomTool\"},{\"id\":\"2608d879-a054-40f4-9a11-91b741ab7eb6\",\"type\":\"SaveTool\"},{\"id\":\"2fade6e2-a7c7-4472-940b-d367404f3b77\",\"type\":\"ResetTool\"},{\"id\":\"fd8f79d5-8327-474d-9279-a29762766299\",\"type\":\"HelpTool\"}]},\"id\":\"f8b16930-30ca-44a9-bd11-ad36d054197e\",\"type\":\"Toolbar\"},{\"attributes\":{\"callback\":null,\"column_names\":[\"outers\",\"inners\",\"level\",\"start\",\"entry_class_table\",\"end\",\"color\",\"centers\",\"values\"],\"data\":{\"centers\":[1.125,2.25,2.25,2.25,1.125,2.25,2.25,2.25,1.125,2.25,2.25,2.25,2.25,2.25],\"color\":[\"#f22c40\",\"#f22c40\",\"#f22c40\",\"#f22c40\",\"#5ab738\",\"#5ab738\",\"#5ab738\",\"#5ab738\",\"#407ee7\",\"#407ee7\",\"#407ee7\",\"#407ee7\",\"#407ee7\",\"#407ee7\"],\"end\":[5.657473907294483,0.18249915829982202,2.9199865327971524,5.657473907294483,5.970329607237034,5.683545215623028,5.709616523951574,5.970329607237034,6.283185307179586,6.048543532222673,6.100686148879765,6.204971382193949,6.257113998851041,6.283185307179587],\"entry_class_table\":[[\"OwnerController\",\"\"],[\"OwnerController\",\"OWNERS\"],[\"OwnerController\",\"PETS\"],[\"OwnerController\",\"TYPES\"],[\"VetController\",\"\"],[\"VetController\",\"SPECIALTIES\"],[\"VetController\",\"VETS\"],[\"VetController\",\"VET_SPECIALTIES\"],[\"VisitController\",\"\"],[\"VisitController\",\"\"],[\"VisitController\",\"OWNERS\"],[\"VisitController\",\"PETS\"],[\"VisitController\",\"TYPES\"],[\"VisitController\",\"VISITS\"]],\"inners\":[0.0,1.5,1.5,1.5,0.0,1.5,1.5,1.5,0.0,1.5,1.5,1.5,1.5,1.5],\"level\":[0.0,1.0,1.0,1.0,0.0,1.0,1.0,1.0,0.0,1.0,1.0,1.0,1.0,1.0],\"outers\":[1.5,3.0,3.0,3.0,1.5,3.0,3.0,3.0,1.5,3.0,3.0,3.0,3.0,3.0],\"start\":[0.0,0.0,0.18249915829982202,2.9199865327971524,5.657473907294483,5.657473907294483,5.683545215623028,5.709616523951574,5.970329607237034,5.970329607237034,6.048543532222673,6.100686148879765,6.204971382193949,6.257113998851041],\"values\":[217.0,7.0,105.0,105.0,12.0,1.0,1.0,10.0,12.0,3.0,2.0,4.0,2.0,1.0]}},\"id\":\"307f4012-8753-42e9-b683-a7417554e706\",\"type\":\"ColumnDataSource\"},{\"attributes\":{\"plot\":{\"id\":\"db4d03d9-8fcd-4a54-8dcc-95d25c420e6e\",\"subtype\":\"Chart\",\"type\":\"Plot\"}},\"id\":\"fc5f6e34-8b72-4dc3-a858-f05b7e1f0c28\",\"type\":\"PanTool\"},{\"attributes\":{\"axis_label\":null,\"formatter\":{\"id\":\"4b9fb647-4799-4ad8-8ec9-ffaea131a054\",\"type\":\"BasicTickFormatter\"},\"plot\":{\"id\":\"db4d03d9-8fcd-4a54-8dcc-95d25c420e6e\",\"subtype\":\"Chart\",\"type\":\"Plot\"},\"ticker\":{\"id\":\"bbf70639-9676-4d47-a6d2-7e6e887ae70a\",\"type\":\"BasicTicker\"},\"visible\":false},\"id\":\"5ab5d755-3f25-4b73-87ec-3cad37d51e8c\",\"type\":\"LinearAxis\"},{\"attributes\":{\"overlay\":{\"id\":\"ee0559b9-792b-4ba6-81a3-467e019b5da2\",\"type\":\"BoxAnnotation\"},\"plot\":{\"id\":\"db4d03d9-8fcd-4a54-8dcc-95d25c420e6e\",\"subtype\":\"Chart\",\"type\":\"Plot\"}},\"id\":\"5ff25e80-18e6-40a8-9305-4e8901441621\",\"type\":\"BoxZoomTool\"},{\"attributes\":{\"plot\":{\"id\":\"db4d03d9-8fcd-4a54-8dcc-95d25c420e6e\",\"subtype\":\"Chart\",\"type\":\"Plot\"}},\"id\":\"2fade6e2-a7c7-4472-940b-d367404f3b77\",\"type\":\"ResetTool\"}],\"root_ids\":[\"db4d03d9-8fcd-4a54-8dcc-95d25c420e6e\"]},\"title\":\"Bokeh Application\",\"version\":\"0.12.0\"}};\n",
       "            var render_items = [{\"docid\":\"ec521b87-396f-4217-8b09-509a083f106f\",\"elementid\":\"a8d64175-3009-4a57-9078-e607caa2cb10\",\"modelid\":\"db4d03d9-8fcd-4a54-8dcc-95d25c420e6e\",\"notebook_comms_target\":\"c47e20fa-a122-4f72-9eba-6949c128fabb\"}];\n",
       "            \n",
       "            Bokeh.embed.embed_items(docs_json, render_items);\n",
       "        });\n",
       "      },\n",
       "      function(Bokeh) {\n",
       "      }\n",
       "    ];\n",
       "  \n",
       "    function run_inline_js() {\n",
       "      for (var i = 0; i < inline_js.length; i++) {\n",
       "        inline_js[i](window.Bokeh);\n",
       "      }\n",
       "    }\n",
       "  \n",
       "    if (window._bokeh_is_loading === 0) {\n",
       "      console.log(\"Bokeh: BokehJS loaded, going straight to plotting\");\n",
       "      run_inline_js();\n",
       "    } else {\n",
       "      load_libs(js_urls, function() {\n",
       "        console.log(\"Bokeh: BokehJS plotting callback run at\", now());\n",
       "        run_inline_js();\n",
       "      });\n",
       "    }\n",
       "  }(this));\n",
       "</script>"
      ]
     },
     "metadata": {},
     "output_type": "display_data"
    },
    {
     "data": {
      "text/html": [
       "<p><code>&lt;Bokeh Notebook handle for <strong>In[17]</strong>&gt;</code></p>"
      ],
      "text/plain": [
       "<bokeh.io._CommsHandle at 0x1a2bfdedef0>"
      ]
     },
     "execution_count": 17,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "from bokeh.charts import Donut, show, output_notebook\n",
    "\n",
    "plot_data = grouped_by_entry_class_and_table.reset_index()\n",
    "d = Donut(plot_data, label=['entry_class', 'table'], \n",
    "          values='sql_count',\n",
    "          text_font_size='8pt',\n",
    "          hover_text='sql_count'\n",
    "         )\n",
    "output_notebook()\n",
    "show(d)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "You could also have a look at the most problematic spot in the application by grouping the data by the class and the method that triggers the execution of the most SQL statements."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 18,
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/html": [
       "<div>\n",
       "<table border=\"1\" class=\"dataframe\">\n",
       "  <thead>\n",
       "    <tr style=\"text-align: right;\">\n",
       "      <th></th>\n",
       "      <th></th>\n",
       "      <th>sql_count</th>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>trigger_class</th>\n",
       "      <th>trigger_method</th>\n",
       "      <th></th>\n",
       "    </tr>\n",
       "  </thead>\n",
       "  <tbody>\n",
       "    <tr>\n",
       "      <th rowspan=\"2\" valign=\"top\">JdbcOwnerRepositoryImpl</th>\n",
       "      <th>getPetTypes</th>\n",
       "      <td>107.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>loadPetsAndVisits</th>\n",
       "      <td>107.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>JdbcVetRepositoryImpl</th>\n",
       "      <th>findAll</th>\n",
       "      <td>12.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>JdbcOwnerRepositoryImpl</th>\n",
       "      <th>findById</th>\n",
       "      <td>7.0</td>\n",
       "    </tr>\n",
       "    <tr>\n",
       "      <th>JdbcVisitRepositoryImpl</th>\n",
       "      <th>save</th>\n",
       "      <td>5.0</td>\n",
       "    </tr>\n",
       "  </tbody>\n",
       "</table>\n",
       "</div>"
      ],
      "text/plain": [
       "                                           sql_count\n",
       "trigger_class           trigger_method              \n",
       "JdbcOwnerRepositoryImpl getPetTypes            107.0\n",
       "                        loadPetsAndVisits      107.0\n",
       "JdbcVetRepositoryImpl   findAll                 12.0\n",
       "JdbcOwnerRepositoryImpl findById                 7.0\n",
       "JdbcVisitRepositoryImpl save                     5.0"
      ]
     },
     "execution_count": 18,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "hotspots.groupby(['trigger_class', 'trigger_method'])[['sql_count']].sum().sort_values(\n",
    "    by='sql_count', ascending=False).head(5)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Again, the <tt>Jdbc<b>Owner</b>RepositoryImpl</tt> is heavily working with other data. \n",
    "\n",
    "This gives you a very actionable information where you can start improving!"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "# Result\n",
    "The overall result of this analysis is clearly an application problem and a sign of the famous N+1 query problem that's almost typical for any application that uses a database without care.\n",
    "\n",
    "If you look at the corresponding source code, you'll find spots in your application like the one below in the <tt>JdbcOwnerRepositoryImpl</tt> class:\n",
    "\n",
    "```java\n",
    "    public void loadPetsAndVisits(final Owner owner) {\n",
    "        Map<String, Object> params = new HashMap<>();\n",
    "        params.put(\"id\", owner.getId());\n",
    "        \n",
    "        final List<JdbcPet> pets = this.namedParameterJdbcTemplate.query(\n",
    "            \"SELECT pets.id, name, birth_date, type_id, owner_id, \n",
    "             visits.id as visit_id, visit_date, description, pet_id \n",
    "             FROM pets LEFT OUTER JOIN visits ON  pets.id = pet_id \n",
    "             WHERE owner_id=:id\", params, new JdbcPetVisitExtractor());\n",
    "             \n",
    "        Collection<PetType> petTypes = getPetTypes();\n",
    "        for (JdbcPet pet : pets) {\n",
    "            pet.setType(EntityUtils.getById(petTypes, PetType.class, pet.getTypeId()));\n",
    "            owner.addPet(pet);\n",
    "        }\n",
    "    }\n",
    "```\n",
    "E. g. we see data that isn't needed in the UI, but loaded from a database within a loop. This can surely be improved!"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "collapsed": true
   },
   "source": [
    "# Discussion and Limitations\n",
    "\n",
    "This approach for mining performance problem follows a simple pattern: \n",
    "1. Load all the data you need into Neo4j\n",
    "1. Encode your problems/concepts in Cypher \n",
    "1. Retrieve the data for further analysis in Pandas\n",
    "\n",
    "With these steps, you quickly drill down to the root cause of problems.\n",
    "\n",
    "But there are also limitations:\n",
    "\n",
    "* There is one big problem with this approach if you use want to export big hotspot call trees in JProfiler. It simply doesn't work when the XML data is getting too big (> 500 MB)\n",
    "  * One approach would be the get direct access to the HotSpot data in JProfiler. I still have to ask the developers of JProfiler if this would be possible.\n",
    "  * The other approach that we're trying to do at work is to export just the Call Tree (because it's not so much data) as a XML file, import it into Neo4j (by using jQAssistant, too) and calculate the HotSpots ourself.\n",
    "* Additionally, jQAssistant isn't able to load huge (> 2 GB) XML files out of the box, but there may be some tweaks to get that working, too.\n",
    "* Identifying your own application just by the package name makes the Cypher queries a lot more complex. If you can (and if you have something that's called an architecture), it should be easier for you to just use class names to determine the entry points into your application (the same goes for determining the triggers).\n",
    "\n",
    "Overall, I'm really happy with this approach because it immediately shows me the performance pain points in our application."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "collapsed": true
   },
   "source": [
    "# Summary\n",
    "I hope that you take away many new ideas for your analysis of software data:\n",
    "\n",
    "* It's easy to export graph like performance measures from JProfiler\n",
    "* You can read XML content with jQAssistant\n",
    "* With coding your knowledge into a graph step by step, you can easily achieve almost anything with Neo4j\n",
    "* Post-processing good data with Pandas and Bokeh is easy like pie!\n",
    "\n",
    "The main idea was to load a huge graph with all the information and reduce it to just the specific information we need for action. In general, I use this approach to mine my way through any graph-based data format like XML files or other software structures.\n",
    "\n",
    "Last but not least: Many thanks to my student Andreas, who had to prototype some of my crazy graph query ideas :-)\n",
    "\n",
    "\n",
    "And as always: I'll be happy to answer your questions and please let me know what you think about this approach!"
   ]
  }
 ],
 "metadata": {
  "anaconda-cloud": {},
  "kernelspec": {
   "display_name": "Python [Root]",
   "language": "python",
   "name": "Python [Root]"
  },
  "language_info": {
   "codemirror_mode": {
    "name": "ipython",
    "version": 3
   },
   "file_extension": ".py",
   "mimetype": "text/x-python",
   "name": "python",
   "nbconvert_exporter": "python",
   "pygments_lexer": "ipython3",
   "version": "3.5.2"
  }
 },
 "nbformat": 4,
 "nbformat_minor": 1
}