notebooks/01.07-Timing-and-Profiling.ipynb

{
 "cells": [
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "<!--BOOK_INFORMATION-->\n",
    "<img align=\"left\" style=\"padding-right:10px;\" src=\"figures/PDSH-cover-small.png\">\n",
    "\n",
    "*This notebook contains an excerpt from the [Python Data Science Handbook](http://shop.oreilly.com/product/0636920034919.do) by Jake VanderPlas; the content is available [on GitHub](https://github.com/jakevdp/PythonDataScienceHandbook).*\n",
    "\n",
    "*The text is released under the [CC-BY-NC-ND license](https://creativecommons.org/licenses/by-nc-nd/3.0/us/legalcode), and code is released under the [MIT license](https://opensource.org/licenses/MIT). If you find this content useful, please consider supporting the work by [buying the book](http://shop.oreilly.com/product/0636920034919.do)!*"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "<!--NAVIGATION-->\n",
    "< [Errors and Debugging](01.06-Errors-and-Debugging.ipynb) | [Contents](Index.ipynb) | [More IPython Resources](01.08-More-IPython-Resources.ipynb) >\n",
    "\n",
    "<a href=\"https://colab.research.google.com/github/jakevdp/PythonDataScienceHandbook/blob/master/notebooks/01.07-Timing-and-Profiling.ipynb\"><img align=\"left\" src=\"https://colab.research.google.com/assets/colab-badge.svg\" alt=\"Open in Colab\" title=\"Open and Execute in Google Colaboratory\"></a>\n"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "# Profiling and Timing Code"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "In the process of developing code and creating data processing pipelines, there are often trade-offs you can make between various implementations.\n",
    "Early in developing your algorithm, it can be counterproductive to worry about such things. As Donald Knuth famously quipped, \"We should forget about small efficiencies, say about 97% of the time: premature optimization is the root of all evil.\"\n",
    "\n",
    "But once you have your code working, it can be useful to dig into its efficiency a bit.\n",
    "Sometimes it's useful to check the execution time of a given command or set of commands; other times it's useful to dig into a multiline process and determine where the bottleneck lies in some complicated series of operations.\n",
    "IPython provides access to a wide array of functionality for this kind of timing and profiling of code.\n",
    "Here we'll discuss the following IPython magic commands:\n",
    "\n",
    "- ``%time``: Time the execution of a single statement\n",
    "- ``%timeit``: Time repeated execution of a single statement for more accuracy\n",
    "- ``%prun``: Run code with the profiler\n",
    "- ``%lprun``: Run code with the line-by-line profiler\n",
    "- ``%memit``: Measure the memory use of a single statement\n",
    "- ``%mprun``: Run code with the line-by-line memory profiler\n",
    "\n",
    "The last four commands are not bundled with IPython–you'll need to get the ``line_profiler`` and ``memory_profiler`` extensions, which we will discuss in the following sections."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Timing Code Snippets: ``%timeit`` and ``%time``\n",
    "\n",
    "We saw the ``%timeit`` line-magic and ``%%timeit`` cell-magic in the introduction to magic functions in [IPython Magic Commands](01.03-Magic-Commands.ipynb); it can be used to time the repeated execution of snippets of code:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 1,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "100000 loops, best of 3: 1.54 µs per loop\n"
     ]
    }
   ],
   "source": [
    "%timeit sum(range(100))"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Note that because this operation is so fast, ``%timeit`` automatically does a large number of repetitions.\n",
    "For slower commands, ``%timeit`` will automatically adjust and perform fewer repetitions:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 2,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "1 loops, best of 3: 407 ms per loop\n"
     ]
    }
   ],
   "source": [
    "%%timeit\n",
    "total = 0\n",
    "for i in range(1000):\n",
    "    for j in range(1000):\n",
    "        total += i * (-1) ** j"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Sometimes repeating an operation is not the best option.\n",
    "For example, if we have a list that we'd like to sort, we might be misled by a repeated operation.\n",
    "Sorting a pre-sorted list is much faster than sorting an unsorted list, so the repetition will skew the result:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 3,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "100 loops, best of 3: 1.9 ms per loop\n"
     ]
    }
   ],
   "source": [
    "import random\n",
    "L = [random.random() for i in range(100000)]\n",
    "%timeit L.sort()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "For this, the ``%time`` magic function may be a better choice. It also is a good choice for longer-running commands, when short, system-related delays are unlikely to affect the result.\n",
    "Let's time the sorting of an unsorted and a presorted list:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 4,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "sorting an unsorted list:\n",
      "CPU times: user 40.6 ms, sys: 896 µs, total: 41.5 ms\n",
      "Wall time: 41.5 ms\n"
     ]
    }
   ],
   "source": [
    "import random\n",
    "L = [random.random() for i in range(100000)]\n",
    "print(\"sorting an unsorted list:\")\n",
    "%time L.sort()"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 5,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "sorting an already sorted list:\n",
      "CPU times: user 8.18 ms, sys: 10 µs, total: 8.19 ms\n",
      "Wall time: 8.24 ms\n"
     ]
    }
   ],
   "source": [
    "print(\"sorting an already sorted list:\")\n",
    "%time L.sort()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Notice how much faster the presorted list is to sort, but notice also how much longer the timing takes with ``%time`` versus ``%timeit``, even for the presorted list!\n",
    "This is a result of the fact that ``%timeit`` does some clever things under the hood to prevent system calls from interfering with the timing.\n",
    "For example, it prevents cleanup of unused Python objects (known as *garbage collection*) which might otherwise affect the timing.\n",
    "For this reason, ``%timeit`` results are usually noticeably faster than ``%time`` results.\n",
    "\n",
    "For ``%time`` as with ``%timeit``, using the double-percent-sign cell magic syntax allows timing of multiline scripts:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 6,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "CPU times: user 504 ms, sys: 979 µs, total: 505 ms\n",
      "Wall time: 505 ms\n"
     ]
    }
   ],
   "source": [
    "%%time\n",
    "total = 0\n",
    "for i in range(1000):\n",
    "    for j in range(1000):\n",
    "        total += i * (-1) ** j"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "For more information on ``%time`` and ``%timeit``, as well as their available options, use the IPython help functionality (i.e., type ``%time?`` at the IPython prompt)."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Profiling Full Scripts: ``%prun``\n",
    "\n",
    "A program is made of many single statements, and sometimes timing these statements in context is more important than timing them on their own.\n",
    "Python contains a built-in code profiler (which you can read about in the Python documentation), but IPython offers a much more convenient way to use this profiler, in the form of the magic function ``%prun``.\n",
    "\n",
    "By way of example, we'll define a simple function that does some calculations:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 7,
   "metadata": {},
   "outputs": [],
   "source": [
    "def sum_of_lists(N):\n",
    "    total = 0\n",
    "    for i in range(5):\n",
    "        L = [j ^ (j >> i) for j in range(N)]\n",
    "        total += sum(L)\n",
    "    return total"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Now we can call ``%prun`` with a function call to see the profiled results:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 8,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      " "
     ]
    }
   ],
   "source": [
    "%prun sum_of_lists(1000000)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "In the notebook, the output is printed to the pager, and looks something like this:\n",
    "\n",
    "```\n",
    "14 function calls in 0.714 seconds\n",
    "\n",
    "   Ordered by: internal time\n",
    "\n",
    "   ncalls  tottime  percall  cumtime  percall filename:lineno(function)\n",
    "        5    0.599    0.120    0.599    0.120 <ipython-input-19>:4(<listcomp>)\n",
    "        5    0.064    0.013    0.064    0.013 {built-in method sum}\n",
    "        1    0.036    0.036    0.699    0.699 <ipython-input-19>:1(sum_of_lists)\n",
    "        1    0.014    0.014    0.714    0.714 <string>:1(<module>)\n",
    "        1    0.000    0.000    0.714    0.714 {built-in method exec}\n",
    "```\n",
    "\n",
    "The result is a table that indicates, in order of total time on each function call, where the execution is spending the most time. In this case, the bulk of execution time is in the list comprehension inside ``sum_of_lists``.\n",
    "From here, we could start thinking about what changes we might make to improve the performance in the algorithm.\n",
    "\n",
    "For more information on ``%prun``, as well as its available options, use the IPython help functionality (i.e., type ``%prun?`` at the IPython prompt)."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Line-By-Line Profiling with ``%lprun``\n",
    "\n",
    "The function-by-function profiling of ``%prun`` is useful, but sometimes it's more convenient to have a line-by-line profile report.\n",
    "This is not built into Python or IPython, but there is a ``line_profiler`` package available for installation that can do this.\n",
    "Start by using Python's packaging tool, ``pip``, to install the ``line_profiler`` package:\n",
    "\n",
    "```\n",
    "$ pip install line_profiler\n",
    "```\n",
    "\n",
    "Next, you can use IPython to load the ``line_profiler`` IPython extension, offered as part of this package:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 9,
   "metadata": {},
   "outputs": [],
   "source": [
    "%load_ext line_profiler"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Now the ``%lprun`` command will do a line-by-line profiling of any function–in this case, we need to tell it explicitly which functions we're interested in profiling:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 10,
   "metadata": {},
   "outputs": [],
   "source": [
    "%lprun -f sum_of_lists sum_of_lists(5000)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "As before, the notebook sends the result to the pager, but it looks something like this:\n",
    "\n",
    "```\n",
    "Timer unit: 1e-06 s\n",
    "\n",
    "Total time: 0.009382 s\n",
    "File: <ipython-input-19-fa2be176cc3e>\n",
    "Function: sum_of_lists at line 1\n",
    "\n",
    "Line #      Hits         Time  Per Hit   % Time  Line Contents\n",
    "==============================================================\n",
    "     1                                           def sum_of_lists(N):\n",
    "     2         1            2      2.0      0.0      total = 0\n",
    "     3         6            8      1.3      0.1      for i in range(5):\n",
    "     4         5         9001   1800.2     95.9          L = [j ^ (j >> i) for j in range(N)]\n",
    "     5         5          371     74.2      4.0          total += sum(L)\n",
    "     6         1            0      0.0      0.0      return total\n",
    "```\n",
    "\n",
    "The information at the top gives us the key to reading the results: the time is reported in microseconds and we can see where the program is spending the most time.\n",
    "At this point, we may be able to use this information to modify aspects of the script and make it perform better for our desired use case.\n",
    "\n",
    "For more information on ``%lprun``, as well as its available options, use the IPython help functionality (i.e., type ``%lprun?`` at the IPython prompt)."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Profiling Memory Use: ``%memit`` and ``%mprun``\n",
    "\n",
    "Another aspect of profiling is the amount of memory an operation uses.\n",
    "This can be evaluated with another IPython extension, the ``memory_profiler``.\n",
    "As with the ``line_profiler``, we start by ``pip``-installing the extension:\n",
    "\n",
    "```\n",
    "$ pip install memory_profiler\n",
    "```\n",
    "\n",
    "Then we can use IPython to load the extension:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 12,
   "metadata": {},
   "outputs": [],
   "source": [
    "%load_ext memory_profiler"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "The memory profiler extension contains two useful magic functions: the ``%memit`` magic (which offers a memory-measuring equivalent of ``%timeit``) and the ``%mprun`` function (which offers a memory-measuring equivalent of ``%lprun``).\n",
    "The ``%memit`` function can be used rather simply:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 13,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "peak memory: 100.08 MiB, increment: 61.36 MiB\n"
     ]
    }
   ],
   "source": [
    "%memit sum_of_lists(1000000)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "We see that this function uses about 100 MB of memory.\n",
    "\n",
    "For a line-by-line description of memory use, we can use the ``%mprun`` magic.\n",
    "Unfortunately, this magic works only for functions defined in separate modules rather than the notebook itself, so we'll start by using the ``%%file`` magic to create a simple module called ``mprun_demo.py``, which contains our ``sum_of_lists`` function, with one addition that will make our memory profiling results more clear:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 14,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "Overwriting mprun_demo.py\n"
     ]
    }
   ],
   "source": [
    "%%file mprun_demo.py\n",
    "def sum_of_lists(N):\n",
    "    total = 0\n",
    "    for i in range(5):\n",
    "        L = [j ^ (j >> i) for j in range(N)]\n",
    "        total += sum(L)\n",
    "        del L # remove reference to L\n",
    "    return total"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "We can now import the new version of this function and run the memory line profiler:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 15,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "\n"
     ]
    }
   ],
   "source": [
    "from mprun_demo import sum_of_lists\n",
    "%mprun -f sum_of_lists sum_of_lists(1000000)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "The result, printed to the pager, gives us a summary of the memory use of the function, and looks something like this:\n",
    "```\n",
    "Filename: ./mprun_demo.py\n",
    "\n",
    "Line #    Mem usage    Increment   Line Contents\n",
    "================================================\n",
    "     4     71.9 MiB      0.0 MiB           L = [j ^ (j >> i) for j in range(N)]\n",
    "\n",
    "\n",
    "Filename: ./mprun_demo.py\n",
    "\n",
    "Line #    Mem usage    Increment   Line Contents\n",
    "================================================\n",
    "     1     39.0 MiB      0.0 MiB   def sum_of_lists(N):\n",
    "     2     39.0 MiB      0.0 MiB       total = 0\n",
    "     3     46.5 MiB      7.5 MiB       for i in range(5):\n",
    "     4     71.9 MiB     25.4 MiB           L = [j ^ (j >> i) for j in range(N)]\n",
    "     5     71.9 MiB      0.0 MiB           total += sum(L)\n",
    "     6     46.5 MiB    -25.4 MiB           del L # remove reference to L\n",
    "     7     39.1 MiB     -7.4 MiB       return total\n",
    "```\n",
    "Here the ``Increment`` column tells us how much each line affects the total memory budget: observe that when we create and delete the list ``L``, we are adding about 25 MB of memory usage.\n",
    "This is on top of the background memory usage from the Python interpreter itself.\n",
    "\n",
    "For more information on ``%memit`` and ``%mprun``, as well as their available options, use the IPython help functionality (i.e., type ``%memit?`` at the IPython prompt)."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "<!--NAVIGATION-->\n",
    "< [Errors and Debugging](01.06-Errors-and-Debugging.ipynb) | [Contents](Index.ipynb) | [More IPython Resources](01.08-More-IPython-Resources.ipynb) >\n",
    "\n",
    "<a href=\"https://colab.research.google.com/github/jakevdp/PythonDataScienceHandbook/blob/master/notebooks/01.07-Timing-and-Profiling.ipynb\"><img align=\"left\" src=\"https://colab.research.google.com/assets/colab-badge.svg\" alt=\"Open in Colab\" title=\"Open and Execute in Google Colaboratory\"></a>\n"
   ]
  }
 ],
 "metadata": {
  "anaconda-cloud": {},
  "kernelspec": {
   "display_name": "Python [default]",
   "language": "python",
   "name": "python3"
  },
  "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.6.1"
  }
 },
 "nbformat": 4,
 "nbformat_minor": 1
}