Skip to content

Instantly share code, notes, and snippets.

@jiffyclub

jiffyclub/ProfileDemo.ipynb

Created July 6, 2012 19:57
Show Gist options
  • Star 2 You must be signed in to star a gist
  • Fork 1 You must be signed in to fork a gist
  • Save jiffyclub/3062428 to your computer and use it in GitHub Desktop.
Save jiffyclub/3062428 to your computer and use it in GitHub Desktop.
Download ZIP
Examples of timing and profiling Python code using built-in tools and IPython. Requires IPython 0.13+.
Display the source blob
Display the rendered blob
Raw
ProfileDemo.ipynb
{
"metadata": {
"name": "ProfileDemo"
},
"nbformat": 3,
"nbformat_minor": 0,
"worksheets": [
{
"cells": [
{
"cell_type": "markdown",
"metadata": {},
"source": [
"Timing\n",
"======"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"At the command line:"
]
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"!time python slow_functions.py"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"10.7445980559\r\n",
"\r\n",
"real\t0m2.545s\r\n",
"user\t0m2.476s\r\n",
"sys\t0m0.030s\r\n"
]
}
],
"prompt_number": 1
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"import slow_functions"
],
"language": "python",
"metadata": {},
"outputs": [],
"prompt_number": 2
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"With the `time` module:"
]
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"import time"
],
"language": "python",
"metadata": {},
"outputs": [],
"prompt_number": 4
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"t1 = time.time()\n",
"result = slow_functions.main()\n",
"t2 = time.time()\n",
"print 'slow_functions.main took {} seconds'.format(t2 - t1)"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"slow_functions.main took 2.52013397217 seconds"
]
},
{
"output_type": "stream",
"stream": "stdout",
"text": [
"\n"
]
}
],
"prompt_number": 5
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"IPython magic: `%run`"
]
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"%run -t slow_functions.py"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"10.7445980559\n",
"\n",
"IPython CPU timings (estimated):\n",
" User : 2.43 s.\n",
" System : 0.01 s.\n",
"Wall time: 2.44 s.\n"
]
}
],
"prompt_number": 6
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"Ipython magic: `%timeit`"
]
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"%timeit slow_functions.main()"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"1 loops, best of 3: 2.67 s per loop\n"
]
}
],
"prompt_number": 7
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"import numpy as np\n",
"from numpy import interp\n",
"from scipy.interpolate import interp1d"
],
"language": "python",
"metadata": {},
"outputs": [],
"prompt_number": 8
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"x = np.linspace(0, 2*np.pi, 10)\n",
"y = np.sin(x)\n",
"xvals = np.linspace(0, 2*np.pi, 50)"
],
"language": "python",
"metadata": {},
"outputs": [],
"prompt_number": 9
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"#scipy\n",
"f = interp1d(x, y)\n",
"%timeit f(xvals)"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"10000 loops, best of 3: 92.8 us per loop\n"
]
}
],
"prompt_number": 10
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"# numpy\n",
"%timeit interp(xvals, x, y)"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"100000 loops, best of 3: 3.93 us per loop\n"
]
}
],
"prompt_number": 11
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"scipy_vals = f(xvals)\n",
"numpy_vals = interp(xvals, x, y)\n",
"print np.allclose(scipy_vals, numpy_vals)"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"True\n"
]
}
],
"prompt_number": 12
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"Profiling\n",
"========="
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"At the command line:"
]
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"!python -m cProfile slow_functions.py"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"10.7445980559\r\n",
" 2019 function calls in 2.426 seconds\r\n",
"\r\n",
" Ordered by: standard name\r\n",
"\r\n",
" ncalls tottime percall cumtime percall filename:lineno(function)\r\n",
" 1 0.003 0.003 2.426 2.426 slow_functions.py:1(<module>)\r\n",
" 1001 0.780 0.001 0.780 0.001 slow_functions.py:11(func2)\r\n",
" 1001 0.779 0.001 0.779 0.001 slow_functions.py:19(func3)\r\n",
" 1 0.000 0.000 0.781 0.781 slow_functions.py:27(func4)\r\n",
" 11 0.862 0.078 0.862 0.078 slow_functions.py:3(func1)\r\n",
" 1 0.002 0.002 1.560 1.560 slow_functions.py:34(func5)\r\n",
" 1 0.000 0.000 2.423 2.423 slow_functions.py:41(main)\r\n",
" 1 0.000 0.000 0.000 0.000 {math.log10}\r\n",
" 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}\r\n",
"\r\n",
"\r\n"
]
}
],
"prompt_number": 13
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"Viewing with [`pstats`](http://docs.python.org/library/profile.html#module-pstats)"
]
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"!python -m cProfile -o slow_functions.prof slow_functions.py"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"10.7445980559\r\n"
]
}
],
"prompt_number": 14
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"import pstats"
],
"language": "python",
"metadata": {},
"outputs": [],
"prompt_number": 15
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"stats = pstats.Stats('slow_functions.prof')"
],
"language": "python",
"metadata": {},
"outputs": [],
"prompt_number": 16
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"stats.print_stats()"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"Thu Jul 5 12:21:54 2012 slow_functions.prof"
]
},
{
"output_type": "stream",
"stream": "stdout",
"text": [
"\n",
"\n",
" 2019 function calls in 2.360 seconds\n",
"\n",
" Random listing order was used\n",
"\n",
" ncalls tottime percall cumtime percall filename:lineno(function)\n",
" 11 0.837 0.076 0.837 0.076 slow_functions.py:3(func1)\n",
" 1 0.003 0.003 2.360 2.360 slow_functions.py:1(<module>)\n",
" 1 0.002 0.002 1.518 1.518 slow_functions.py:34(func5)\n",
" 1 0.000 0.000 0.761 0.761 slow_functions.py:27(func4)\n",
" 1001 0.757 0.001 0.757 0.001 slow_functions.py:11(func2)\n",
" 1 0.000 0.000 0.000 0.000 {math.log10}\n",
" 1 0.000 0.000 2.357 2.357 slow_functions.py:41(main)\n",
" 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}\n",
" 1001 0.762 0.001 0.762 0.001 slow_functions.py:19(func3)\n",
"\n",
"\n"
]
},
{
"output_type": "pyout",
"prompt_number": 17,
"text": [
"<pstats.Stats instance at 0x104b4b710>"
]
}
],
"prompt_number": 17
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"stats.sort_stats('cum').print_stats()"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"Thu Jul 5 12:21:54 2012 slow_functions.prof\n",
"\n",
" 2019 function calls in 2.360 seconds\n",
"\n",
" Ordered by: cumulative time\n",
"\n",
" ncalls tottime percall cumtime percall filename:lineno(function)\n",
" 1 0.003 0.003 2.360 2.360 slow_functions.py:1(<module>)\n",
" 1 0.000 0.000 2.357 2.357 slow_functions.py:41(main)\n",
" 1 0.002 0.002 1.518 1.518 slow_functions.py:34(func5)\n",
" 11 0.837 0.076 0.837 0.076 slow_functions.py:3(func1)\n",
" 1001 0.762 0.001 0.762 0.001 slow_functions.py:19(func3)\n",
" 1 0.000 0.000 0.761 0.761 slow_functions.py:27(func4)\n",
" 1001 0.757 0.001 0.757 0.001 slow_functions.py:11(func2)\n",
" 1 0.000 0.000 0.000 0.000 {math.log10}\n",
" 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}\n",
"\n",
"\n"
]
},
{
"output_type": "pyout",
"prompt_number": 18,
"text": [
"<pstats.Stats instance at 0x104b4b710>"
]
}
],
"prompt_number": 18
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"stats.sort_stats('time').print_stats()"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"Thu Jul 5 12:21:54 2012 slow_functions.prof\n",
"\n",
" 2019 function calls in 2.360 seconds\n",
"\n",
" Ordered by: internal time\n",
"\n",
" ncalls tottime percall cumtime percall filename:lineno(function)\n",
" 11 0.837 0.076 0.837 0.076 slow_functions.py:3(func1)\n",
" 1001 0.762 0.001 0.762 0.001 slow_functions.py:19(func3)\n",
" 1001 0.757 0.001 0.757 0.001 slow_functions.py:11(func2)\n",
" 1 0.003 0.003 2.360 2.360 slow_functions.py:1(<module>)\n",
" 1 0.002 0.002 1.518 1.518 slow_functions.py:34(func5)\n",
" 1 0.000 0.000 2.357 2.357 slow_functions.py:41(main)\n",
" 1 0.000 0.000 0.761 0.761 slow_functions.py:27(func4)\n",
" 1 0.000 0.000 0.000 0.000 {math.log10}\n",
" 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}\n",
"\n",
"\n"
]
},
{
"output_type": "pyout",
"prompt_number": 19,
"text": [
"<pstats.Stats instance at 0x104b4b710>"
]
}
],
"prompt_number": 19
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"stats.sort_stats('time').print_stats(3)"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"Thu Jul 5 12:21:54 2012 slow_functions.prof\n",
"\n",
" 2019 function calls in 2.360 seconds\n",
"\n",
" Ordered by: internal time\n",
" List reduced from 9 to 3 due to restriction <3>\n",
"\n",
" ncalls tottime percall cumtime percall filename:lineno(function)\n",
" 11 0.837 0.076 0.837 0.076 slow_functions.py:3(func1)\n",
" 1001 0.762 0.001 0.762 0.001 slow_functions.py:19(func3)\n",
" 1001 0.757 0.001 0.757 0.001 slow_functions.py:11(func2)\n",
"\n",
"\n"
]
},
{
"output_type": "pyout",
"prompt_number": 20,
"text": [
"<pstats.Stats instance at 0x104b4b710>"
]
}
],
"prompt_number": 20
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"stats.sort_stats('cum').print_stats(r'func\\d')"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"Thu Jul 5 12:21:54 2012 slow_functions.prof\n",
"\n",
" 2019 function calls in 2.360 seconds\n",
"\n",
" Ordered by: cumulative time\n",
" List reduced from 9 to 5 due to restriction <'func\\\\d'>\n",
"\n",
" ncalls tottime percall cumtime percall filename:lineno(function)\n",
" 1 0.002 0.002 1.518 1.518 slow_functions.py:34(func5)\n",
" 11 0.837 0.076 0.837 0.076 slow_functions.py:3(func1)\n",
" 1001 0.762 0.001 0.762 0.001 slow_functions.py:19(func3)\n",
" 1 0.000 0.000 0.761 0.761 slow_functions.py:27(func4)\n",
" 1001 0.757 0.001 0.757 0.001 slow_functions.py:11(func2)\n",
"\n",
"\n"
]
},
{
"output_type": "pyout",
"prompt_number": 21,
"text": [
"<pstats.Stats instance at 0x104b4b710>"
]
}
],
"prompt_number": 21
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"stats.sort_stats('time').print_stats(r'func\\d', 3)"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"Thu Jul 5 12:21:54 2012 slow_functions.prof\n",
"\n",
" 2019 function calls in 2.360 seconds\n",
"\n",
" Ordered by: internal time\n",
" List reduced from 9 to 5 due to restriction <'func\\\\d'>\n",
" List reduced from 5 to 3 due to restriction <3>\n",
"\n",
" ncalls tottime percall cumtime percall filename:lineno(function)\n",
" 11 0.837 0.076 0.837 0.076 slow_functions.py:3(func1)\n",
" 1001 0.762 0.001 0.762 0.001 slow_functions.py:19(func3)\n",
" 1001 0.757 0.001 0.757 0.001 slow_functions.py:11(func2)\n",
"\n",
"\n"
]
},
{
"output_type": "pyout",
"prompt_number": 22,
"text": [
"<pstats.Stats instance at 0x104b4b710>"
]
}
],
"prompt_number": 22
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"More IPython magic: `%prun`"
]
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"%prun slow_functions.main()"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"\n"
]
}
],
"prompt_number": 23
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"%prun -D slow_functions_main.prof slow_functions.main()"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
" \n",
"*** Profile stats marshalled to file u'slow_functions_main.prof'. \n"
]
}
],
"prompt_number": 24
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"stats = %prun -q -r f(xvals)"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"\n"
]
}
],
"prompt_number": 25
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"# work around a bug in IPython\n",
"import sys\n",
"stats.stream = sys.stdout "
],
"language": "python",
"metadata": {},
"outputs": [],
"prompt_number": 26
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"stats.sort_stats('time').print_stats(10)"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
" 17 function calls in 0.001 seconds\n",
"\n",
" Ordered by: internal time\n",
" List reduced from 15 to 10 due to restriction <10>\n",
"\n",
" ncalls tottime percall cumtime percall filename:lineno(function)\n",
" 1 0.000 0.000 0.000 0.000 interpolate.py:286(_call_linear)\n",
" 1 0.000 0.000 0.001 0.001 interpolate.py:338(__call__)\n",
" 1 0.000 0.000 0.000 0.000 interpolate.py:391(_check_bounds)\n",
" 1 0.000 0.000 0.000 0.000 fromnumeric.py:756(searchsorted)\n",
" 2 0.000 0.000 0.000 0.000 {method 'any' of 'numpy.ndarray' objects}\n",
" 1 0.000 0.000 0.001 0.001 <string>:1(<module>)\n",
" 1 0.000 0.000 0.000 0.000 {method 'clip' of 'numpy.ndarray' objects}\n",
" 1 0.000 0.000 0.000 0.000 {method 'searchsorted' of 'numpy.ndarray' objects}\n",
" 1 0.000 0.000 0.000 0.000 numeric.py:216(asarray)\n",
" 1 0.000 0.000 0.000 0.000 {method 'astype' of 'numpy.ndarray' objects}\n",
"\n",
"\n"
]
},
{
"output_type": "pyout",
"prompt_number": 27,
"text": [
"<pstats.Stats instance at 0x104b50f80>"
]
}
],
"prompt_number": 27
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"%%prun\n",
"f(xvals)\n",
"interp(xvals, x, y)"
],
"language": "python",
"metadata": {},
"outputs": []
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"[`line_profiler`](http://packages.python.org/line_profiler/) with IPython magic"
]
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"%load_ext line_profiler"
],
"language": "python",
"metadata": {},
"outputs": [],
"prompt_number": 28
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"%lprun -f slow_functions.main slow_functions.main()"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"\n"
]
}
],
"prompt_number": 29
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"%lprun -f slow_functions.func5 slow_functions.main()"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"\n"
]
}
],
"prompt_number": 30
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"%lprun -f f.__call__ f(xvals)"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
"\n"
]
}
],
"prompt_number": 31
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"[RunSnakeRun](http://www.vrplumber.com/programming/runsnakerun/)"
]
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"%prun -q -D scipy_interp.prof f(xvals)"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
" \n",
"*** Profile stats marshalled to file u'scipy_interp.prof'. \n"
]
}
],
"prompt_number": 32
},
{
"cell_type": "code",
"collapsed": false,
"input": [
"%prun -q -D numpy_interp.prof interp(xvals, x, y)"
],
"language": "python",
"metadata": {},
"outputs": [
{
"output_type": "stream",
"stream": "stdout",
"text": [
" \n",
"*** Profile stats marshalled to file u'numpy_interp.prof'. \n"
]
}
],
"prompt_number": 33
},
{
"cell_type": "code",
"collapsed": false,
"input": [],
"language": "python",
"metadata": {},
"outputs": []
}
],
"metadata": {}
}
]
}
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment