Profiling_in_a_Jupyter_notebook.ipynb

{
 "cells": [
  {
   "cell_type": "markdown",
   "metadata": {
    "toc": "true"
   },
   "source": [
    "# Table of Contents\n",
    " <p><div class=\"lev1 toc-item\"><a href=\"#Profiling-in-a-Jupyter-notebook\" data-toc-modified-id=\"Profiling-in-a-Jupyter-notebook-1\"><span class=\"toc-item-num\">1&nbsp;&nbsp;</span>Profiling in a Jupyter notebook</a></div><div class=\"lev2 toc-item\"><a href=\"#References\" data-toc-modified-id=\"References-11\"><span class=\"toc-item-num\">1.1&nbsp;&nbsp;</span>References</a></div><div class=\"lev2 toc-item\"><a href=\"#Basic-Python-code\" data-toc-modified-id=\"Basic-Python-code-12\"><span class=\"toc-item-num\">1.2&nbsp;&nbsp;</span>Basic Python code</a></div><div class=\"lev2 toc-item\"><a href=\"#First-profiling\" data-toc-modified-id=\"First-profiling-13\"><span class=\"toc-item-num\">1.3&nbsp;&nbsp;</span>First profiling</a></div><div class=\"lev2 toc-item\"><a href=\"#Cython-version\" data-toc-modified-id=\"Cython-version-14\"><span class=\"toc-item-num\">1.4&nbsp;&nbsp;</span>Cython version</a></div>"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "# Profiling in a Jupyter notebook\n",
    "\n",
    "Small experiment to see how to easily profile some pure [Python](https://www.python.org) and [Cython-enhanced Python code](http://cython.org), for both time and memory, directly within [the Jupyter notebook](http://www.jupyter.org).\n",
    "\n",
    "----\n",
    "## References\n",
    "- https://www.dataquest.io/blog/jupyter-notebook-tips-tricks-shortcuts/\n",
    "- http://pynash.org/2013/03/06/timing-and-profiling/\n",
    "- Example of profiling an using Cython, from the [profiling Cython code tutorial](http://docs.cython.org/en/latest/src/tutorial/profiling_tutorial.html#profiling-tutorial)"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 1,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "CPython 3.5.3\n",
      "IPython 6.0.0\n",
      "\n",
      "compiler   : GCC 6.3.0 20170118\n",
      "system     : Linux\n",
      "release    : 4.10.0-21-generic\n",
      "machine    : x86_64\n",
      "processor  : x86_64\n",
      "CPU cores  : 4\n",
      "interpreter: 64bit\n",
      "Git hash   : 0f7c8d70a89e5bc90866eb42b38a01b76665debd\n"
     ]
    }
   ],
   "source": [
    "%load_ext watermark\n",
    "%watermark -v -m -g"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "----\n",
    "## Basic Python code"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 94,
   "metadata": {
    "collapsed": true
   },
   "outputs": [],
   "source": [
    "def recip_square(i):\n",
    "    return 1./i**2\n",
    "\n",
    "def approx_pi(n=10000000):\n",
    "    val = 0.\n",
    "    for k in range(1,n+1):\n",
    "        val += recip_square(k)\n",
    "    return (6 * val)**.5"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "----\n",
    "## First profiling"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 95,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "CPU times: user 4 s, sys: 0 ns, total: 4 s\n",
      "Wall time: 4.02 s\n"
     ]
    },
    {
     "data": {
      "text/plain": [
       "3.1415925580959025"
      ]
     },
     "execution_count": 95,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "%time approx_pi()"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 96,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "4.26 s ± 45.3 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)\n"
     ]
    }
   ],
   "source": [
    "%timeit approx_pi()"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 97,
   "metadata": {
    "code_folding": [
     0
    ],
    "collapsed": true
   },
   "outputs": [],
   "source": [
    "# Thanks to https://nbviewer.jupyter.org/gist/minrk/7715212\n",
    "from __future__ import print_function\n",
    "from IPython.core import page\n",
    "def myprint(s):\n",
    "    try:\n",
    "        print(s['text/plain'])\n",
    "    except (KeyError, TypeError):\n",
    "        print(s)\n",
    "page.page = myprint\n"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 98,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "         10000004 function calls in 4.972 seconds\n",
      "\n",
      "   Ordered by: internal time\n",
      "\n",
      "   ncalls  tottime  percall  cumtime  percall filename:lineno(function)\n",
      " 10000000    3.280    0.000    3.280    0.000 <ipython-input-94-8fdaa89ffea3>:1(recip_square)\n",
      "        1    1.692    1.692    4.972    4.972 <ipython-input-94-8fdaa89ffea3>:4(approx_pi)\n",
      "        1    0.000    0.000    4.972    4.972 {built-in method builtins.exec}\n",
      "        1    0.000    0.000    4.972    4.972 <string>:1(<module>)\n",
      "        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}\n",
      " "
     ]
    }
   ],
   "source": [
    "%prun approx_pi()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "After installing `line_profiler` and enabling the IPython magic, we can use it"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 99,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "\n",
      "*** Profile printout saved to text file '/tmp/test_lprun.txt'. \n",
      "Timer unit: 1e-06 s\r\n",
      "\r\n",
      "Total time: 5.88048 s\r\n",
      "File: <ipython-input-94-8fdaa89ffea3>\r\n",
      "Function: recip_square at line 1\r\n",
      "\r\n",
      "Line #      Hits         Time  Per Hit   % Time  Line Contents\r\n",
      "==============================================================\r\n",
      "     1                                           def recip_square(i):\r\n",
      "     2  10000000      5880485      0.6    100.0      return 1./i**2\r\n",
      "\r\n",
      "Total time: 20.6013 s\r\n",
      "File: <ipython-input-94-8fdaa89ffea3>\r\n",
      "Function: approx_pi at line 4\r\n",
      "\r\n",
      "Line #      Hits         Time  Per Hit   % Time  Line Contents\r\n",
      "==============================================================\r\n",
      "     4                                           def approx_pi(n=10000000):\r\n",
      "     5         1            2      2.0      0.0      val = 0.\r\n",
      "     6  10000001      3911824      0.4     19.0      for k in range(1,n+1):\r\n",
      "     7  10000000     16689447      1.7     81.0          val += recip_square(k)\r\n",
      "     8         1            4      4.0      0.0      return (6 * val)**.5"
     ]
    }
   ],
   "source": [
    "%lprun -T /tmp/test_lprun.txt -f recip_square -f approx_pi approx_pi()\n",
    "%cat /tmp/test_lprun.txt"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "With the memory profiler:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 100,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "The memory_profiler extension is already loaded. To reload it, use:\n",
      "  %reload_ext memory_profiler\n"
     ]
    }
   ],
   "source": [
    "%load_ext memory_profiler"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 101,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "ERROR: Could not find file <ipython-input-94-8fdaa89ffea3>\n",
      "NOTE: %mprun can only be used on functions defined in physical files, and not in the IPython environment.\n",
      "ERROR: Could not find file <ipython-input-94-8fdaa89ffea3>\n",
      "NOTE: %mprun can only be used on functions defined in physical files, and not in the IPython environment.\n",
      "\n",
      "\n",
      "\n",
      "*** Profile printout saved to text file /tmp/test_mprun.txt. \n"
     ]
    }
   ],
   "source": [
    "%mprun -T /tmp/test_mprun.txt -f recip_square -f approx_pi approx_pi()\n",
    "%cat /tmp/test_mprun.txt"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 102,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "peak memory: 77.60 MiB, increment: 0.00 MiB\n"
     ]
    }
   ],
   "source": [
    "%memit approx_pi()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "----\n",
    "## Cython version"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 103,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "The cython extension is already loaded. To reload it, use:\n",
      "  %reload_ext cython\n"
     ]
    }
   ],
   "source": [
    "%load_ext cython"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 104,
   "metadata": {},
   "outputs": [],
   "source": [
    "%%cython -3\n",
    "# cython: profile=True\n",
    "\n",
    "def recip_square2(int i):\n",
    "    return 1./i**2\n",
    "\n",
    "def approx_pi2(int n=10000000):\n",
    "    cdef double val = 0.\n",
    "    cdef int k\n",
    "    for k in range(1, n + 1):\n",
    "        val += recip_square2(k)\n",
    "    return (6 * val)**.5"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 105,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "3.94 s ± 63.1 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)\n",
      "610 ms ± 3.03 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)\n"
     ]
    }
   ],
   "source": [
    "%timeit approx_pi()\n",
    "%timeit approx_pi2()"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 106,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "         10000005 function calls in 2.143 seconds\n",
      "\n",
      "   Ordered by: internal time\n",
      "\n",
      "   ncalls  tottime  percall  cumtime  percall filename:lineno(function)\n",
      "        1    1.658    1.658    2.143    2.143 _cython_magic_354fd18f414700095ab07463dec470f5.pyx:6(approx_pi2)\n",
      " 10000000    0.485    0.000    0.485    0.000 _cython_magic_354fd18f414700095ab07463dec470f5.pyx:3(recip_square2)\n",
      "        1    0.000    0.000    2.143    2.143 <string>:1(<module>)\n",
      "        1    0.000    0.000    2.143    2.143 {built-in method builtins.exec}\n",
      "        1    0.000    0.000    2.143    2.143 {_cython_magic_354fd18f414700095ab07463dec470f5.approx_pi2}\n",
      "        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}\n",
      " "
     ]
    }
   ],
   "source": [
    "%prun approx_pi2()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "And with just a simple change, by typing the intermediate function:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 107,
   "metadata": {
    "collapsed": true
   },
   "outputs": [],
   "source": [
    "%%cython -3\n",
    "# cython: profile=True\n",
    "\n",
    "cdef double recip_square3(int i):\n",
    "    return 1./(i**2)\n",
    "\n",
    "def approx_pi3(int n=10000000):\n",
    "    cdef double val = 0.\n",
    "    cdef int k\n",
    "    for k in range(1, n + 1):\n",
    "        val += recip_square3(k)\n",
    "    return (6 * val)**.5"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 108,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "31.5 ms ± 890 µs per loop (mean ± std. dev. of 7 runs, 10 loops each)\n"
     ]
    }
   ],
   "source": [
    "%timeit approx_pi3()"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 109,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "         10000005 function calls in 1.451 seconds\n",
      "\n",
      "   Ordered by: internal time\n",
      "\n",
      "   ncalls  tottime  percall  cumtime  percall filename:lineno(function)\n",
      "        1    0.953    0.953    1.451    1.451 _cython_magic_e59e914dbc65ad39e8eabcce1f3dd74a.pyx:6(approx_pi3)\n",
      " 10000000    0.497    0.000    0.497    0.000 _cython_magic_e59e914dbc65ad39e8eabcce1f3dd74a.pyx:3(recip_square3)\n",
      "        1    0.000    0.000    1.451    1.451 <string>:1(<module>)\n",
      "        1    0.000    0.000    1.451    1.451 {built-in method builtins.exec}\n",
      "        1    0.000    0.000    1.451    1.451 {_cython_magic_e59e914dbc65ad39e8eabcce1f3dd74a.approx_pi3}\n",
      "        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}\n",
      " "
     ]
    }
   ],
   "source": [
    "%prun approx_pi3()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "And with an inlined function?"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 110,
   "metadata": {},
   "outputs": [],
   "source": [
    "%%cython -3\n",
    "\n",
    "cdef inline double recip_square4(int i):\n",
    "    return 1./(i**2)\n",
    "\n",
    "def approx_pi4(int n=10000000):\n",
    "    cdef double val = 0.\n",
    "    cdef int k\n",
    "    for k in range(1, n + 1):\n",
    "        val += recip_square4(k)\n",
    "    return (6 * val)**.5"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 111,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "13.7 ms ± 187 µs per loop (mean ± std. dev. of 7 runs, 100 loops each)\n"
     ]
    }
   ],
   "source": [
    "%timeit approx_pi4()"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 112,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "         4 function calls in 0.015 seconds\n",
      "\n",
      "   Ordered by: internal time\n",
      "\n",
      "   ncalls  tottime  percall  cumtime  percall filename:lineno(function)\n",
      "        1    0.014    0.014    0.014    0.014 {_cython_magic_9d338490eeecee00b47e73b849343da2.approx_pi4}\n",
      "        1    0.000    0.000    0.014    0.014 <string>:1(<module>)\n",
      "        1    0.000    0.000    0.014    0.014 {built-in method builtins.exec}\n",
      "        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}\n",
      " "
     ]
    }
   ],
   "source": [
    "%prun approx_pi4()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "And with just a simple change, by using `i*i` instead of `i**2`:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 113,
   "metadata": {},
   "outputs": [],
   "source": [
    "%%cython -3\n",
    "# cython: profile=True\n",
    "from __future__ import division\n",
    "import cython\n",
    "\n",
    "@cython.profile(False)\n",
    "cdef inline double recip_square5(int i):\n",
    "    return 1./(i*i)\n",
    "\n",
    "def approx_pi5(int n=10000000):\n",
    "    cdef double val = 0.\n",
    "    cdef int k\n",
    "    for k in range(1, n + 1):\n",
    "        val += recip_square5(k)\n",
    "    return (6 * val)**.5"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 114,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "13.9 ms ± 237 µs per loop (mean ± std. dev. of 7 runs, 100 loops each)\n"
     ]
    }
   ],
   "source": [
    "%timeit approx_pi4()"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 115,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "         4 function calls in 0.014 seconds\n",
      "\n",
      "   Ordered by: internal time\n",
      "\n",
      "   ncalls  tottime  percall  cumtime  percall filename:lineno(function)\n",
      "        1    0.014    0.014    0.014    0.014 {_cython_magic_9d338490eeecee00b47e73b849343da2.approx_pi4}\n",
      "        1    0.000    0.000    0.014    0.014 <string>:1(<module>)\n",
      "        1    0.000    0.000    0.014    0.014 {built-in method builtins.exec}\n",
      "        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}\n",
      " "
     ]
    }
   ],
   "source": [
    "%prun approx_pi4()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "That's it for today."
   ]
  }
 ],
 "metadata": {
  "kernelspec": {
   "display_name": "Python 3",
   "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.5.3"
  },
  "notify_time": "10",
  "toc": {
   "colors": {
    "hover_highlight": "#DAA520",
    "running_highlight": "#FF0000",
    "selected_highlight": "#FFD700"
   },
   "moveMenuLeft": true,
   "nav_menu": {
    "height": "97px",
    "width": "251px"
   },
   "navigate_menu": true,
   "number_sections": true,
   "sideBar": true,
   "threshold": 4,
   "toc_cell": true,
   "toc_section_display": "block",
   "toc_window_display": true
  }
 },
 "nbformat": 4,
 "nbformat_minor": 2
}