{
"cells": [
{
"cell_type": "markdown",
"metadata": {
"toc": "true"
},
"source": [
"# Table of Contents\n",
" "
]
},
{
"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 :1(recip_square)\n",
" 1 1.692 1.692 4.972 4.972 :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 :1()\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: \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: \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 \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 \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 :1()\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 :1()\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 :1()\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 :1()\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
}