Felsökning och profilering

En gyllene regel inom programmering är att kod inte gör det du förväntar dig att den ska göra, utan det du säger åt den att göra. Att överbrygga den luckan kan ibland vara ganska svårt. I den här föreläsningen går vi igenom användbara tekniker för att hantera felaktig och resurshungrig kod: felsökning och profilering.

Felsökning (debugging)

Printf-felsökning och loggning

“The most effective debugging tool is still careful thought, coupled with judiciously placed print statements” — Brian Kernighan, Unix for Beginners.

Ett första sätt att felsöka ett program är att lägga till utskriftssatser kring där du upptäckt problemet, och fortsätta iterera tills du extraherat tillräcklig information för att förstå vad som orsakar felet.

Ett andra sätt är att använda loggning i ditt program i stället för ad hoc-utskriftssatser. Loggning är bättre än vanliga utskriftssatser av flera skäl:

Här finns ett exempelprogram som loggar meddelanden:

$ python logger.py
# Rå utdata som med vanliga utskriftssatser
$ python logger.py log
# Loggformaterad utdata
$ python logger.py log ERROR
# Skriv bara ut ERROR-nivå och högre
$ python logger.py color
# Färgformaterad utdata

Ett av mina favorittips för mer läsbara loggar är att färgkoda dem. Vid det här laget har du troligen märkt att terminalen använder färger för att göra saker mer läsbara. Men hur gör den det? Program som ls eller grep använder ANSI-escapekoder, som är särskilda teckensekvenser för att tala om för skalet att ändra färg på utdata. Till exempel skriver echo -e "\e[38;2;255;0;0mDet här är rött\e[0m" ut meddelandet Det här är rött i rött i terminalen, så länge terminalen stödjer äkta färg (true color). Om din terminal inte stödjer det (t.ex. macOS Terminal.app) kan du använda mer universellt stödda escapekoder för 16 färger, till exempel echo -e "\e[31;1mDet här är rött\e[0m".

Skriptet nedan visar hur man skriver ut många RGB-färger i terminalen (igen, så länge äkta färg stöds).

#!/usr/bin/env bash
for R in $(seq 0 20 255); do
    for G in $(seq 0 20 255); do
        for B in $(seq 0 20 255); do
            printf "\e[38;2;${R};${G};${B}m█\e[0m";
        done
    done
done

Tredjepartsloggar

När du börjar bygga större programvarusystem stöter du sannolikt på beroenden som kör som separata program. Webbservrar, databaser och meddelandebrokers är vanliga exempel på sådana beroenden. När du interagerar med dessa system behöver du ofta läsa deras loggar, eftersom felmeddelanden på klientsidan inte alltid räcker.

Som tur är skriver de flesta program sina egna loggar någonstans i systemet. I UNIX-system är det vanligt att program skriver loggar under /var/log. Till exempel placerar webbservern NGINX sina loggar under /var/log/nginx. På senare tid har system också börjat använda en systemlogg, som i allt högre grad är platsen där alla loggmeddelanden hamnar. De flesta (men inte alla) Linux-system använder systemd, en systemdaemon som styr många delar av systemet, som vilka tjänster som är aktiverade och körs. systemd lägger loggar under /var/log/journal i ett specialformat, och du kan använda kommandot journalctl för att visa meddelandena. På macOS finns fortfarande /var/log/system.log, men fler och fler verktyg använder systemloggen som kan visas med log show. På de flesta UNIX-system kan du också använda dmesg för att komma åt kärnloggen.

För att skriva till systemloggar kan du använda skalprogrammet logger. Här är ett exempel på att använda logger och kontrollera att posten hamnat i systemloggen. Dessutom har de flesta programspråk bindningar för loggning till systemloggen.

logger "Hello Logs"
# På macOS
log show --last 1m | grep Hello
# På Linux
journalctl --since "1m ago" | grep Hello

Som vi såg i föreläsningen om datahantering kan loggar vara väldigt utförliga och kräva viss bearbetning och filtrering för att få fram rätt information. Om du ofta filtrerar i journalctl och log show kan du använda deras flaggor som gör en första filtrering av utdata. Det finns också verktyg som lnav som ger bättre presentation och navigering i loggfiler.

Felsökare

När printf-felsökning inte räcker bör du använda en felsökare. Felsökare är program som låter dig interagera med ett programs körning, och de gör det möjligt att:

Många programmeringsspråk levereras med någon form av felsökare. I Python är detta Python Debugger pdb.

Här är en kort beskrivning av några kommandon som pdb stödjer:

Låt oss gå igenom ett exempel där vi använder pdb för att fixa följande felaktiga Python-kod (se föreläsningsvideon).

def bubble_sort(arr):
    n = len(arr)
    for i in range(n):
        for j in range(n):
            if arr[j] > arr[j+1]:
                arr[j] = arr[j+1]
                arr[j+1] = arr[j]
    return arr

print(bubble_sort([4, 2, 1, 8, 7, 6]))

Notera att eftersom Python är ett tolkat språk kan vi använda pdb-skalet både för att köra kommandon och instruktioner. ipdb är en förbättrad pdb som använder IPython-REPL och ger tab completion, syntax highlighting, bättre tracebacks och bättre introspektion samtidigt som samma gränssnitt som pdb-modulen behålls.

För mer låg-nivåprogrammering vill du sannolikt titta på gdb (och dess livskvalitetsförbättring pwndbg) samt lldb. De är optimerade för felsökning av C-liknande språk men låter dig undersöka i princip vilken process som helst och se dess aktuella maskintillstånd: register, stack, programräknare osv.

Specialiserade verktyg

Även om det du försöker felsöka är en black-box-binär finns verktyg som kan hjälpa. När program behöver utföra åtgärder som bara kärnan kan göra använder de systemanrop. Det finns kommandon som låter dig spåra vilka systemanrop programmet gör. I Linux finns strace, och i macOS/BSD finns dtrace. dtrace kan vara svårt att använda eftersom det använder sitt eget språk, D, men det finns en wrapper som heter dtruss och ger ett gränssnitt mer likt strace (mer detaljer här).

Nedan följer exempel på hur strace eller dtruss används för att visa spårning av systemanropet stat vid körning av ls. För en djupare genomgång av strace är den här artikeln och det här zinet bra läsning.

# På Linux
sudo strace -e lstat ls -l > /dev/null
# På macOS
sudo dtruss -t lstat64_extended ls -l > /dev/null

I vissa situationer kan du behöva titta på nätverkspaket för att förstå felet i programmet. Verktyg som tcpdump och Wireshark är paketanalysverktyg som låter dig läsa innehållet i nätverkspaket och filtrera dem med olika kriterier.

För webbutveckling är utvecklarverktygen i Chrome/Firefox mycket praktiska. De har ett stort antal verktyg, inklusive:

Statisk analys

För vissa problem behöver du inte köra någon kod alls. Till exempel kan du, bara genom att noggrant läsa kod, upptäcka att loopvariabeln skuggar ett redan existerande variabel- eller funktionsnamn, eller att ett program läser en variabel innan den definierats. Det är här verktyg för statisk analys kommer in. Program för statisk analys tar källkod som indata och analyserar den med kodregler för att resonera om korrekthet.

I följande Python-exempel finns flera misstag. Först skuggar loopvariabeln foo den tidigare definitionen av funktionen foo. Vi skrev också baz i stället för bar på sista raden, så programmet kraschar efter sleep-anropet (som tar en minut).

import time

def foo():
    return 42

for foo in range(5):
    print(foo)
bar = 1
bar *= 0.2
time.sleep(60)
print(baz)

Verktyg för statisk analys kan identifiera den här typen av problem. När vi kör pyflakes på koden får vi fel kopplade till båda programfelen. mypy är ett annat verktyg som kan upptäcka typkontrollproblem. Här varnar mypy för att bar först är en int och sedan castas till float. Notera igen att alla dessa problem upptäcktes utan att köra koden.

$ pyflakes foobar.py
foobar.py:6: redefinition of unused 'foo' from line 3
foobar.py:11: undefined name 'baz'

$ mypy foobar.py
foobar.py:6: error: Incompatible types in assignment (expression has type "int", variable has type "Callable[[], Any]")
foobar.py:9: error: Incompatible types in assignment (expression has type "float", variable has type "int")
foobar.py:11: error: Name 'baz' is not defined
Found 3 errors in 1 file (checked 1 source file)

I föreläsningen om skalverktyg tog vi upp shellcheck, som är ett liknande verktyg för skalskript.

De flesta redigerare och IDE:er kan visa utdata från dessa verktyg direkt i redigeraren och markera varningar och fel. Detta kallas ofta lintning och kan också användas för andra typer av problem, som stilavvikelser eller osäkra konstruktioner.

I Vim kan insticksmodulerna ale eller syntastic ge den funktionen. För Python är pylint och pep8 exempel på stil-linters, och bandit är ett verktyg för att hitta vanliga säkerhetsproblem. För andra språk har människor sammanställt omfattande listor över användbara verktyg för statisk analys, till exempel Awesome Static Analysis (du kan titta på avsnittet Writing), och för linters finns Awesome Linters.

Ett komplement till stil-lintning är kodformatterare, som black för Python, gofmt för Go, rustfmt för Rust eller prettier för JavaScript, HTML och CSS. Dessa verktyg autoformaterar koden så att den följer vanliga stilkonventioner för det aktuella språket. Även om du kanske inte vill ge upp stilkontroll över koden hjälper standardiserat format andra att läsa din kod och gör dig bättre på att läsa andras (stilmässigt standardiserade) kod.

Profilering

Även om koden fungerar som väntat kanske det inte räcker om den samtidigt slukar all CPU eller allt minne. Algoritmkurser lär ofta ut big O-notation men inte hur man hittar flaskhalsar i program. Eftersom premature optimization is the root of all evil bör du lära dig både profileringsverktyg och övervakningsverktyg. De hjälper dig att förstå vilka delar av programmet som tar mest tid och resurser, så att du kan fokusera optimering där den spelar roll.

Timing

Precis som i felsökningsfallet räcker det i många scenarier att bara skriva ut tiden som koden tog mellan två punkter. Här är ett exempel i Python med modulen time.

import time, random
n = random.randint(1, 10) * 100

# Hämta aktuell tid
start = time.time()

# Gör lite arbete
print("Sleeping for {} ms".format(n))
time.sleep(n/1000)

# Beräkna tid mellan start och nu
print(time.time() - start)

# Exempelutdata
# Sleeping for 500 ms
# 0.5713930130004883

Väggklocktid kan dock vara missvisande eftersom datorn kan köra andra processer samtidigt eller vänta på händelser. Det är vanligt att verktyg skiljer på Real, User och Sys tid. Generellt visar User + Sys hur mycket tid processen faktiskt spenderade på CPU:n (mer förklaring här).

Prova till exempel att köra ett kommando som gör en HTTP-förfrågan och prefixa det med time. Med långsam anslutning kan du få utdata som nedan. Här tog förfrågan över 2 sekunder, men processen tog bara 15 ms användartid och 12 ms kärntid på CPU.

$ time curl https://missing.csail.mit.edu &> /dev/null
real    0m2.561s
user    0m0.015s
sys     0m0.012s

Profilerare

CPU

Oftast när folk säger profilerare menar de egentligen CPU-profilerare, som är vanligast. Det finns två huvudtyper av CPU-profilerare: spårning och sampling. Spårningsprofilerare behåller en logg över varje funktionsanrop programmet gör, medan samplingsprofilerare provar programmet periodiskt (vanligen varje millisekund) och spelar in programmets stack. De använder dessa data för att presentera aggregerad statistik över vad programmet lagt mest tid på. Här finns en bra introduktion om du vill ha mer detaljer.

De flesta programmeringsspråk har någon kommandoradsprofilerare du kan använda för att analysera kod. De integreras ofta med fullfjädrade IDE:er, men i den här föreläsningen fokuserar vi på kommandoradsverktygen.

I Python kan vi använda modulen cProfile för att profilera tid per funktionsanrop. Här är ett enkelt exempel som implementerar en rudimentär grep i Python:

#!/usr/bin/env python

import sys, re

def grep(pattern, file):
    with open(file, 'r') as f:
        print(file)
        for i, line in enumerate(f.readlines()):
            pattern = re.compile(pattern)
            match = pattern.search(line)
            if match is not None:
                print("{}: {}".format(i, line), end="")

if __name__ == '__main__':
    times = int(sys.argv[1])
    pattern = sys.argv[2]
    for i in range(times):
        for file in sys.argv[3:]:
            grep(pattern, file)

Vi kan profilera den här koden med kommandot nedan. Om vi analyserar utdata ser vi att I/O tar mest tid och att kompilering av regex också tar en del tid. Eftersom regex bara behöver kompileras en gång kan vi flytta ut det ur loopen.

$ python -m cProfile -s tottime grep.py 1000 '^(import|\s*def)[^,]*$' *.py

[omitted program output]

 ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     8000    0.266    0.000    0.292    0.000 {built-in method io.open}
     8000    0.153    0.000    0.894    0.000 grep.py:5(grep)
    17000    0.101    0.000    0.101    0.000 {built-in method builtins.print}
     8000    0.100    0.000    0.129    0.000 {method 'readlines' of '_io._IOBase' objects}
    93000    0.097    0.000    0.111    0.000 re.py:286(_compile)
    93000    0.069    0.000    0.069    0.000 {method 'search' of '_sre.SRE_Pattern' objects}
    93000    0.030    0.000    0.141    0.000 re.py:231(compile)
    17000    0.019    0.000    0.029    0.000 codecs.py:318(decode)
        1    0.017    0.017    0.911    0.911 grep.py:3(<module>)

[omitted lines]

En invändning mot Pythons cProfile (och många profilerare) är att de visar tid per funktionsanrop. Det kan snabbt bli ointuitivt, särskilt när du använder tredjepartsbibliotek eftersom interna anrop också räknas. Ett mer intuitivt sätt att visa profileringsdata är tid per kodrad, vilket är vad radprofilerare (line profilers) gör.

Till exempel gör följande Python-kod en förfrågan till kurswebbplatsen och parsar svaret för att hämta alla URL:er på sidan:

#!/usr/bin/env python
import requests
from bs4 import BeautifulSoup

# Detta är en dekorator som talar om för line_profiler
# att vi vill analysera den här funktionen
@profile
def get_urls():
    response = requests.get('https://missing.csail.mit.edu')
    s = BeautifulSoup(response.content, 'lxml')
    urls = []
    for url in s.find_all('a'):
        urls.append(url['href'])

if __name__ == '__main__':
    get_urls()

Om vi använder Pythons cProfile får vi över 2500 rader utdata, och även med sortering är det svårt att se var tiden går. En snabb körning med line_profiler visar i stället tidsåtgång per rad:

$ kernprof -l -v a.py
Wrote profile results to urls.py.lprof
Timer unit: 1e-06 s

Total time: 0.636188 s
File: a.py
Function: get_urls at line 5

Line #  Hits         Time  Per Hit   % Time  Line Contents
==============================================================
 5                                           @profile
 6                                           def get_urls():
 7         1     613909.0 613909.0     96.5      response = requests.get('https://missing.csail.mit.edu')
 8         1      21559.0  21559.0      3.4      s = BeautifulSoup(response.content, 'lxml')
 9         1          2.0      2.0      0.0      urls = []
10        25        685.0     27.4      0.1      for url in s.find_all('a'):
11        24         33.0      1.4      0.0          urls.append(url['href'])

Minne

I språk som C eller C++ kan minnesläckor göra att programmet aldrig frigör minne som det inte längre behöver. För att hjälpa vid minnesfelsökning kan du använda verktyg som Valgrind som hjälper dig att hitta minnesläckor.

I språk med garbage collection, som Python, är minnesprofilerare fortfarande användbara, eftersom objekt inte samlas upp så länge du har referenser till dem. Här är ett exempelprogram och dess utdata när det körs med memory-profiler (notera dekoratorn, liksom i line-profiler).

@profile
def my_func():
    a = [1] * (10 ** 6)
    b = [2] * (2 * 10 ** 7)
    del b
    return a

if __name__ == '__main__':
    my_func()

$ python -m memory_profiler example.py
Line #    Mem usage  Increment   Line Contents
==============================================
     3                           @profile
     4      5.97 MB    0.00 MB   def my_func():
     5     13.61 MB    7.64 MB       a = [1] * (10 ** 6)
     6    166.20 MB  152.59 MB       b = [2] * (2 * 10 ** 7)
     7     13.61 MB -152.59 MB       del b
     8     13.61 MB    0.00 MB       return a

Händelseprofilering

Precis som med strace för felsökningsfallet kan du vilja ignorera kodens detaljer och behandla det du kör som en svart låda när du profilerar. Kommandot perf abstraherar bort CPU-skillnader och rapporterar inte tid eller minne direkt, utan systemhändelser relaterade till programmet. Till exempel kan perf enkelt rapportera dålig cachelokalitet, höga nivåer av page faults eller livelocks. Här är en översikt:

Visualisering

Profileringsutdata för verkliga program innehåller ofta stora mängder information på grund av programvaruprojekts inneboende komplexitet. Människor är visuella och ganska dåliga på att läsa stora mängder siffror och förstå dem. Därför finns många verktyg för att visa profileringsutdata på ett lättare sätt.

Ett vanligt sätt att visa CPU-profileringsdata för samplingsprofilerare är flamdiagram (flame graph), som visar en hierarki av funktionsanrop längs Y-axeln och tidsåtgång proportionellt längs X-axeln. De är också interaktiva, så du kan zooma in i specifika delar av programmet och se stackspår (prova att klicka i bilden nedan).

FlameGraph

Anropsgrafer (call graphs) eller kontrollflödesgrafer (control flow graphs) visar relationer mellan underrutiner i ett program genom att representera funktioner som noder och funktionsanrop mellan dem som riktade kanter. När detta kombineras med profileringsdata som antal anrop och tidsåtgång kan anropsgrafer vara väldigt användbara för att tolka programmets flöde. I Python kan du använda biblioteket pycallgraph för att generera dem.

Call Graph

Resursövervakning

Ibland är första steget i prestandaanalys att förstå faktiskt resursutnyttjande. Program kör ofta långsamt när de är resursbegränsade, till exempel om minnet är för litet eller nätverket långsamt. Det finns mängder av kommandoradsverktyg för att undersöka och visa olika systemresurser som CPU-användning, minnesanvändning, nätverk, diskanvändning och så vidare.

Om du vill testa dessa verktyg kan du också skapa artificiell belastning med kommandot stress.

Specialverktyg

Ibland är black-box-benchmarking allt du behöver för att avgöra vilken programvara du ska använda. Verktyg som hyperfine låter dig snabbt benchmarka kommandoradsprogram. I föreläsningen om skalverktyg och skriptning rekommenderade vi till exempel fd framför find. Vi kan använda hyperfine för att jämföra dem i vanliga uppgifter. I exemplet nedan var fd 20x snabbare än find på min maskin.

$ hyperfine --warmup 3 'fd -e jpg' 'find . -iname "*.jpg"'
Benchmark #1: fd -e jpg
  Time (mean ± σ):      51.4 ms ±   2.9 ms    [User: 121.0 ms, System: 160.5 ms]
  Range (min … max):    44.2 ms …  60.1 ms    56 runs

Benchmark #2: find . -iname "*.jpg"
  Time (mean ± σ):      1.126 s ±  0.101 s    [User: 141.1 ms, System: 956.1 ms]
  Range (min … max):    0.975 s …  1.287 s    10 runs

Summary
  'fd -e jpg' ran
   21.89 ± 2.33 times faster than 'find . -iname "*.jpg"'

Precis som i felsökningsfallet kommer webbläsare också med fantastiska verktyg för profilering av sidladdning, så att du kan se var tiden går (laddning, rendering, skriptning osv). Mer information för Firefox och Chrome.

Övningar

Felsökning

  1. Använd journalctl i Linux eller log show i macOS för att hämta superuser-åtkomster och kommandon under senaste dygnet. Om det inte finns några kan du köra några ofarliga kommandon som sudo ls och kontrollera igen.

  2. Gör den här praktiska pdb-handledningen för att bekanta dig med kommandona. För en djupare guide, läs den här.

  3. Installera shellcheck och prova att kontrollera skriptet nedan. Vad är fel i koden? Fixa det. Installera ett linter-tillägg i din redigerare så att varningarna visas automatiskt.

    #!/bin/sh
## Exempel: ett typiskt skript med flera problem
for f in $(ls *.m3u)
do
   grep -qi hq.*mp3 $f \
     && echo -e 'Spellistan $f innehåller en mp3-fil i hög kvalitet'
done

  4. (Avancerad) Läs om omvänd felsökning (reverse debugging) och få ett enkelt exempel att fungera med rr eller RevPDB.

Profilering

  1. Här finns implementationer av några sorteringsalgoritmer. Använd cProfile och line_profiler för att jämföra exekveringstid för insertion sort och quicksort. Vad är flaskhalsen i respektive algoritm? Använd sedan memory_profiler för att kontrollera minnesförbrukningen. Varför är insertion sort bättre? Kolla nu in-place-versionen av quicksort. Utmaning: använd perf för att titta på cykelantal och cacheträffar/missar för varje algoritm.

  2. Här är lite (möjligen omständlig) Python-kod för att beräkna Fibonaccital med en funktion per tal.

    #!/usr/bin/env python
def fib0(): return 0

def fib1(): return 1

s = """def fib{}(): return fib{}() + fib{}()"""

if __name__ == '__main__':

    for n in range(2, 10):
        exec(s.format(n, n-1, n-2))
    # from functools import lru_cache
    # for n in range(10):
    #     exec("fib{} = lru_cache(1)(fib{})".format(n, n))
    print(eval("fib9()"))

    Lägg koden i en fil och gör den körbar. Installera förkrav: pycallgraph och graphviz. (Om du kan köra dot har du redan GraphViz.) Kör koden som den är med pycallgraph graphviz -- ./fib.py och kontrollera filen pycallgraph.png. Hur många gånger anropas fib0? Vi kan göra bättre genom att memoizera funktionerna. Avkommentera de kommenterade raderna och generera bilderna igen. Hur många gånger anropar vi varje fibN-funktion nu?

  3. Ett vanligt problem är att en port du vill lyssna på redan används av en annan process. Låt oss lära oss hitta processens PID. Kör först python -m http.server 4444 för att starta en minimal webbserver som lyssnar på port 4444. Kör i en annan terminal lsof | grep LISTEN för att skriva ut alla lyssnande processer och portar. Hitta processens PID och avsluta den med kill <PID>.

  4. Att begränsa en process resurser kan vara ett annat användbart verktyg i verktygslådan. Prova stress -c 3 och visualisera CPU-förbrukningen med htop. Kör sedan taskset --cpu-list 0,2 stress -c 3 och visualisera igen. Använder stress tre CPU:er? Varför inte? Läs man taskset. Utmaning: uppnå samma sak med cgroups. Prova att begränsa minnesförbrukningen för stress -m.

  5. (Avancerad) Kommandot curl ipinfo.io gör en HTTP-förfrågan och hämtar information om din publika IP. Öppna Wireshark och försök sniffa request- och reply-paketen som curl skickar och tar emot. (Tips: använd filtret http för att bara se HTTP-paket.)

Edit this page.

Licensed under CC BY-NC-SA.