1-Memory-Profilers.ipynb

{
 "cells": [
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "# Introduction to Memory Profiling"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "> Objectives:\n",
    "> * Be introduced to memory profiling using different tools\n",
    "> * Some small introduction to time profiling in IPython too\n"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## ipython_memwatcher"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Our recommended way to profile memory consumption for this tutorial will be [ipython_memwatcher](https://pypi.python.org/pypi/ipython_memwatcher):\n"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 1,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "In [1] used 0.020 MiB RAM in 0.002s, peaked 0.000 MiB above current, total RAM usage 30.293 MiB\n"
     ]
    }
   ],
   "source": [
    "from ipython_memwatcher import MemWatcher\n",
    "mw = MemWatcher()\n",
    "mw.start_watching_memory()"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 2,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "In [2] used 31.203 MiB RAM in 0.066s, peaked 0.000 MiB above current, total RAM usage 61.496 MiB\n"
     ]
    }
   ],
   "source": [
    "# Let's create a big object\n",
    "a = [i for i in range(1000*1000)]"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 3,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "data": {
      "text/plain": [
       "Measurements(memory_delta=31.203125, time_delta=0.06564903259277344, memory_peak=0, memory_usage=61.49609375)"
      ]
     },
     "execution_count": 3,
     "metadata": {},
     "output_type": "execute_result"
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "In [3] used 0.062 MiB RAM in 0.017s, peaked 0.000 MiB above current, total RAM usage 61.559 MiB\n"
     ]
    }
   ],
   "source": [
    "# Get some measurements from the last executed cell:\n",
    "meas = mw.measurements\n",
    "meas"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 4,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "data": {
      "text/plain": [
       "31.203125"
      ]
     },
     "execution_count": 4,
     "metadata": {},
     "output_type": "execute_result"
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "In [4] used 0.012 MiB RAM in 0.003s, peaked 0.000 MiB above current, total RAM usage 61.570 MiB\n"
     ]
    }
   ],
   "source": [
    "# MemWatcher.measurements is a named tuple.  We can easily get info out of it:\n",
    "meas.memory_delta"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 5,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "data": {
      "text/plain": [
       "32.718848"
      ]
     },
     "execution_count": 5,
     "metadata": {},
     "output_type": "execute_result"
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "In [5] used 0.000 MiB RAM in 0.004s, peaked 0.000 MiB above current, total RAM usage 61.570 MiB\n"
     ]
    }
   ],
   "source": [
    "# This takes between 32 ~ 35 bytes per element:\n",
    "meas.memory_delta * (2**20) / 1e6"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 6,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "data": {
      "text/plain": [
       "int"
      ]
     },
     "execution_count": 6,
     "metadata": {},
     "output_type": "execute_result"
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "In [6] used 0.008 MiB RAM in 0.003s, peaked 0.000 MiB above current, total RAM usage 61.578 MiB\n"
     ]
    }
   ],
   "source": [
    "# What are these elements made from?\n",
    "type(a[0])"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 7,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "data": {
      "text/plain": [
       "24"
      ]
     },
     "execution_count": 7,
     "metadata": {},
     "output_type": "execute_result"
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "In [7] used 0.008 MiB RAM in 0.002s, peaked 0.000 MiB above current, total RAM usage 61.586 MiB\n"
     ]
    }
   ],
   "source": [
    "# How much memory take an int?\n",
    "# Beware: the size below will depend on whether you are using a 32-bit or 64-bit Python\n",
    "import sys\n",
    "sys.getsizeof(a[0])"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Ok.  On 64-bits, that means that the int object allocates 8 bytes for the integer value, and 16 bytes for other metadata (Python object).  But 24 is quite less than 32~35.  Where this overhead comes from?\n",
    "\n",
    "Well, it turns out that the list structure needs additional pointers to reference the different components. [Explain with some diagrams]"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## memory_profiler"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "[memory_profiler](https://pypi.python.org/pypi/memory_profiler) is a basic module for memory profiling that many others use (like the `ipython_memwatcher` above) and it interacts well with ipython, so it is worth to see how it works:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 8,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "In [8] used 0.020 MiB RAM in 0.005s, peaked 0.000 MiB above current, total RAM usage 61.605 MiB\n"
     ]
    }
   ],
   "source": [
    "%load_ext memory_profiler"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 9,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "peak memory: 131.30 MiB, increment: 69.69 MiB\n",
      "In [9] used 69.852 MiB RAM in 0.290s, peaked 0.000 MiB above current, total RAM usage 131.457 MiB\n"
     ]
    }
   ],
   "source": [
    "# Use %memit magic command exposed by memory_profiler\n",
    "%memit b = [i for i in range(1000*1000)]"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Please note that the `peak_memory` in this case is different than the `peaked_memory` reported by ipython_memwatcher package."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Guppy"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Guppy is nice for having an overview of how different structures are using our memory:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 10,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "data": {
      "text/plain": [
       "Partition of a set of 2131793 objects. Total size = 82441016 bytes.\n",
       " Index  Count   %     Size   % Cumulative  % Kind (class / dict of class)\n",
       "     0 2002850  94 48068400  58  48068400  58 int\n",
       "     1   1276   0 16451680  20  64520080  78 list\n",
       "     2  59738   3  5226152   6  69746232  85 str\n",
       "     3  31923   1  2736616   3  72482848  88 tuple\n",
       "     4   1799   0  1759016   2  74241864  90 dict (no owner)\n",
       "     5    483   0  1370952   2  75612816  92 dict of module\n",
       "     6   8200   0  1049600   1  76662416  93 types.CodeType\n",
       "     7   8028   0   963360   1  77625776  94 function\n",
       "     8    948   0   854144   1  78479920  95 type\n",
       "     9    948   0   770784   1  79250704  96 dict of type\n",
       "<584 more rows. Type e.g. '_.more' to view.>"
      ]
     },
     "execution_count": 10,
     "metadata": {},
     "output_type": "execute_result"
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "In [10] used 33.320 MiB RAM in 2.868s, peaked 17.500 MiB above current, total RAM usage 164.777 MiB\n"
     ]
    }
   ],
   "source": [
    "from guppy import hpy; hp=hpy()\n",
    "hp.heap()"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 11,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "data": {
      "text/plain": [
       "Partition of a set of 1132069 objects. Total size = 50326800 bytes.\n",
       " Index  Count   %     Size   % Cumulative  % Kind (class / dict of class)\n",
       "     0 1003108  89 24074592  48  24074592  48 int\n",
       "     1   1273   0  8325000  17  32399592  64 list\n",
       "     2  59743   5  5226472  10  37626064  75 str\n",
       "     3  31924   3  2736720   5  40362784  80 tuple\n",
       "     4   1805   0  1762232   4  42125016  84 dict (no owner)\n",
       "     5    483   0  1370952   3  43495968  86 dict of module\n",
       "     6   8200   1  1049600   2  44545568  89 types.CodeType\n",
       "     7   8027   1   963240   2  45508808  90 function\n",
       "     8    948   0   854144   2  46362952  92 type\n",
       "     9    948   0   770784   2  47133736  94 dict of type\n",
       "<580 more rows. Type e.g. '_.more' to view.>"
      ]
     },
     "execution_count": 11,
     "metadata": {},
     "output_type": "execute_result"
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "In [11] used 34.801 MiB RAM in 0.598s, peaked 0.000 MiB above current, total RAM usage 199.578 MiB\n"
     ]
    }
   ],
   "source": [
    "del b\n",
    "hp.heap()"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 12,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "data": {
      "text/plain": [
       "Partition of a set of 1 object. Total size = 8126536 bytes.\n",
       " Index  Count   %     Size   % Cumulative  % Kind (class / dict of class)\n",
       "     0      1 100  8126536 100   8126536 100 list"
      ]
     },
     "execution_count": 12,
     "metadata": {},
     "output_type": "execute_result"
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "In [12] used 0.031 MiB RAM in 0.002s, peaked 0.000 MiB above current, total RAM usage 199.609 MiB\n"
     ]
    }
   ],
   "source": [
    "# Size of the list (beware, this does not include the contents!)\n",
    "hp.iso(a)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "collapsed": true
   },
   "source": [
    "## %time and %timeit"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 13,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "CPU times: user 12 ms, sys: 0 ns, total: 12 ms\n",
      "Wall time: 11.3 ms\n",
      "In [13] used 0.008 MiB RAM in 0.013s, peaked 0.000 MiB above current, total RAM usage 199.617 MiB\n"
     ]
    }
   ],
   "source": [
    "# IPython provides a magic command to see how much time a command takes to run\n",
    "%time asum = sum(a)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Note that `%time` offers quite detailed statistics on the time spent.\n",
    "\n",
    "Also, the time reported by MemoryWatcher has a typical overhead of 1~5 ms over the time reported by %time, so when the times to measure are about this order then it is better to rely on the %time (or %timeit below) values.  "
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 14,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "100 loops, best of 3: 6.18 ms per loop\n",
      "In [14] used 0.016 MiB RAM in 2.578s, peaked 0.000 MiB above current, total RAM usage 199.633 MiB\n"
     ]
    }
   ],
   "source": [
    "# We have another way to measure timings doing several loops and getting the mean\n",
    "%timeit bsum = sum(a)\n",
    "# However, one must notice that %timeit does not return the result of expressions"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Interestingly, %timeit allows to retrieve the measured times in loops with the -o flag:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 15,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "100 loops, best of 3: 6.19 ms per loop\n",
      "[0.6193509101867676, 0.6191778182983398, 0.6193079948425293]\n",
      "0.00619177818298\n",
      "In [15] used 0.020 MiB RAM in 2.558s, peaked 0.000 MiB above current, total RAM usage 199.652 MiB\n"
     ]
    }
   ],
   "source": [
    "t = %timeit -o sum(a)\n",
    "print(t.all_runs)\n",
    "print(t.best)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "And one can specify the number of loops (-n) and the number of repetitions (-r):"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 16,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "1 loops, best of 1: 9.54 ms per loop\n",
      "[0.00953817367553711]\n",
      "0.00953817367554\n",
      "In [16] used 0.000 MiB RAM in 0.012s, peaked 0.000 MiB above current, total RAM usage 199.652 MiB\n"
     ]
    }
   ],
   "source": [
    "t = %timeit -r1 -n1 -o sum(a)\n",
    "print(t.all_runs)\n",
    "print(t.best)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "### Exercise 1\n",
    "\n",
    "Provided a dictionary like:\n",
    "\n",
    "```\n",
    "d = dict((\"key: %i\"%i, i*2) for i in a)\n",
    "```\n",
    "\n",
    "Try to guess how much RAM it uses using the techniques introduced above.\n",
    "\n",
    "Why do you think it takes more space than a list?\n",
    "\n",
    "*Hint*: Every entry in a dictionary has pointers to two objects: key and value. "
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "collapsed": true
   },
   "source": [
    "## Solution"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 17,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "In [17] used 97.230 MiB RAM in 0.681s, peaked 0.000 MiB above current, total RAM usage 296.883 MiB\n"
     ]
    }
   ],
   "source": [
    "d = dict((\"key: %i\"%i, i*2) for i in a)"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 18,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "data": {
      "text/plain": [
       "72"
      ]
     },
     "execution_count": 18,
     "metadata": {},
     "output_type": "execute_result"
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "In [18] used 0.004 MiB RAM in 0.001s, peaked 0.000 MiB above current, total RAM usage 296.887 MiB\n"
     ]
    }
   ],
   "source": [
    "# Compute the size of key + value\n",
    "sys.getsizeof(\"key: 100000\") + sys.getsizeof(1)"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 20,
   "metadata": {
    "collapsed": false
   },
   "outputs": [
    {
     "data": {
      "text/plain": [
       "Partition of a set of 1 object. Total size = 50331928 bytes.\n",
       " Index  Count   %     Size   % Cumulative  % Kind (class / dict of class)\n",
       "     0      1 100 50331928 100  50331928 100 dict (no owner)"
      ]
     },
     "execution_count": 20,
     "metadata": {},
     "output_type": "execute_result"
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "In [20] used 0.004 MiB RAM in 0.527s, peaked 0.000 MiB above current, total RAM usage 296.891 MiB\n"
     ]
    }
   ],
   "source": [
    "# Compute the size of the dict struct (using guppy here)\n",
    "hp.iso(d)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "So, guppy is telling us that just the dictionary structure is taking ~50 MB, whereas the contents alone are taking ~70MB, so we should have expected the dictionary to consume ~120 MB.  However, our `MemWatcher` instance is reporting just ~100 MB.  Take away lesson: measuring memory consumption in Python is tricky but using proper tools we can still get valuable hints!"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {
    "collapsed": true
   },
   "outputs": [],
   "source": []
  }
 ],
 "metadata": {
  "kernelspec": {
   "display_name": "Python 2",
   "language": "python",
   "name": "python2"
  },
  "language_info": {
   "codemirror_mode": {
    "name": "ipython",
    "version": 2
   },
   "file_extension": ".py",
   "mimetype": "text/x-python",
   "name": "python",
   "nbconvert_exporter": "python",
   "pygments_lexer": "ipython2",
   "version": "2.7.10"
  }
 },
 "nbformat": 4,
 "nbformat_minor": 0
}