Skip to content

Instantly share code, notes, and snippets.

@jenshnielsen

jenshnielsen/Logging benchmarking.ipynb

Created November 13, 2017 12:21
Show Gist options
  • Save jenshnielsen/5b07f69ba01954ef852b9db4db98be3b to your computer and use it in GitHub Desktop.
Save jenshnielsen/5b07f69ba01954ef852b9db4db98be3b to your computer and use it in GitHub Desktop.
Download ZIP
Display the source blob
Display the rendered blob
Raw
Logging benchmarking.ipynb
{
"cells": [
{
"cell_type": "code",
"execution_count": 1,
"metadata": {},
"outputs": [],
"source": [
"import logging\n",
"import time\n",
"logger = logging.getLogger(__name__)\n",
"\n",
"logging.basicConfig(level=logging.INFO,\n",
" handlers=[logging.StreamHandler(stream=None)])"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"This notebook explores the performance implications of logging using a stream handler logging to stderr. I have not considdered using alternative handlers or writing to a file."
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"### Basic loop no logging"
]
},
{
"cell_type": "code",
"execution_count": 2,
"metadata": {},
"outputs": [
{
"name": "stdout",
"output_type": "stream",
"text": [
"224 µs ± 2.33 µs per loop (mean ± std. dev. of 7 runs, 1000 loops each)\n"
]
}
],
"source": [
"%%timeit\n",
"for i in range(10000):\n",
" pass"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"### Adding timing to the loop"
]
},
{
"cell_type": "code",
"execution_count": 3,
"metadata": {},
"outputs": [
{
"name": "stdout",
"output_type": "stream",
"text": [
"1.53 ms ± 90.1 µs per loop (mean ± std. dev. of 7 runs, 1000 loops each)\n"
]
}
],
"source": [
"%%timeit\n",
"lasttime = time.perf_counter()\n",
"for i in range(10000):\n",
" currenttime = time.perf_counter()\n",
" lasttime = currenttime"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"### Logging formatting (3.5 style)"
]
},
{
"cell_type": "code",
"execution_count": 4,
"metadata": {},
"outputs": [
{
"name": "stdout",
"output_type": "stream",
"text": [
"21.5 ms ± 2.91 ms per loop (mean ± std. dev. of 7 runs, 10 loops each)\n"
]
}
],
"source": [
"%%timeit\n",
"lasttime = time.perf_counter()\n",
"for i in range(10000):\n",
" currenttime = time.perf_counter()\n",
" lasttime = currenttime\n",
" logger.debug(\"itteration {} took {}\".format(i, currenttime-lasttime))"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"### Logging formatting (3.6 style)"
]
},
{
"cell_type": "code",
"execution_count": 5,
"metadata": {},
"outputs": [
{
"name": "stdout",
"output_type": "stream",
"text": [
"18 ms ± 1.93 ms per loop (mean ± std. dev. of 7 runs, 100 loops each)\n"
]
}
],
"source": [
"%%timeit\n",
"lasttime = time.perf_counter()\n",
"for i in range(10000):\n",
" currenttime = time.perf_counter()\n",
" lasttime = currenttime\n",
" logger.debug(f\"itteration {i} took {currenttime-lasttime}\")"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"### Logging with defered formatting"
]
},
{
"cell_type": "code",
"execution_count": 6,
"metadata": {},
"outputs": [
{
"name": "stdout",
"output_type": "stream",
"text": [
"10.9 ms ± 57.2 µs per loop (mean ± std. dev. of 7 runs, 100 loops each)\n"
]
}
],
"source": [
"%%timeit\n",
"lasttime = time.perf_counter()\n",
"for i in range(10000):\n",
" currenttime = time.perf_counter()\n",
" lasttime = currenttime\n",
" logger.debug(\"itteration %d took %d\", i, currenttime-lasttime)"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"### Logging output to notebook"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"Note that this loop is 100 times shorter"
]
},
{
"cell_type": "code",
"execution_count": 7,
"metadata": {
"scrolled": false
},
"outputs": [
{
"name": "stderr",
"output_type": "stream",
"text": [
"INFO:__main__:itteration 0 took 0.0\n",
"INFO:__main__:itteration 1 took 0.0\n",
"INFO:__main__:itteration 2 took 0.0\n",
"INFO:__main__:itteration 3 took 0.0\n",
"INFO:__main__:itteration 4 took 0.0\n",
"INFO:__main__:itteration 5 took 0.0\n",
"INFO:__main__:itteration 6 took 0.0\n",
"INFO:__main__:itteration 7 took 0.0\n",
"INFO:__main__:itteration 8 took 0.0\n",
"INFO:__main__:itteration 9 took 0.0\n",
"INFO:__main__:itteration 10 took 0.0\n",
"INFO:__main__:itteration 11 took 0.0\n",
"INFO:__main__:itteration 12 took 0.0\n",
"INFO:__main__:itteration 13 took 0.0\n",
"INFO:__main__:itteration 14 took 0.0\n",
"INFO:__main__:itteration 15 took 0.0\n",
"INFO:__main__:itteration 16 took 0.0\n",
"INFO:__main__:itteration 17 took 0.0\n",
"INFO:__main__:itteration 18 took 0.0\n",
"INFO:__main__:itteration 19 took 0.0\n",
"INFO:__main__:itteration 20 took 0.0\n",
"INFO:__main__:itteration 21 took 0.0\n",
"INFO:__main__:itteration 22 took 0.0\n",
"INFO:__main__:itteration 23 took 0.0\n",
"INFO:__main__:itteration 24 took 0.0\n",
"INFO:__main__:itteration 25 took 0.0\n",
"INFO:__main__:itteration 26 took 0.0\n",
"INFO:__main__:itteration 27 took 0.0\n",
"INFO:__main__:itteration 28 took 0.0\n",
"INFO:__main__:itteration 29 took 0.0\n",
"INFO:__main__:itteration 30 took 0.0\n",
"INFO:__main__:itteration 31 took 0.0\n",
"INFO:__main__:itteration 32 took 0.0\n",
"INFO:__main__:itteration 33 took 0.0\n",
"INFO:__main__:itteration 34 took 0.0\n",
"INFO:__main__:itteration 35 took 0.0\n",
"INFO:__main__:itteration 36 took 0.0\n",
"INFO:__main__:itteration 37 took 0.0\n",
"INFO:__main__:itteration 38 took 0.0\n",
"INFO:__main__:itteration 39 took 0.0\n",
"INFO:__main__:itteration 40 took 0.0\n",
"INFO:__main__:itteration 41 took 0.0\n",
"INFO:__main__:itteration 42 took 0.0\n",
"INFO:__main__:itteration 43 took 0.0\n",
"INFO:__main__:itteration 44 took 0.0\n",
"INFO:__main__:itteration 45 took 0.0\n",
"INFO:__main__:itteration 46 took 0.0\n",
"INFO:__main__:itteration 47 took 0.0\n",
"INFO:__main__:itteration 48 took 0.0\n",
"INFO:__main__:itteration 49 took 0.0\n",
"INFO:__main__:itteration 50 took 0.0\n",
"INFO:__main__:itteration 51 took 0.0\n",
"INFO:__main__:itteration 52 took 0.0\n",
"INFO:__main__:itteration 53 took 0.0\n",
"INFO:__main__:itteration 54 took 0.0\n",
"INFO:__main__:itteration 55 took 0.0\n",
"INFO:__main__:itteration 56 took 0.0\n",
"INFO:__main__:itteration 57 took 0.0\n",
"INFO:__main__:itteration 58 took 0.0\n",
"INFO:__main__:itteration 59 took 0.0\n",
"INFO:__main__:itteration 60 took 0.0\n",
"INFO:__main__:itteration 61 took 0.0\n",
"INFO:__main__:itteration 62 took 0.0\n",
"INFO:__main__:itteration 63 took 0.0\n",
"INFO:__main__:itteration 64 took 0.0\n",
"INFO:__main__:itteration 65 took 0.0\n",
"INFO:__main__:itteration 66 took 0.0\n",
"INFO:__main__:itteration 67 took 0.0\n",
"INFO:__main__:itteration 68 took 0.0\n",
"INFO:__main__:itteration 69 took 0.0\n",
"INFO:__main__:itteration 70 took 0.0\n",
"INFO:__main__:itteration 71 took 0.0\n",
"INFO:__main__:itteration 72 took 0.0\n",
"INFO:__main__:itteration 73 took 0.0\n",
"INFO:__main__:itteration 74 took 0.0\n",
"INFO:__main__:itteration 75 took 0.0\n",
"INFO:__main__:itteration 76 took 0.0\n",
"INFO:__main__:itteration 77 took 0.0\n",
"INFO:__main__:itteration 78 took 0.0\n",
"INFO:__main__:itteration 79 took 0.0\n",
"INFO:__main__:itteration 80 took 0.0\n",
"INFO:__main__:itteration 81 took 0.0\n",
"INFO:__main__:itteration 82 took 0.0\n",
"INFO:__main__:itteration 83 took 0.0\n",
"INFO:__main__:itteration 84 took 0.0\n",
"INFO:__main__:itteration 85 took 0.0\n",
"INFO:__main__:itteration 86 took 0.0\n",
"INFO:__main__:itteration 87 took 0.0\n",
"INFO:__main__:itteration 88 took 0.0\n",
"INFO:__main__:itteration 89 took 0.0\n",
"INFO:__main__:itteration 90 took 0.0\n",
"INFO:__main__:itteration 91 took 0.0\n",
"INFO:__main__:itteration 92 took 0.0\n",
"INFO:__main__:itteration 93 took 0.0\n",
"INFO:__main__:itteration 94 took 0.0\n",
"INFO:__main__:itteration 95 took 0.0\n",
"INFO:__main__:itteration 96 took 0.0\n",
"INFO:__main__:itteration 97 took 0.0\n",
"INFO:__main__:itteration 98 took 0.0\n",
"INFO:__main__:itteration 99 took 0.0\n"
]
},
{
"name": "stdout",
"output_type": "stream",
"text": [
"CPU times: user 83.5 ms, sys: 24.2 ms, total: 108 ms\n",
"Wall time: 104 ms\n"
]
}
],
"source": [
"%%time\n",
"lasttime = time.perf_counter()\n",
"for i in range(100):\n",
" currenttime = time.perf_counter()\n",
" lasttime = currenttime\n",
" logger.info(\"itteration {} took {}\".format(i, currenttime-lasttime))\n",
" #logger.debug(\"itteration %d took %d\", i, currenttime-lasttime)"
]
}
],
"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.3"
}
},
"nbformat": 4,
"nbformat_minor": 2
}
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment