{ "cells": [ { "cell_type": "markdown", "metadata": {}, "source": [ "# Debugging and Profiling" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "## Debugging" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Um ein Programm von Fehlern zu bereinigen, muss man zuerst abklären um welchen Typ von Fehler es sich handelt:" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "### Syntaxfehler\n", "\n", "Ein Syntaxfehler tritt unmittelbar bei der (versuchten) Auführung des Programmes auf.\n", "Es gibt viele Gründe hierfür und es ist eine genaue Kontrolle der Stelle unmittelbar bevor der Fehler auftritt notwendig.\n", "Beispiele sind falsch balanzierte Klammern, Zeilenumbrüche mit vergessenen oder falschen Einrückungen, vergessene Zeichen wie Doppelpunkte, Beistriche, usw.\n", "Andererseits sind Syntaxfehler die am einfachsten zu korrigierenden Fehler!" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "### Laufzeitfehler\n", "\n", "Bricht ein Programm während der Ausführung ab, so handelt es sich um einen Laufzeitfehler.\n", "Dies sind entweder Ausnahmen (\"[Exceptions](https://docs.python.org/2/library/exceptions.html)\"),\n", "die höchstwahrscheinlich durch vorschalten geeigneter Tests vermeidbar gewesen wären, oder \"Errors\".\n", "Letzteres sind Fehler, die nie auftreten dürfen.\n", "\n", "Beispiele:\n", "* Schreiben auf eine geöffnete Datei, die aber bereits geschlossen ist.\n", "* Entfernen eines Elements aus einer Liste, obwohl die Liste schon leer ist (Test: `len(liste) == 0`).\n", "* usw.\n", "\n", "Es gibt auch Exceptions, die im Programmablauf gewollt auftreten.\n", "Zum Beispiel die [StopIteration-Exception](https://docs.python.org/2/library/exceptions.html#exceptions.StopIteration),\n", "welche beim Ende des Iterierens über einen Iterator ausgeworfen wird." ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "### Logikfehler\n", "\n", "Das sind Fehler im Ablauf des Programmes,\n", "die keinen Fehler auswerfen aber trotzdem zu einem falschen Ergebnis führen.\n", "Dies sind die kompliziertesten Fehler und können die meisten Kopfschmerzen erzeugen.\n", "\n", "Qualitätstests können helfen, sie zu beseitigen.\n", "Es kann auch nützlich sein, mit dem `assert` Statement Invatianten in den Programmfluss einzubauen.\n", "(Eine \"Invariante\" ist eine logische Aussage, die immer wahr sein muss.)\n", "\n", "Beispiel: Wir entfernen möglicherweise ohne vorherigen Test 2x ein Element aus einer Liste.\n", "Damit dies immer funktioniert,\n", "fügen wir ein `assert`-Statement ein,\n", "um sofort einen Fehler zu bekommen falls die Liste nicht ausreichend gefüllt sein sollte.\n", "Damit wird vermieden, nur manchaml mit geringer Wahrscheinlichkeit einen Fehler zu bekommen." ] }, { "cell_type": "code", "execution_count": 1, "metadata": { "collapsed": false }, "outputs": [ { "name": "stdout", "output_type": "stream", "text": [ "3\n" ] } ], "source": [ "from random import random\n", "\n", "ll = [1, 2, 3]\n", "assert len(ll) >= 2\n", "\n", "if random() > .5:\n", " print(ll.pop())\n", " if random() > .9:\n", " print(ll.pop())" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "## Profiling" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Die einfachste Art des Profilings ist, mit %timeit die Ausführungsgeschwindigkeit zu kontrollieren." ] }, { "cell_type": "code", "execution_count": 2, "metadata": { "collapsed": false }, "outputs": [ { "name": "stdout", "output_type": "stream", "text": [ "The slowest run took 30.00 times longer than the fastest. This could mean that an intermediate result is being cached.\n", "10000000 loops, best of 3: 193 ns per loop\n" ] } ], "source": [ "import math\n", "%timeit math.sqrt(2)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Es gibt diverse Pythonmodule für Profiling: Zeilenweise für ein Skript oder für den Speicherverbrauch.\n", "\n", "```\n", "$ pip install [--user] line-profiler\n", "$ pip install [--user] psutil\n", "$ pip install [--user] memory_profiler\n", "```\n", "(In Canopy, ist `--user` nicht notwendig)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Anschließend entweder über die IPython Notebook Konfiguration permanent oder wie folgt manuell diese IPython Magic Funktionen aktivieren." ] }, { "cell_type": "code", "execution_count": 13, "metadata": { "collapsed": false }, "outputs": [], "source": [ "%load_ext memory_profiler" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "## Zeitmessung" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Hierfür speichern wir ein kleines (nicht sinnvolles, aber anschauliches) Programm in als Modul `profile_me.py` ab." ] }, { "cell_type": "code", "execution_count": 14, "metadata": { "collapsed": false }, "outputs": [ { "name": "stdout", "output_type": "stream", "text": [ "Overwriting res/profile_me.py\n" ] } ], "source": [ "%%writefile res/profile_me.py\n", "def profile_me(e):\n", " x = 1\n", " z = [0]\n", " import math\n", " while z[-1] < e:\n", " v = math.sin(x)\n", " for i in range(x):\n", " v2 = v + math.sqrt(i)\n", " z.append(v2)\n", " x += 1\n", " return x" ] }, { "cell_type": "code", "execution_count": 15, "metadata": { "collapsed": false }, "outputs": [], "source": [ "from res.profile_me import profile_me\n", "%lprun -f profile_me profile_me(40)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Man erhält eine detaillierte Auflistung für jede Zeile, wie viel Zeit sie verbrauchte und wie oft sie ausgeführt wurde.\n", "Diese Informationen gehören zu den aussagekräftigsten überhaupt.\n", "Nur auf Basis solcher Analysen kann eine erfolgreiche (und sinnvolle!) Optimierung des Codes stattfinden.\n", "\n", "```\n", "Timer unit: 1e-06 s\n", "\n", "Total time: 1.25865 s\n", "File: res/profile_me.py\n", "Function: profile_me at line 1\n", "\n", "Line # Hits Time Per Hit % Time Line Contents\n", "==============================================================\n", " 1 def profile_me(e):\n", " 2 1 2 2.0 0.0 x = 1\n", " 3 1 1 1.0 0.0 z = [0]\n", " 4 1 6 6.0 0.0 import math\n", " 5 1529 1295 0.8 0.1 while z[-1] < e:\n", " 6 1528 1451 0.9 0.1 v = math.sin(x)\n", " 7 1169684 534961 0.5 42.5 for i in range(x):\n", " 8 1168156 718623 0.6 57.1 v2 = v + math.sqrt(i)\n", " 9 1528 1374 0.9 0.1 z.append(v2)\n", " 10 1528 936 0.6 0.1 x += 1\n", " 11 1 1 1.0 0.0 return x\n", "```" ] }, { "cell_type": "code", "execution_count": 16, "metadata": { "collapsed": false }, "outputs": [ { "name": "stdout", "output_type": "stream", "text": [ " " ] } ], "source": [ "%prun profile_me(40)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "`%prun` sammelt alle Funktionsaufrufe.\n", "\n", "```\n", " 1172743 function calls in 0.344 seconds\n", "\n", " Ordered by: internal time\n", "\n", " ncalls tottime percall cumtime percall filename:lineno(function)\n", " 1 0.229 0.229 0.344 0.344 profile_me.py:1(profile_me)\n", " 1168156 0.106 0.000 0.106 0.000 {math.sqrt}\n", " 1528 0.007 0.000 0.007 0.000 {range}\n", " 1528 0.000 0.000 0.000 0.000 {math.sin}\n", " 1528 0.000 0.000 0.000 0.000 {method 'append' of 'list' objects}\n", " 1 0.000 0.000 0.344 0.344 :1()\n", " 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}\n", "```" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "## Speicherverbrauch\n", "\n", "Speicherverbrauch gehört zu den kompliziertesten Aspekten des Profilings.\n", "Objekte werden dynamisch erzeugt und hierfür dynamisch Speicher angelegt.\n", "Der [Garbage Collector](http://en.wikipedia.org/wiki/Garbage_collection_%28computer_science%29) räumt nicht mehr benötigte Objekte auf.\n", "Spannend ist daher, wieviel Speicherverbrauch während des Ausführens verbraucht wird (Maximalwert) und ob wiederholende Aufrufe den Speicherverbrauch immer weiter erhöhen." ] }, { "cell_type": "code", "execution_count": 17, "metadata": { "collapsed": false }, "outputs": [ { "name": "stdout", "output_type": "stream", "text": [ "peak memory: 70.23 MiB, increment: 0.04 MiB\n" ] } ], "source": [ "%memit -r 3 profile_me(10)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Für %mprun muss das Skript in einer physischen Datei liegen,\n", "wir nehmen das `profile_me.py` von früher." ] }, { "cell_type": "code", "execution_count": 18, "metadata": { "collapsed": false }, "outputs": [ { "name": "stdout", "output_type": "stream", "text": [ "\n" ] } ], "source": [ "from res.profile_me import profile_me\n", "%mprun -f profile_me profile_me(10)" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "```\n", "Filename: res/profile_me.py\n", "\n", "Line # Mem usage Increment Line Contents\n", "================================================\n", " 1 29.8 MiB 0.0 MiB def profile_me(e):\n", " 2 29.8 MiB 0.0 MiB x = 1\n", " 3 29.8 MiB 0.0 MiB z = [0]\n", " 4 29.8 MiB 0.0 MiB import math\n", " 5 29.8 MiB 0.0 MiB while z[-1] < e:\n", " 6 29.8 MiB 0.0 MiB v = math.sin(x)\n", " 7 29.8 MiB 0.0 MiB for i in range(x):\n", " 8 29.8 MiB 0.0 MiB v2 = v + math.sqrt(i)\n", " 9 29.8 MiB 0.0 MiB z.append(v2)\n", " 10 29.8 MiB 0.0 MiB x += 1\n", " 11 29.8 MiB 0.0 MiB return x\n", "```" ] } ], "metadata": { "kernelspec": { "display_name": "Anaconda (Python 3)", "language": "python", "name": "anaconda3" }, "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.5.1" } }, "nbformat": 4, "nbformat_minor": 0 }