profiling.ipynb

{
 "cells": [
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "# Profiling tutorial\n",
    "Never try to optimise your code without profiling first."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## 1. Coarse-grained profiling\n",
    "Measuring the performance of an entire program run."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "### /usr/bin/time\n",
    "Great tool for getting an initial feel of program behaviour.\n",
    "- Language independent - can measure anything\n",
    "- Gives some basic data like total time spent, total memory used\n",
    "- Also gives more advanced information like user/system CPU time, page faults, context switches, IO operations.\n",
    "- Good for benchmarking your program: monitoring it's performance when we make changes and making sure it does not get worse.\n",
    "\n",
    "These two examples show the behaviour of an io-intensive vs an computation-intensive program:\n",
    "\n",
    "**MacOS** replace `-v` with `-l`"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "%%bash \n",
    "/usr/bin/time -v curl -s http://example.com > /dev/null"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "%%bash \n",
    "/usr/bin/time -v python -c \"for i in list(range(int(1e6))): n = i\""
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "The -o option will output to a file:\n",
    "\n",
    "/usr/bin/time -v -o myfile.txt {command}"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## 2. Function-level python profiling"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "### Timing a single block of code\n",
    "For a one-off timing you can just time the function at the start and end, or use jupyter."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "import time\n",
    "def myfunc():\n",
    "    start = time.perf_counter()\n",
    "    n = 0\n",
    "    for i in range(int(1e6)):\n",
    "        n = i\n",
    "    print('Time taken: {} secs'.format(time.perf_counter() - start))\n",
    "\n",
    "myfunc()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "You can easily wrap this in a decorator:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "import time\n",
    "def time_func(func):\n",
    "    def wrapper(*args, **kw):\n",
    "        start_time = time.perf_counter()\n",
    "        result = func(*args, **kw)\n",
    "        end_time = time.perf_counter()\n",
    "        print('Func {} took {} secs'.format(func.__name__, (end_time - start_time)))\n",
    "        return result\n",
    "    return wrapper\n",
    "\n",
    "@time_func\n",
    "def myfunc():\n",
    "    n = 0\n",
    "    for i in range(int(1e6)):\n",
    "        n = i\n",
    "\n",
    "myfunc()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "### Using Jupyter %time and %timeit\n",
    "This way we can time code very easily:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "%%time\n",
    "n = 0\n",
    "for i in range(int(1e6)):\n",
    "    n = i"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "%%timeit -n 3 -r 10\n",
    "n = 0\n",
    "for i in range(int(1e6)):\n",
    "    n = i"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "def myfunc():\n",
    "    n = 0\n",
    "    for i in range(int(1e6)):\n",
    "        n = i\n",
    "%timeit -n 3 -r 10 myfunc()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "### Memory profiling a block of code\n",
    "Need to install the `memory_profiler` package: `conda install memory_profiler` or `pip install memory_profiler`"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "%load_ext memory_profiler\n",
    "def myfunc():\n",
    "    n = 0\n",
    "    for i in range(int(1e6)):\n",
    "        n = i\n",
    "%memit myfunc()"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "%%memit\n",
    "n = 0\n",
    "for i in range(int(1e6)):\n",
    "    n = i"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "### Using cProfile to get function call data\n",
    "The cProfile module will tell you how much time is spent on each function in your python program and how many times each was called. cProfile is included in the standard python library so no need to install anything."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "%%bash\n",
    "python -m cProfile -s cumulative walk.py"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "# Or you can call it from within python\n",
    "import cProfile\n",
    "from walk import keep_python_busy\n",
    "cProfile.run('keep_python_busy()', sort='cumulative')"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "These results are not very readable though. Let's output them to a file so we can use some visualisation tools."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 1,
   "metadata": {},
   "outputs": [],
   "source": [
    "import cProfile\n",
    "from walk import keep_python_busy\n",
    "cProfile.run('keep_python_busy()', filename='walk.prof')"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "### Interpreting cProfile results with snakeviz"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "%%bash\n",
    "snakeviz walk.prof"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "### Using PyCharm Pro's profiler\n",
    "The \"profile\" button in Pycharm Pro can make it easy to do profiling-optimising iterations."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "collapsed": true
   },
   "source": [
    "![pycharm profiling button](resources/pycharm_profile_button.png)\n",
    "This will give you a call list and a call graph similar to KCacheGrind (but not interactive):\n",
    "![pycharm profiling graph](resources/pycharm_profile_graph.png)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## 3. Line-level profiling\n",
    "The stuff we've seen so far are great for narrowing down and finding where the bottlnecks are. However, once we have identified which functions are slow we may want to make the function faster and for that we need to know which lines are the slowest."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "### Using line_profiler\n",
    "We need to specify the funtion we want to profile and the root code we want to run - they may not be the same as the function to be profiled may be called from many other functions."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 1,
   "metadata": {},
   "outputs": [],
   "source": [
    "%load_ext line_profiler\n",
    "\n",
    "from walk import primes_in_range\n",
    "\n",
    "%lprun -f primes_in_range primes_in_range(100000)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "### Using memory_profiler\n",
    "Likewise, we may want to find out which lines in our code are incrementing our memory consumption.\n",
    "You may want to restart the kernel before running this as python keeps a cache of objects."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 1,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "\n"
     ]
    }
   ],
   "source": [
    "%load_ext memory_profiler\n",
    "\n",
    "from walk import use_memory\n",
    "\n",
    "%mprun -f use_memory use_memory(str_repeat=100000, str_count=1000)"
   ]
  }
 ],
 "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.6.8"
  }
 },
 "nbformat": 4,
 "nbformat_minor": 2
}