Отладка и Профилирование

Золотое правило программирования заключается в том, что код не делает то, что вы от него ожидаете, а то, что вы ему скажете. Преодолеть это расхождение иногда может быть довольно сложной задачей. В этой лекции мы рассмотрим полезные техники для работы с проблемным и ресурсоемким кодом: отладку и профилирование.

Отладка

отладка с помощью Printf и Logging

“Самым эффективным инструментом отладки по-прежнему остается внимательное размышление в сочетании с умело размещенными операторами вывода” — Брайан Керниган, Unix для начинающих.

Первый подход к отладке программы заключается в добавлении операторов вывода вокруг места, где вы обнаружили проблему, и продолжении итераций до тех пор, пока вы не извлечете достаточно информации для понимания, что является причиной проблемы.

Второй подход заключается в использовании логирования в вашей программе вместо операторов вывода, добавляемых по мере необходимости. Логирование лучше обычных операторов вывода по нескольким причинам:

Здесь пример кода, который логирует сообщение:

$ python logger.py
# Raw output as with just prints
$ python logger.py log
# Log formatted output
$ python logger.py log ERROR
# Print only ERROR levels and above
$ python logger.py color
# Color formatted output

Отличной идеей является сделать логи более читаемыми с помощью вывода их в разном цвете. К настоящему моменту вы, вероятно, заметили, что ваш терминал использует цвета, чтобы сделать текст более читаемым. Но как он это делает? Некоторые программы, например ls или grep используют ANSI escape codes, которые являются специальными последовательностями символов, чтобы показать вашей оболочке, что необходимо изменить цвет вывода. Например, выполнение echo -e "\e[38;2;255;0;0mThis is red\e[0m" напечатает This is red красным цветом в вашем терминале, если он поддерживает true color. Если ваш терминал не поддерживает это (например macOS’s Terminal.app), вы можете использовать более универсально поддерживаемые escape codes для 16 цветов, например: echo -e "\e[31;1mThis is red\e[0m".

Данный скрипт показывает, как напечатать много RGB цветов в ваш терминал (опять же, если терминал поддерживает true color).

#!/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

Third party logs

Когда вы начинаете создавать более крупные программные системы, вы, скорее всего, столкнетесь с зависимостями, которые работают как отдельные программы. Веб-серверы, базы данных или брокеры сообщений являются обычными примерами таких зависимостей. При взаимодействии с этими системами часто бывает необходимо читать их логи, поскольку сообщения об ошибках на стороне клиента могут быть недостаточны.

К счастью, большинство программ записывают свои собственные логи где-то в вашей системе. В UNIX системах программы часто пишут свои логи в /var/log. Например, вебсерверы NGINX пишут свои логи в /var/log/nginx. В последнее время системы начали использовать system log который всё чаще становится местом, куда направляются все лог сообщения. Большинство (но не все) Линукс систем используют systemd, системный демон, который контролирует много вещей в вашей системе, например какие системы включены и исполняются. systemd пишет логи в /var/log/journal в специальном формате, и вы можете использовать команду journalctl, чтобы отображать сообщения. Похожим образом в macOS есть /var/log/system.log, но все больше и больше инструментов используют системный логи, которые могут быть отображены с помощью log show. В большинстве UNIX систме вы также можете использовать dmesg для доступа к логам ядра.

Для записи системный логов вы можете использовать logger. Ниже приведен пример использования logger и то, как праверять что запись сделана в системные логи. Более того, большинство языков программирования имеют инструменты логирования в системный лог.

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

Как мы уже видели в лекции про data wrangling логи могут быть довольно многословными и они требуют от пользователя некоторой фильтрации, для получения необходимой информации. Если вы находите процесс фильтрации логов через journalctl и log show трудоемким, вы можете рассмотреть использование флагов, которые могут служить первых шагом фильтрации выхода логов. Есть много инструментов, таких как lnav, которые предоставляют улучшенное отображение и навигацию по лог файлам.

Debuggers

Когда отладки с помощью printf недостаточно, стоит рассмотреть использование отладчиков (debugger). Отладчики являются программами, которые позваляют вам взаимодействовать с исполняющейся программой, позволяя делать следующее:

Многие языки программирования поставляются с той или иной формой отладчика. В Python это Python Debugger pdb.

Ниже приведено краткое описание некоторых команд pdb:

Давайте посмотрим на пример использования pdb, чтобы найти ошибку в данном python коде (Для этого посмотрите видео).

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]))

Заметим, что т.к. Python является интерпретируемым языком, мы можем использовать оболочку pdb для исполнения команд и инструкций. ipdb является улучшенной версией pdb, который использует IPython REPL позволяющий автодополнение, подсветку синтаксиса, улучшенный tracebacks (вывод ошибок), и улучшенный самоанализ при сохранении того же интерфейса pdb.

Для более низкоуровневого программирования вы возможно захотите взглянуть на gdb (и его улучшенную модификацию pwndbg) и lldb. Они оптимизированы для отладки на языке, подобном Си, но позволят вам исследовать практически любой процесс и получить его текущее машинное состояние: регистры, стек, счетчик программ и т.д.

Специальные инструменты

Даже если вы пытаетесь отлаживать бинарный файл (который является по сути черным ящиком) есть инструменты, которые могут помочь вам с этим. Всякий раз, когда программам требуется выполнить действия, доступные только ядру, они используют System Calls.

Существуют команды, которые позволяют отслеживать системные вызовы, выполняемые вашей программой. В Linux есть strace, а в macOS и BSD есть dtrace. dtrace может быть сложно использовать, так как он использует свой собственный язык программирования D, однако есть обертка, которая называется dtruss, которая предоставляет интерфейс более похожий на strace (больше деталей здесь).

Ниже приведены некоторые примеры использования strace или dtruss чтобы проследить системный вызов stat во время исполнения команды ls. Для погружения в strace, это отличный источник.

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

При некоторых обстоятельствах вам может потребоваться просмотреть сетевые пакеты, чтобы выяснить, в чем проблема в вашей программе. Такие инструменты, как tcpdump и Wireshark являются анализаторами сетевых пакетов, которые позволяют вам читать содержание сетевых пакетов и фильтровать их по разным критериям.

Для веб разработки довольно удобны the Chrome/Firefox developer tools. Они предлагают большое количество инструментов, включающих в себя:

Static Analysis

Для некоторых проблем вам не надо запускать никакой код. Например, просто внимательно посмотрев на часть кода, вы можете понять, что переменные цикла переписывают уже существующие переменные или имена функций; или программа читает переменную до ее инициализации. В таком случае пригождаются инструменты static analysis. Статистический анализ кода берет исходный код в качестве входа и анализирует его, используя правила для того, чтобы понять его корректность.

В нижеприведенном Python коде есть несколько ошибок. Во-первых, переменная цикла foo переопределяет предыдущее определение функции foo. Также мы написали baz вместь bar в последней строке, поэтому программа завершится с ошибкой после завершения вызова sleep (который займет целую минуту).

import time

def foo():
    return 42

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

Статический анализатор кода может определить такие проблемы. Когда мы запускаем pyflakes мы увидим обе эти ошибки. mypy - еще один инструмент, который может определять проблемы проверки типов. Здесь, mypy предупредит нас, что bar изначально был типа int, а затем приведен к float. Опять, заметим, что все эти ошибки были найдены без необходимости запуска кода.

В лекции про shell мы обсудили shellcheck, который является похожим инструментом для shell скриптов.

$ 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)

Большинство редакторов и IDE поддерживают отображение вывода таких инструментов прямо внутри редактора, подсвечивая линии с предупреждениями и с ощибками. Это часто называют корректировкой кода (code linting), и это также может использоваться для отображения других типов проблем, таких как стилистические нарушения или небезопасные конструкции.

В vim, плагины ale или syntastic позволят вам делать это. Для Python, pylint и pep8 являются примерами стилистических линеров, а bandit является инстументом, разработанным для нахождения часто встречающихся проблем безопасности. Для других языков пользователи составили исчерпывающие списки полезных инструментов статического анализа, таких как Awesome Static Analysis (возможно, вы захотите заглянуть в раздел Writing) а для линтеров есть Awesome Linters.

Дополнительным инструментом для стилистической корректировки являются средства форматирования кода, такие как black для Python, gofmt для Go, rustfmt для Rust или prettier для JavaScript, HTML и CSS. Эти инструменты автоматически форматируют ваш код таким образом, чтобы он соответствовал общим стилистическим шаблонам для данного языка программирования. Несмотря на то, что вы, возможно, не желаете предоставлять стилистический контроль над своим кодом, стандартизация кода поможет другим людям читать ваш код и улучшит ваше умение читать чужой (стилистически стандартизированный) код.

Профилирование

Даже если ваш код функционально ведет себя так, как вы ожидаете, этого может оказаться недостаточно, если в процессе работы будет задействован весь ваш процессор или память. Курсы алгоритмов часто учат нотацию большое O, но не то, как находить сложные места в вашей программе. Т.к. преждевременная оптимизация - корень всех зол, вам следует ознакомиться с профилировщиками и инструментами мониторинга. Они помогут вам понять, какие части вашей программы отнимают больше всего времени и/или ресурсов, чтобы вы могли сосредоточиться на оптимизации этих частей.

Замер времени

Аналогично случаю с отладчиков, в большом числе сценариев может быть достаточно просто выводить в стандартный вывод время исполнения кода между 2х строчек. Ниже Python пример использования модуля time.

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

# Get current time
start = time.time()

# Do some work
print("Sleeping for {} ms".format(n))
time.sleep(n/1000)

# Compute time between start and now
print(time.time() - start)

# Output
# Sleeping for 500 ms
# 0.5713930130004883

Однако общее время работы может вводить в заблуждение, поскольку на вашем компьютере одновременно могут выполняться другие процессы или ожидаться какие-либо события. Часто инструменты делают различие между Real, User и Sys временем. В общем случае, User + Sys говорит о том, сколько времени ващ процесс действительно провел в CPU (более детальное описание здесь).

Например, попробуйте запустить команду, которая выполняет HTTP запрос и добавьте префикс time. Если соединение медленное, возможно вы получите похожий вывод. Здесь вызову понадобилось больше 2 секунд на выполнение запроса, но сам процесс занял только 15ms на CPU для выполнения команд пользователя и 12ms на CPU для выполнения инструкций ядра.

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

Профилировщики

CPU

Когда люди говорят профилировщики (profilers), обычно они имеют в виду CPU профилировщики (_CPU profilers). Есть 2 главных типа профилировщиков CPU: отслеживающие (tracing) и сэмплирующие (sampling) профилировщики. Отслеживающие профилировщики ведут учет за каждым вызовом функций, которые делает ваша программа, в то время как сэмплирующие профилировщики исследуют вашу программу периодически (обычно каждую милисекунду) и записывают программный стек. Они используют записи, чтобы предоставить общую статистику, где ваша программа провела больше всего времени, и что она делала. Здесь - хорошая вводная статья, если вы хотите узнать больше подробностей по данной теме.

В большинстве языков программирования есть своего рода профилировщик командной строки, который вы можете использовать для анализа своего кода. Они часто интегрируются с полноценными IDE, но в этой лекции мы сосредоточимся на самих инструментах командной строки.

В Python можно использовать модуль cProfile для профилирования времени вызова функций. Ниже приведен простой пример, который реализует grep в 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)

Мы можем профилировать этот код, используя следующую команду. Анализируя вывод, мы видим, что IO занимает большую часть времени, и что компиляция регулярного выражения также занимает много времени. Поскольку регулярное выражение нужно скомпилировать только один раз, мы можем исключить его из списка for.

$ 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]

Недостатком профилировщика cProfile (и многих других профилировщиков, если на то пошло) является то, что они отображают время на вызов функции. Это может очень быстро стать неинтуитивным, особенно если вы используете в своем коде сторонние библиотеки, поскольку также учитываются вызовы внутренних функций. Более интуитивно понятный способ отображения информации о профилировании заключается в указании времени, затрачиваемого на каждую строку кода, что и делают line profilers.

Например, следующий фрагмент кода на Python выполняет запрос на веб-сайт класса и анализирует ответ, чтобы получить все URL-адреса на странице:

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

# This is a decorator that tells line_profiler
# that we want to analyze this function
@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()

Если бы мы использовали cProfile мы бы получили более 2500 строк вывода, и даже после сортировки было бы сложно понять, где было проведено время. Запуск line_profiler показывает время, затраченное на каждую строку:

$ 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'])

Память

В языках вроде C или C++ утечки памяти могут быть причиной того, что ваша программа никогда не освобождает память, которая ей больше не нужна. Чтобы помочь в процессе отладки памяти, вы можете использовать такие инструменты, как Valgrind, которые помогут вам найти утечки памяти.

В языках со сборщиком мусора (напримре Python) также полезно использовать профилировщики памяти, потому что сборщик мусора не будет удалять объект из памяти, пока на него кто-то ссылается. Ниже пример программы и ее вывода, когда она запущена с memory-profiler (обратите внимание на декоратор, как в 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

Профилирование событий

Как и в случае с strace для отладки, вы можете проигнорировать особенности кода, который вы запускаете, и относиться к нему как к черному ящику во время профилирования. Команда perf сводит к минимуму различия в работе процессора и не сообщает о времени или объеме памяти, но вместо этого сообщает о системных событиях, связанных с вашими программами. Например, perf может легко сообщать о плохом расположении кэша, большом количестве ошибок страницы (page faults) или блокировках работы (livelocks). Вот краткое описание команды:

Визуализация

Вывод рофилировщиков для больших программ будет содержать большое количество информации из-за свойственной програмным проектам сложности. Люди - существа со зрительным восприятием, и они совершенно не умеют читать большое количество цифр и понимать их смысл. Поэтому существует множество инструментов для отображения выходных данных профилировщика более простым для анализа способом.

Одним из распространенных способов отображения информации о профилировании процессора для сэмплирующих профилировщиков выборки является использование Flame Graph, который отображает иерархию вызовов функций по оси Y и время выполнения по оси X. Они также интерактивны, позволяя вам увеличивать масштаб определенных частей программы и просматривать их стек (попробуйте щелкнуть на изображении ниже).

FlameGraph

Графики вызовов или графики потоков управления отображают взаимосвязи между подпрограммами внутри программы, используя функции в качестве узлов, а вызовы функций между ними - в качестве направленных ребер. В сочетании с информацией о профилировании, такой как количество вызовов и затраченное время, графики вызовов могут быть весьма полезны для интерпретации хода выполнения программы. В Python можно использовать библиотеку pycallgraph для их генерации.

Call Graph

Мониторинг ресурсов

Иногда первым шагом к анализу производительности вашей программы является понимание того, каково ее фактическое потребление ресурсов. Программы часто работают медленно, когда у них ограничены ресурсы, например, недостаточно памяти или при плохом сетевом подключении. Существует множество инструментов командной строки для проверки и отображения различных системных ресурсов, таких как загрузка процессора, памяти, сети, диска и так далее.

Если вы хотите протестировать эти инструменты, вы также можете искусственно увеличить нагрузку на машину, используя команду stress command.

Специализированные инструменты

Иногда бенчмаркинг “черного ящика” - это все, что вам нужно, чтобы определить, какое программное обеспечение использовать. Инструменты вида hyperfine позволяет быстро протестировать (benchmark) программы командной строки. Например, В лекции про инструменты оболочки и скриптинг мы рекомендовали fd вместо find. Можно использовать hyperfine, чтобы сравнить их. Напрмиер, в примере ниже fd был в 20 раз быстрее, чем find на моей машине.

$ 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"'

Как и в случае с отладкой, браузеры также оснащены фантастическим набором инструментов для профилирования загрузки веб-страниц, позволяющих вам определить, на что тратится время (загрузка, рендеринг, исполнение скриптов и т.д.). Больше информации здесь: Firefox и Chrome.

Упражнения

Отладка

  1. Используйте journalctl на Linux или log show на macOS, чтобы получить команды супер пользователя (super user) за последний день. Если таких нет, выполните безобидную команду, например sudo ls и проверьте еще раз.

  2. Выполните этот туториал по pdb и познакомьтесь с его командами. Для более подробного ознакомления, прочитайте это.

  3. Установите shellcheck и попытайтесь проверить следующий скрипт. Что не так с кодом? Исправьте его. Установите плагин linter в свой редактор, чтобы вы могли автоматически получать свои предупреждения.

    #!/bin/sh
    ## Example: a typical script with several problems
    for f in $(ls *.m3u)
    do
      grep -qi hq.*mp3 $f \
        && echo -e 'Playlist $f contains a HQ file in mp3 format'
    done
    
  4. (Дополнительно) прочитайте про reversible debugging и сделайте простой пример для использования rr или RevPDB.

    Профилирование

  5. Здесь несколько реализаций алгоритмов сортировки. Используйте cProfile и line_profiler, чтобы сравнить исполнение insertion sort и quicksort. В чем узкое место каждого из алгоритмов? Затем используйте memory_profiler для проверки потребления памяти; почему insertion sort лучше? Теперь проверьте inplace версию quicksort. Проблема: Используйте perf чтобы посмотреть на количество циклов и попаданий в кэш и промахов каждого алгоритма.

  6. Ниже приведен (слегка переусложненный) пример кода на Python для вычисления чисел Фибоначчи.

    #!/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()"))
    

    Запишите код в файл и сделайте его исполняемым. Установите: pycallgraph и graphviz. (Если вы можете запустить dot, у вас уже есть GraphViz.) Запустите код следующим образом pycallgraph graphviz -- ./fib.py и посмотрите на pycallgraph.png. Сколько раз была вызвана функция fib0? Мы можем сделать лучше, путем запоминания функций. Раскоментируйте закоментированные строки и перегенерируйте изображения. Сколько раз вызывается каждая функция fibN теперь?

  7. Частая проблема заключается в том, что порт, который вы хотите слушать уже занят другим процессом. Давайте узнаем, как находить pid такого процесса. Сначала выполните python -m http.server 4444, чтобы запустить минималистичный веб-сервер на порту 4444. В другом терминале запустите lsof | grep LISTEN^ который напечатаем вам все процессы, которые слушают какой-то порт. Найдите ваш процесс и остановите его с помощью kill <PID>.

  8. Ограничение ресурсов процессов может стать еще одним удобным инструментом в вашем арсенале. Попробуйте запустить stress -c 3 и визуализируйте потребление CPU с помощью htop. Теперь, выполните taskset --cpu-list 0,2 stress -c 3 и визуализируйте это. stress занимает 3 CPU? Почему нет? Почитайте man taskset. Вызов: достигните того же самого, используя cgroups. Попробуйте ограничить потребление памяти stress -m.

  9. (Дополнительно) Команда curl ipinfo.io выполняет HTTP запрос и возвращает информацию о вашем публичном IP. Откройте Wireshark и попробуйте прослушать (sniff) пакеты запросов и ответов, которые curl отправил и получил. (Подсказка: Используйте фильтр http, чтобы смотреть только HTTP пакеты).

Редактировать страницу.

Лицензия CC BY-NC-SA.