...

пятница, 22 января 2021 г.

[Перевод] Трассировка Python GIL

Есть много статей, объясняющих, для чего нужен Python GIL (The Global Interpreter Lock) (я подразумеваю CPython). Если вкратце, то GIL не даёт многопоточному чистому коду на Python использовать несколько ядер процессора.

Однако мы в Vaex исполняем большинство задач с интенсивными вычислениями на С++ с отключением GIL. Это нормальная практика для высокопроизводительных Python—библиотек, в которых Python всего лишь выступает в роли высокоуровневого связующего звена.

GIL нужно отключать явно, и это ответственность программиста, о которой он может забыть, что приведёт к неэффективному использованию мощностей. Недавно я сам побывал в роли забывшего, и нашёл подобную проблему в Apache Arrow (это зависимость Vaex, так что когда GIL не отключается в Arrow, мы (и все остальные) сталкиваемся с падением производительности).

Кроме того, при исполнении на 64 ядрах производительность Vaex иногда далека от идеала. Возможно, он использует 4000 % процессора вместо 6400 %, что меня не устраивает. Вместо того, чтобы наугад вставлять выключатели для изучения этого эффекта, я хочу разобраться в происходящем, и если проблема в GIL, то хочу понять, почему и как он тормозит Vaex.

Почему я это пишу


Я планирую написать серию статей, рассказывающих о некоторых инструментах и методиках профилирования и трассировки Python с нативными расширениями, а также о том, как эти инструменты можно объединить для анализа и визуализации работы Python при включённом и отключённом GIL.

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

Требования


Linux


Вам нужен доступ к Linux-машине с root-привилегиями (sudo достаточно). Или попросите сисадмина выполнить для вас нижеописанные команды. Для остальной статьи достаточно пользовательских привилегий.

Perf


Убедитесь, что у вас установлен perf, к примеру, на Ubuntu это можно сделать так: 
$ sudo yum install perf

Конфигурация ядра


Запуск в роли пользователя: 
# Enable users to run perf (use at own risk)
$ sudo sysctl kernel.perf_event_paranoid=-1

# Enable users to see schedule trace events:
$ sudo mount -o remount,mode=755 /sys/kernel/debug
$ sudo mount -o remount,mode=755 /sys/kernel/debug/tracing

Пакеты Python


Мы будем использовать VizTracer и per4m 
$ pip install "viztracer>=0.11.2" "per4m>=0.1,<0.2"

Отслеживание состояний потоков и процессов с помощью perf


В Python нельзя выяснить состояние GIL (кроме использования поллинга), потому что для этого нет API. Мы можем отслеживать состояние из ядра, и для этого нам нужен инструмент perf.

С его помощью (он также известен как perf_events) мы можем прослушивать изменения состояний процессов и потоков (нас интересует только засыпание и исполнение) и журналировать их. Perf может выглядеть пугающе, но это мощный инструмент. Если хотите узнать о нём больше, рекомендую почитать статью Джулии Эванс или сайт Брендана Грегга.

Чтобы настроиться, для начала применим perf к простенькой программе:

import time
from threading import Thread

def sleep_a_bit():
    time.sleep(1)

def main():
    t = Thread(target=sleep_a_bit)
    t.start()
    t.join()

main()

Мы прослушиваем всего несколько событий, чтобы уменьшить зашумлённость (обратите внимание на использование символов подстановки (wildcards)): 
$ perf record -e sched:sched_switch  -e sched:sched_process_fork \
        -e 'sched:sched_wak*' -- python -m per4m.example0
[ perf record: Woken up 2 times to write data ]
[ perf record: Captured and wrote 0,032 MB perf.data (33 samples) ]

И применим скриптовую команду perf для вывода читабельного результата, пригодного для парсинга.
Скрытый текст 
$ perf script
        :3040108 3040108 [032] 5563910.979408:                sched:sched_waking: comm=perf pid=3040114 prio=120 target_cpu=031
        :3040108 3040108 [032] 5563910.979431:                sched:sched_wakeup: comm=perf pid=3040114 prio=120 target_cpu=031
          python 3040114 [031] 5563910.995616:                sched:sched_waking: comm=kworker/31:1 pid=2502104 prio=120 target_cpu=031
          python 3040114 [031] 5563910.995618:                sched:sched_wakeup: comm=kworker/31:1 pid=2502104 prio=120 target_cpu=031
          python 3040114 [031] 5563910.995621:                sched:sched_waking: comm=ksoftirqd/31 pid=198 prio=120 target_cpu=031
          python 3040114 [031] 5563910.995622:                sched:sched_wakeup: comm=ksoftirqd/31 pid=198 prio=120 target_cpu=031
          python 3040114 [031] 5563910.995624:                sched:sched_switch: prev_comm=python prev_pid=3040114 prev_prio=120 prev_state=R+ ==> next_comm=kworker/31:1 next_pid=2502104 next_prio=120
          python 3040114 [031] 5563911.003612:                sched:sched_waking: comm=kworker/32:1 pid=2467833 prio=120 target_cpu=032
          python 3040114 [031] 5563911.003614:                sched:sched_wakeup: comm=kworker/32:1 pid=2467833 prio=120 target_cpu=032
          python 3040114 [031] 5563911.083609:                sched:sched_waking: comm=ksoftirqd/31 pid=198 prio=120 target_cpu=031
          python 3040114 [031] 5563911.083612:                sched:sched_wakeup: comm=ksoftirqd/31 pid=198 prio=120 target_cpu=031
          python 3040114 [031] 5563911.083613:                sched:sched_switch: prev_comm=python prev_pid=3040114 prev_prio=120 prev_state=R ==> next_comm=ksoftirqd/31 next_pid=198 next_prio=120
          python 3040114 [031] 5563911.108984:                sched:sched_waking: comm=node pid=2446812 prio=120 target_cpu=045
          python 3040114 [031] 5563911.109059:                sched:sched_waking: comm=node pid=2446812 prio=120 target_cpu=045
          python 3040114 [031] 5563911.112250:          sched:sched_process_fork: comm=python pid=3040114 child_comm=python child_pid=3040116
          python 3040114 [031] 5563911.112260:            sched:sched_wakeup_new: comm=python pid=3040116 prio=120 target_cpu=037
          python 3040114 [031] 5563911.112262:            sched:sched_wakeup_new: comm=python pid=3040116 prio=120 target_cpu=037
          python 3040114 [031] 5563911.112273:                sched:sched_switch: prev_comm=python prev_pid=3040114 prev_prio=120 prev_state=S ==> next_comm=swapper/31 next_pid=0 next_prio=120
          python 3040116 [037] 5563911.112418:                sched:sched_waking: comm=python pid=3040114 prio=120 target_cpu=031
          python 3040116 [037] 5563911.112450:                sched:sched_waking: comm=python pid=3040114 prio=120 target_cpu=031
          python 3040116 [037] 5563911.112473: sched:sched_wake_idle_without_ipi: cpu=31
         swapper     0 [031] 5563911.112476:                sched:sched_wakeup: comm=python pid=3040114 prio=120 target_cpu=031
          python 3040114 [031] 5563911.112485:                sched:sched_switch: prev_comm=python prev_pid=3040114 prev_prio=120 prev_state=S ==> next_comm=swapper/31 next_pid=0 next_prio=120
          python 3040116 [037] 5563911.112485:                sched:sched_waking: comm=python pid=3040114 prio=120 target_cpu=031
          python 3040116 [037] 5563911.112489:                sched:sched_waking: comm=python pid=3040114 prio=120 target_cpu=031
          python 3040116 [037] 5563911.112496:                sched:sched_switch: prev_comm=python prev_pid=3040116 prev_prio=120 prev_state=S ==> next_comm=swapper/37 next_pid=0 next_prio=120
         swapper     0 [031] 5563911.112497:                sched:sched_wakeup: comm=python pid=3040114 prio=120 target_cpu=031
          python 3040114 [031] 5563911.112513:                sched:sched_switch: prev_comm=python prev_pid=3040114 prev_prio=120 prev_state=S ==> next_comm=swapper/31 next_pid=0 next_prio=120
         swapper     0 [037] 5563912.113490:                sched:sched_waking: comm=python pid=3040116 prio=120 target_cpu=037
         swapper     0 [037] 5563912.113529:                sched:sched_wakeup: comm=python pid=3040116 prio=120 target_cpu=037
          python 3040116 [037] 5563912.113595:                sched:sched_waking: comm=python pid=3040114 prio=120 target_cpu=031
          python 3040116 [037] 5563912.113620:                sched:sched_waking: comm=python pid=3040114 prio=120 target_cpu=031
         swapper     0 [031] 5563912.113697:                sched:sched_wakeup: comm=python pid=3040114 prio=120 target_cpu=031


Взгляните на четвёртую колонку (время в секундах): программа заснула (прошла одна секунда). Здесь мы видим вход в состояние сна: 
python 3040114 [031] 5563911.112513: sched:sched_switch: prev_comm=python prev_pid=3040114 prev_prio=120 prev_state=S ==> next_comm=swapper/31 next_pid=0 next_prio=120

Это означает, что ядро изменило состояние потока Python на S (=sleeping).

Секунду спустя программа пробудилась:

swapper 0 [031] 5563912.113697: sched:sched_wakeup: comm=python pid=3040114 prio=120 target_cpu=031

Конечно, чтобы разобраться в происходящем придётся собрать инструментарий. Да, результат можно также легко отпарсить с помощью per4m, но прежде чем мы продолжим, хочу с помощью VizTracer визуализировать поток чуть более сложной программы.

VizTracer


Это трассировщик Python, способный визуализировать работу, которую программа выполняет в браузере. Давайте применим его к более сложной программе: 
import threading
import time

def some_computation():
    total = 0   
    for i in range(1_000_000):
        total += i
    return total

def main():
    thread1 = threading.Thread(target=some_computation)
    thread2 = threading.Thread(target=some_computation)
    thread1.start()
    thread2.start()
    time.sleep(0.2)
    for thread in [thread1, thread2]:
        thread.join()

main()

Результат работы трассировщика: 
$ viztracer -o example1.html --ignore_frozen -m per4m.example1
Loading finish                                        
Saving report to /home/maartenbreddels/github/maartenbreddels/per4m/example1.html ...
Dumping trace data to json, total entries: 94, estimated json file size: 11.0KiB
Generating HTML report
Report saved.

Так выглядит получившийся HTML:

Похоже, some_computation исполнялась параллельно (дважды), хотя мы знаем, что GIL это предотвращает. Что тут происходит?

Объединение результатов работы VizTracer и perf


Давайте применим к программе perf, как в случае с example0.py. Только теперь добавим аргумент -k CLOCK_MONOTONIC, чтобы использовать те же часы, что и VizTracer, и попросим его сгенерировать JSON вместо HTML: 
$ perf record -e sched:sched_switch  -e sched:sched_process_fork -e 'sched:sched_wak*' \
   -k CLOCK_MONOTONIC  -- viztracer -o viztracer1.json --ignore_frozen -m per4m.example1

Затем с помощью per4m преобразуем результаты скрипта perf в JSON, который может прочитать VizTracer: 
$ perf script | per4m perf2trace sched -o perf1.json
Wrote to perf1.json

Теперь с помощью VizTracer объединим два JSON-файла: 
$ viztracer --combine perf1.json viztracer1.json -o example1_state.html
Saving report to /home/maartenbreddels/github/maartenbreddels/per4m/example1.html ...
Dumping trace data to json, total entries: 131, estimated json file size: 15.4KiB
Generating HTML report
Report saved.

Вот что получили:

Очевидно, что потоки регулярно засыпают из-за GIL и не исполняются параллельно.

Примечание: длина фазы сна около 5 мс, что соответствует значению по умолчанию sys.getswitchinterval

Определение GIL


Наш процесс засыпает, но мы не видим разницы между состояниями сна, которое инициируется вызовом time.sleep или GIL. Есть несколько способов определить разницу, рассмотрим два из них.

Через трассировку стека


С помощью perf record -g (а лучше с помощью perf record --call-graph dwarf, что подразумевает -g), мы получим трассировки стека для каждого события perf. 
$ perf record -e sched:sched_switch  -e sched:sched_process_fork -e 'sched:sched_wak*'\
   -k CLOCK_MONOTONIC  --call-graph dwarf -- viztracer -o viztracer1-gil.json --ignore_frozen -m per4m.example1
Loading finish                                        
Saving report to /home/maartenbreddels/github/maartenbreddels/per4m/viztracer1-gil.json ...
Dumping trace data to json, total entries: 94, estimated json file size: 11.0KiB
Report saved.
[ perf record: Woken up 3 times to write data ]
[ perf record: Captured and wrote 0,991 MB perf.data (164 samples) ]

Взглянув на результат скрипта perf (в который мы ради производительности добавили --no-inline), мы получим много информации. Посмотрите на событие изменения состояния, оказывается, вызывался take_gil!
Скрытый текст 
$ perf script --no-inline | less
...
viztracer 3306851 [059] 5614683.022539:                sched:sched_switch: prev_comm=viztracer prev_pid=3306851 prev_prio=120 prev_state=S ==> next_comm=swapper/59 next_pid=0 next_prio=120
        ffffffff96ed4785 __sched_text_start+0x375 ([kernel.kallsyms])
        ffffffff96ed4785 __sched_text_start+0x375 ([kernel.kallsyms])
        ffffffff96ed4b92 schedule+0x42 ([kernel.kallsyms])
        ffffffff9654a51b futex_wait_queue_me+0xbb ([kernel.kallsyms])
        ffffffff9654ac85 futex_wait+0x105 ([kernel.kallsyms])
        ffffffff9654daff do_futex+0x10f ([kernel.kallsyms])
        ffffffff9654dfef __x64_sys_futex+0x13f ([kernel.kallsyms])
        ffffffff964044c7 do_syscall_64+0x57 ([kernel.kallsyms])
        ffffffff9700008c entry_SYSCALL_64_after_hwframe+0x44 ([kernel.kallsyms])
        7f4884b977b1<a href="https://www.maartenbreddels.com/cdn-cgi/l/email-protection"> [email protected]@GLIBC_2.3.2+0x271 (/usr/lib/x86_64-linux-gnu/libpthread-2.31.so)
            55595c07fe6d take_gil+0x1ad (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfaa0b3 PyEval_RestoreThread+0x23 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c000872 lock_PyThread_acquire_lock+0x1d2 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfe71f3 _PyMethodDef_RawFastCallKeywords+0x263 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfe7313 _PyCFunction_FastCallKeywords+0x23 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c01d657 call_function+0x3b7 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c060d00 _PyEval_EvalFrameDefault+0x610 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfb6db1 _PyEval_EvalCodeWithName+0x251 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfd6b00 _PyFunction_FastCallKeywords+0x520 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c01d334 call_function+0x94 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c060d00 _PyEval_EvalFrameDefault+0x610 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfb6db1 _PyEval_EvalCodeWithName+0x251 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfd6b00 _PyFunction_FastCallKeywords+0x520 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c01d334 call_function+0x94 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c060d00 _PyEval_EvalFrameDefault+0x610 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfd6766 _PyFunction_FastCallKeywords+0x186 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c01d334 call_function+0x94 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c060d00 _PyEval_EvalFrameDefault+0x610 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfd6766 _PyFunction_FastCallKeywords+0x186 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c060ae4 _PyEval_EvalFrameDefault+0x3f4 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfb6db1 _PyEval_EvalCodeWithName+0x251 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c074e5d builtin_exec+0x33d (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfe7078 _PyMethodDef_RawFastCallKeywords+0xe8 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfe7313 _PyCFunction_FastCallKeywords+0x23 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c066c39 _PyEval_EvalFrameDefault+0x6549 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfb77e0 _PyEval_EvalCodeWithName+0xc80 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfd6b62 _PyFunction_FastCallKeywords+0x582 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c01d334 call_function+0x94 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c060d00 _PyEval_EvalFrameDefault+0x610 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfd6766 _PyFunction_FastCallKeywords+0x186 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c01d334 call_function+0x94 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c060d00 _PyEval_EvalFrameDefault+0x610 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfd6766 _PyFunction_FastCallKeywords+0x186 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c01d334 call_function+0x94 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c060d00 _PyEval_EvalFrameDefault+0x610 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfd6766 _PyFunction_FastCallKeywords+0x186 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c060ae4 _PyEval_EvalFrameDefault+0x3f4 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfb6db1 _PyEval_EvalCodeWithName+0x251 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595bfb81e2 PyEval_EvalCode+0x22 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c0c51d1 run_mod+0x31 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c0cf31d PyRun_FileExFlags+0x9d (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c0cf50a PyRun_SimpleFileExFlags+0x1ba (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c0d05f0 pymain_main+0x3e0 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            55595c0d067b _Py_UnixMain+0x3b (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
            7f48849bc0b2 __libc_start_main+0xf2 (/usr/lib/x86_64-linux-gnu/libc-2.31.so)
            55595c075100 _start+0x28 (/home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
…


Примечание: также вызывался pthread_cond_timedwait, он используется https://github.com/sumerc/gilstats.py для eBPF, если вас интересуют другие мьютексы.

Ещё примечание: обратите внимание, что здесь нет трассировки стека Python, а вместо неё мы получили _PyEval_EvalFrameDefault и прочее. В будущем я планирую написать, как вставлять трассировку стека.

Инструмент для конвертирования per4m perf2trace понимает это и генерирует другой результат, когда в трассировке присутствует take_gil:

$ perf script --no-inline | per4m perf2trace sched -o perf1-gil.json
Wrote to perf1-gil.json
$ viztracer --combine perf1-gil.json viztracer1-gil.json -o example1-gil.html
Saving report to /home/maartenbreddels/github/maartenbreddels/per4m/example1.html ...
Dumping trace data to json, total entries: 131, estimated json file size: 15.4KiB
Generating HTML report
Report saved.

Получаем:

Теперь мы точно видим, где GIL играет роль!

Через зондирование (kprobes/uprobes)


Мы знаем, когда процессы засыпают (из-за GIL или иных причин), но если хочется подробнее узнать о том, когда включается или выключается GIL, то нужно знать, когда вызываются и возвращаются результаты take_gil и drop_gil. Такую трассировку можно получить благодаря зондированию с помощью perf. В пользовательской среде зондами являются uprobes, это аналог kprobes, которые, как вы могли догадаться, работают в среде ядра. Опять же, прекрасный источник дополнительной информации — Джулия Эванс.

Установим 4 зонда:

sudo perf probe -f -x `which python` python:take_gil=take_gil
sudo perf probe -f -x `which python` python:take_gil=take_gil%return
sudo perf probe -f -x `which python` python:drop_gil=drop_gil
sudo perf probe -f -x `which python` python:drop_gil=drop_gil%return

Added new events:

  python:take_gil      (on take_gil in /home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
  python:take_gil_1    (on take_gil in /home/maartenbreddels/miniconda/envs/dev/bin/python3.7)

You can now use it in all perf tools, such as:

        perf record -e python:take_gil_1 -aR sleep 1

Failed to find "take_gil%return",
 because take_gil is an inlined function and has no return point.
Added new event:
  python:take_gil__return (on take_gil%return in /home/maartenbreddels/miniconda/envs/dev/bin/python3.7)

You can now use it in all perf tools, such as:

        perf record -e python:take_gil__return -aR sleep 1

Added new events:
  python:drop_gil      (on drop_gil in /home/maartenbreddels/miniconda/envs/dev/bin/python3.7)
  python:drop_gil_1    (on drop_gil in /home/maartenbreddels/miniconda/envs/dev/bin/python3.7)

You can now use it in all perf tools, such as:

        perf record -e python:drop_gil_1 -aR sleep 1

Failed to find "drop_gil%return",
 because drop_gil is an inlined function and has no return point.
Added new event:
  python:drop_gil__return (on drop_gil%return in /home/maartenbreddels/miniconda/envs/dev/bin/python3.7)

You can now use it in all perf tools, such as:

        perf record -e python:drop_gil__return -aR sleep 1

Есть какие-то жалобы, а из-за инлайненных drop_gil и take_gil добавилось несколько зондов/событий (то есть функция представлена в бинарном файле несколько раз), но всё работает.

Примечание: возможно, мне повезло, что мой бинарник Python (от conda-forge) скомпилирован так, что соответствующие take_gil/drop_gil (и их результаты), успешно отработавшие, подошли для решения этой проблемы.

Обратите внимание, что зонды не влияют на производительность, и только когда они «активны» (например, когда мы их мониторим из perf), то запускают код по другой ветке. При мониторинге копируются затронутые страницы для отслеживаемого процесса, а в нужные места вставляются контрольные точки (INT3 для процессоров x86). Контрольная точка запускает событие для perf с маленькими накладными расходами. Если вы хотите убрать зонды, то выполните команду:

$ sudo perf probe --del 'python*'

Теперь perf знает о новых событиях, которые он может прослушивать, так что давайте снова его запустим с дополнительным аргументом -e 'python:*gil*': 
$ perf record -e sched:sched_switch  -e sched:sched_process_fork -e 'sched:sched_wak*' -k CLOCK_MONOTONIC  \
  -e 'python:*gil*' -- viztracer  -o viztracer1-uprobes.json --ignore_frozen -m per4m.example1

Примечание: мы убрали --call-graph dwarf, иначе perf не успеет и мы потеряем события.

Затем с помощью per4m perf2trace преобразуем в JSON, который понятен для VizTracer, и заодно получим новую статистику.

$ perf script --no-inline | per4m perf2trace gil -o perf1-uprobes.json
...
Summary of threads:

PID         total(us)    no gil%    has gil%    gil wait%
--------  -----------  -----------  ------------  -------------
3353567*     164490.0         65.9          27.3            6.7
3353569       66560.0          0.3          48.2           51.5
3353570       60900.0          0.0          56.4           43.6

High 'no gil' is good, we like low 'has gil',
 and we don't want 'gil wait'. (* indicates main thread)
... 
Wrote to perf1-uprobes.json

Подкоманда per4m perf2trace gil также выдаёт в качестве результата gil_load. Из него мы узнаём, что оба потока ждут GIL примерно половину времени, как и ожидалось.

С помощью того же файла perf.data, записанного perf, мы также можем сгенерировать информацию о состоянии потока или процесса. Но поскольку мы выполняли без трассировок стека, мы не знаем, заснул ли процесс из-за GIL или нет.

$ perf script --no-inline | per4m perf2trace sched -o perf1-state.json
Wrote to perf1-state.json

Наконец, соберём вместе все три результата: 
$ viztracer --combine perf1-state.json perf1-uprobes.json viztracer1-uprobes.json -o example1-uprobes.html 
Saving report to /home/maartenbreddels/github/maartenbreddels/per4m/example1-uprobes.html ...
Dumping trace data to json, total entries: 10484, estimated json file size: 1.2MiB
Generating HTML report
Report saved.

VizTracer даёт хорошее представление о том, у кого был GIL и кто его ждал:

Над каждым потоком написано, когда поток или процесс ждёт GIL и когда тот включается (помечено как LOCK). Обратите внимание, что эти периоды пересекаются с периодами, когда поток или процесс не спит (выполняется!). Также обратите внимание, что в состоянии выполнения мы видим только один поток или процесс, как и должно быть из-за GIL.

Время между вызовами take_gil, то есть между блокировками (а следовательно, между засыпанием или пробуждением), точно такое же, как в вышеприведённой таблице в колонке gil wait%. Длительность включения GIL для каждого потока, помеченная как LOCK, соответствует времени в колонке gil%.

Выпускаем Кракена… гхм, GIL


Мы видели, как при многопоточном исполнении программы на чистом Python GIL ограничивает производительность, разрешая одновременно исполнять только один поток или процесс (для одного процесса Python, разумеется, и, возможно, в будущем для одного (суб)интерпретатора). Теперь посмотрим, что будет, если отключить GIL, как это происходит при исполнении функций NumPy.

Во втором примере исполняется some_numpy_computation, которая вызывает функцию NumPy M=4 раз параллельно в двух потоках, в то время как основной поток исполняет чистый код на Python.

import threading
import time
import numpy as np

N = 1024*1024*32
M = 4
x = np.arange(N, dtype='f8')

def some_numpy_computation():
    total = 0
    for i in range(M):
        total += x.sum()
    return total

def main(args=None):
    thread1 = threading.Thread(target=some_numpy_computation)
    thread2 = threading.Thread(target=some_numpy_computation)
    thread1.start()
    thread2.start()
    total = 0
    for i in range(2_000_000):
        total += i
    for thread in [thread1, thread2]:
        thread.join()
main()

Вместо исполнения этого скрипта с помощью perf и VizTracer мы применим утилиту per4m giltracer, которая автоматизирует все вышеописанные этапы. Она сделает это немного умнее. По сути, мы дважды запустим perf, один раз без трассировки стека, а второй раз с ней, и импортируем модуль/скрипт до исполнения его основной функции, чтобы избавиться от неинтересной трассировки вроде того же импортирования. Это произойдёт достаточно быстро, чтобы мы не потеряли события. 
$ giltracer --state-detect -o example2-uprobes.html -m per4m.example2
...

Итоги по потокам: 
PID         total(us)    no gil%    has gil%    gil wait%
--------  -----------  -----------  ------------  -------------
3373601*    1359990.0         95.8           4.2            0.1
3373683       60276.4         84.6           2.2           13.2
3373684       57324.0         89.2           1.9            8.9

High 'no gil' is good, we like low 'has gil',
 and we don't want 'gil wait'. (* indicates main thread)
...
Saving report to /home/maartenbreddels/github/maartenbreddels/per4m/example2-uprobes.html ...
...


Хотя в основном потоке исполняется код на Python (для него включён GIL, что обозначается словом LOCK), параллельно исполняются и другие потоки. Обратите внимание, что в примере с чистым Python у нас одновременно исполняется один поток или процесс. А здесь действительно параллельно исполняется три потока. Это стало возможно потому, что подпрограммы NumPy, входящие в C/C++/Fortran, отключили GIL.

Однако GIL всё же влияет на потоки, потому что когда функция NumPy возвращается в Python, ей снова нужно получить GIL, как видно из длительных блоков take_gil. На это тратится 10 % времени каждого потока.

Интеграция Jupyter


Поскольку мой рабочий процесс часто подразумевает работу на MacBook (который не исполняет perf, но поддерживает dtrace), удалённо подключённом к Linux-машине, я использую Jupyter notebook для удалённого исполнения кода. И раз я Jupyter-разработчик, мне пришлось сделать обёртку с помощью cell magic. 
# this registers the giltracer cell magic
%load_ext per4m

%%giltracer
# this call the main define above, but this can also be a multiline code cell
main()

Saving report to /tmp/tmpvi8zw9ut/viztracer.json ...
Dumping trace data to json, total entries: 117, estimated json file size: 13.7KiB
Report saved.

[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0,094 MB /tmp/tmpvi8zw9ut/perf.data (244 samples) ]

Wait for perf to finish...
perf script -i /tmp/tmpvi8zw9ut/perf.data --no-inline --ns | per4m perf2trace gil -o /tmp/tmpvi8zw9ut/giltracer.json -q -v 
Saving report to /home/maartenbreddels/github/maartenbreddels/fastblog/_notebooks/giltracer.html ...
Dumping trace data to json, total entries: 849, estimated json file size: 99.5KiB
Generating HTML report
Report saved.

Скачать giltracer.html

Открыть giltracer.html в новой вкладке (может не работать в связи с обеспечением безопасности)

Заключение


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

Сочетание uprobes с perf позволяет трассировать вызов и возвращение результатов функций take_gil и drop_gil, получая ещё больше информации о влиянии GIL на вашу Python-программу.

Работу нам облегчает экспериментальный пакет per4m, преобразующий скрипт perf в JSON-формат VizTracer, а также некоторые инструменты оркестрации.

Много букаф, не осилил


Если вам просто хочется посмотреть на влияние GIL, то однократно запустите это: 
sudo yum install perf
sudo sysctl kernel.perf_event_paranoid=-1
sudo mount -o remount,mode=755 /sys/kernel/debug
sudo mount -o remount,mode=755 /sys/kernel/debug/tracing
sudo perf probe -f -x `which python` python:take_gil=take_gil
sudo perf probe -f -x `which python` python:take_gil=take_gil%return
sudo perf probe -f -x `which python` python:drop_gil=drop_gil
sudo perf probe -f -x `which python` python:drop_gil=drop_gil%return
pip install "viztracer>=0.11.2" "per4m>=0.1,<0.2"

Пример использования: 
# module
$ giltracer per4m/example2.py
# script
$ giltracer -m per4m.example2
# add thread/process state detection
$ giltracer --state-detect -m per4m.example2
# without uprobes (in case that fails)
$ giltracer --state-detect --no-gil-detect -m per4m.example2

Планы на будущее


Хотелось бы мне, чтобы не пришлось разрабатывать эти инструменты. Надеюсь, мне удалось вдохновить кого-то на создание более совершенных средств, чем мои. Я хочу сосредоточиться на написании высокопроизводительного кода. Однако у меня есть такие планы на будущее:
  • Раскопать измеритель производительности в VizTracer, чтобы посмотреть на промахи кеша или простои процесса.
  • Внедрить трассировку стека Python в трассировки perf, чтобы объединить их с инструментами вроде http://www.brendangregg.com/offcpuanalysis.html
  • Повторить то же упражнение с помощью dtrace, чтобы использовать в MacOS.
  • Автоматически определять, какие C-функции не отключают GIL (https://github.com/vaexio/vaex/pull/1114, https://github.com/apache/arrow/pull/7756 )
  • Применить всё это для решения других задач, например https://github.com/h5py/h5py/issues/1516

Let's block ads! (Why?)

на
Ярлыки: ,

Комментариев нет:

Отправить комментарий

Подписаться на: Комментарии к сообщению (Atom)