At the command line:
!time python slow_functions.py
10.7445980559 real 0m2.545s user 0m2.476s sys 0m0.030s
import slow_functions
With the time
module:
import time
t1 = time.time()
result = slow_functions.main()
t2 = time.time()
print 'slow_functions.main took {} seconds'.format(t2 - t1)
slow_functions.main took 2.52013397217 seconds
IPython magic: %run
%run -t slow_functions.py
10.7445980559 IPython CPU timings (estimated): User : 2.43 s. System : 0.01 s. Wall time: 2.44 s.
Ipython magic: %timeit
%timeit slow_functions.main()
1 loops, best of 3: 2.67 s per loop
import numpy as np
from numpy import interp
from scipy.interpolate import interp1d
x = np.linspace(0, 2*np.pi, 10)
y = np.sin(x)
xvals = np.linspace(0, 2*np.pi, 50)
#scipy
f = interp1d(x, y)
%timeit f(xvals)
10000 loops, best of 3: 92.8 us per loop
# numpy
%timeit interp(xvals, x, y)
100000 loops, best of 3: 3.93 us per loop
scipy_vals = f(xvals)
numpy_vals = interp(xvals, x, y)
print np.allclose(scipy_vals, numpy_vals)
True
At the command line:
!python -m cProfile slow_functions.py
10.7445980559 2019 function calls in 2.426 seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 1 0.003 0.003 2.426 2.426 slow_functions.py:1(<module>) 1001 0.780 0.001 0.780 0.001 slow_functions.py:11(func2) 1001 0.779 0.001 0.779 0.001 slow_functions.py:19(func3) 1 0.000 0.000 0.781 0.781 slow_functions.py:27(func4) 11 0.862 0.078 0.862 0.078 slow_functions.py:3(func1) 1 0.002 0.002 1.560 1.560 slow_functions.py:34(func5) 1 0.000 0.000 2.423 2.423 slow_functions.py:41(main) 1 0.000 0.000 0.000 0.000 {math.log10} 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
Viewing with pstats
!python -m cProfile -o slow_functions.prof slow_functions.py
10.7445980559
import pstats
stats = pstats.Stats('slow_functions.prof')
stats.print_stats()
Thu Jul 5 12:21:54 2012 slow_functions.prof 2019 function calls in 2.360 seconds Random listing order was used ncalls tottime percall cumtime percall filename:lineno(function) 11 0.837 0.076 0.837 0.076 slow_functions.py:3(func1) 1 0.003 0.003 2.360 2.360 slow_functions.py:1(<module>) 1 0.002 0.002 1.518 1.518 slow_functions.py:34(func5) 1 0.000 0.000 0.761 0.761 slow_functions.py:27(func4) 1001 0.757 0.001 0.757 0.001 slow_functions.py:11(func2) 1 0.000 0.000 0.000 0.000 {math.log10} 1 0.000 0.000 2.357 2.357 slow_functions.py:41(main) 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} 1001 0.762 0.001 0.762 0.001 slow_functions.py:19(func3)
<pstats.Stats instance at 0x104b4b710>
stats.sort_stats('cum').print_stats()
Thu Jul 5 12:21:54 2012 slow_functions.prof 2019 function calls in 2.360 seconds Ordered by: cumulative time ncalls tottime percall cumtime percall filename:lineno(function) 1 0.003 0.003 2.360 2.360 slow_functions.py:1(<module>) 1 0.000 0.000 2.357 2.357 slow_functions.py:41(main) 1 0.002 0.002 1.518 1.518 slow_functions.py:34(func5) 11 0.837 0.076 0.837 0.076 slow_functions.py:3(func1) 1001 0.762 0.001 0.762 0.001 slow_functions.py:19(func3) 1 0.000 0.000 0.761 0.761 slow_functions.py:27(func4) 1001 0.757 0.001 0.757 0.001 slow_functions.py:11(func2) 1 0.000 0.000 0.000 0.000 {math.log10} 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
<pstats.Stats instance at 0x104b4b710>
stats.sort_stats('time').print_stats()
Thu Jul 5 12:21:54 2012 slow_functions.prof 2019 function calls in 2.360 seconds Ordered by: internal time ncalls tottime percall cumtime percall filename:lineno(function) 11 0.837 0.076 0.837 0.076 slow_functions.py:3(func1) 1001 0.762 0.001 0.762 0.001 slow_functions.py:19(func3) 1001 0.757 0.001 0.757 0.001 slow_functions.py:11(func2) 1 0.003 0.003 2.360 2.360 slow_functions.py:1(<module>) 1 0.002 0.002 1.518 1.518 slow_functions.py:34(func5) 1 0.000 0.000 2.357 2.357 slow_functions.py:41(main) 1 0.000 0.000 0.761 0.761 slow_functions.py:27(func4) 1 0.000 0.000 0.000 0.000 {math.log10} 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
<pstats.Stats instance at 0x104b4b710>
stats.sort_stats('time').print_stats(3)
Thu Jul 5 12:21:54 2012 slow_functions.prof 2019 function calls in 2.360 seconds Ordered by: internal time List reduced from 9 to 3 due to restriction <3> ncalls tottime percall cumtime percall filename:lineno(function) 11 0.837 0.076 0.837 0.076 slow_functions.py:3(func1) 1001 0.762 0.001 0.762 0.001 slow_functions.py:19(func3) 1001 0.757 0.001 0.757 0.001 slow_functions.py:11(func2)
<pstats.Stats instance at 0x104b4b710>
stats.sort_stats('cum').print_stats(r'func\d')
Thu Jul 5 12:21:54 2012 slow_functions.prof 2019 function calls in 2.360 seconds Ordered by: cumulative time List reduced from 9 to 5 due to restriction <'func\\d'> ncalls tottime percall cumtime percall filename:lineno(function) 1 0.002 0.002 1.518 1.518 slow_functions.py:34(func5) 11 0.837 0.076 0.837 0.076 slow_functions.py:3(func1) 1001 0.762 0.001 0.762 0.001 slow_functions.py:19(func3) 1 0.000 0.000 0.761 0.761 slow_functions.py:27(func4) 1001 0.757 0.001 0.757 0.001 slow_functions.py:11(func2)
<pstats.Stats instance at 0x104b4b710>
stats.sort_stats('time').print_stats(r'func\d', 3)
Thu Jul 5 12:21:54 2012 slow_functions.prof 2019 function calls in 2.360 seconds Ordered by: internal time List reduced from 9 to 5 due to restriction <'func\\d'> List reduced from 5 to 3 due to restriction <3> ncalls tottime percall cumtime percall filename:lineno(function) 11 0.837 0.076 0.837 0.076 slow_functions.py:3(func1) 1001 0.762 0.001 0.762 0.001 slow_functions.py:19(func3) 1001 0.757 0.001 0.757 0.001 slow_functions.py:11(func2)
<pstats.Stats instance at 0x104b4b710>
More IPython magic: %prun
%prun slow_functions.main()
%prun -D slow_functions_main.prof slow_functions.main()
*** Profile stats marshalled to file u'slow_functions_main.prof'.
stats = %prun -q -r f(xvals)
# work around a bug in IPython
import sys
stats.stream = sys.stdout
stats.sort_stats('time').print_stats(10)
17 function calls in 0.001 seconds Ordered by: internal time List reduced from 15 to 10 due to restriction <10> ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 0.000 0.000 interpolate.py:286(_call_linear) 1 0.000 0.000 0.001 0.001 interpolate.py:338(__call__) 1 0.000 0.000 0.000 0.000 interpolate.py:391(_check_bounds) 1 0.000 0.000 0.000 0.000 fromnumeric.py:756(searchsorted) 2 0.000 0.000 0.000 0.000 {method 'any' of 'numpy.ndarray' objects} 1 0.000 0.000 0.001 0.001 <string>:1(<module>) 1 0.000 0.000 0.000 0.000 {method 'clip' of 'numpy.ndarray' objects} 1 0.000 0.000 0.000 0.000 {method 'searchsorted' of 'numpy.ndarray' objects} 1 0.000 0.000 0.000 0.000 numeric.py:216(asarray) 1 0.000 0.000 0.000 0.000 {method 'astype' of 'numpy.ndarray' objects}
<pstats.Stats instance at 0x104b50f80>
%%prun
f(xvals)
interp(xvals, x, y)
line_profiler
with IPython magic
%load_ext line_profiler
%lprun -f slow_functions.main slow_functions.main()
%lprun -f slow_functions.func5 slow_functions.main()
%lprun -f f.__call__ f(xvals)
%prun -q -D scipy_interp.prof f(xvals)
*** Profile stats marshalled to file u'scipy_interp.prof'.
%prun -q -D numpy_interp.prof interp(xvals, x, y)
*** Profile stats marshalled to file u'numpy_interp.prof'.