Ada banyak artikel yang menjelaskan untuk apa Python GIL (Global Interpreter Lock) (maksud saya CPython). Singkatnya, GIL mencegah kode Python bersih multithreaded menggunakan beberapa inti prosesor.
Namun, kami di Vaex melakukan tugas yang paling intensif secara komputasi di C ++ dengan GIL dinonaktifkan. Ini adalah praktik normal untuk pustaka Python berkinerja tinggi, di mana Python hanya bertindak sebagai perekat tingkat tinggi.
GIL harus dinonaktifkan secara eksplisit, dan itu adalah tanggung jawab programmer, yang dapat dia lupakan, yang akan menyebabkan penggunaan kapasitas yang tidak efisien. Baru-baru ini, saya sendiri berperan sebagai pelupa, dan menemukan masalah serupa di Apache Arrow(ini adalah ketergantungan Vaex, jadi ketika GIL tidak dinonaktifkan di Arrow, kami (dan semua orang) mengalami penurunan kinerja).
Selain itu, saat berjalan pada 64 core, kinerja Vaex terkadang jauh dari ideal. Mungkin menggunakan 4000% dari cpu, bukan 6400%, yang tidak cocok untuk saya. Alih-alih memasukkan sakelar secara acak untuk mempelajari efek ini, saya ingin memahami apa yang terjadi, dan jika masalahnya ada di GIL, saya ingin memahami mengapa dan bagaimana hal itu memperlambat Vaex.
Mengapa saya menulis ini
Saya berencana untuk menulis serangkaian artikel yang mencakup beberapa alat dan teknik untuk membuat profil dan menelusuri Python dengan ekstensi asli, dan bagaimana alat ini dapat digabungkan untuk menganalisis dan memvisualisasikan kinerja Python dengan GIL yang diaktifkan dan dinonaktifkan.
Semoga ini akan membantu meningkatkan penelusuran, pembuatan profil, dan pengukuran kinerja lainnya dalam ekosistem bahasa, serta kinerja seluruh ekosistem Python.
Persyaratan
Linux
Anda memerlukan akses root ke mesin Linux (sudo sudah cukup). Atau minta sysadmin Anda untuk menjalankan perintah di bawah ini untuk Anda. Untuk sisa artikel ini, hak pengguna sudah cukup.
Perf
Pastikan Anda telah menginstal perf, misalnya di Ubuntu, Anda dapat melakukannya seperti ini:
$ sudo yum install perf
Konfigurasi kernel
Jalankan sebagai pengguna:
# 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
Paket Python
Kami akan menggunakan VizTracer dan per4m
$ pip install "viztracer>=0.11.2" "per4m>=0.1,<0.2"
Melacak status utas dan proses dengan perf
Tidak ada cara untuk mengetahui status GIL dengan Python (selain menggunakan polling ) karena tidak ada API untuk itu. Kita dapat memantau status dari kernel, dan untuk itu kita membutuhkan alat perf .
Dengan bantuannya (juga dikenal sebagai perf_events), kita dapat mendengarkan perubahan dalam status proses dan utas (kami hanya tertarik pada tidur dan eksekusi) dan mencatatnya. Perf mungkin terlihat mengintimidasi, tetapi ini adalah alat yang ampuh. Jika Anda ingin mengetahui lebih banyak tentang itu, saya sarankan membaca artikel oleh Julia Evans atau situs Brendan Gregg .
Untuk menyimak, pertama-tama mari kita terapkan kinerja ke program sederhana :
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()
Kami mendengarkan hanya beberapa peristiwa untuk mengurangi kebisingan (perhatikan penggunaan wildcard):
$ 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) ]
Dan kita akan menggunakan perintah perf script untuk menghasilkan hasil yang dapat dibaca dan cocok untuk parsing.
Teks tersembunyi
$ 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
Lihatlah kolom keempat (waktu dalam detik): program tertidur (satu detik berlalu). Di sini kita melihat pintu masuk ke kondisi tidur:
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
Ini berarti kernel telah mengubah status utas Python menjadi
S
(= tidur).
Sedetik kemudian, program itu aktif:
swapper 0 [031] 5563912.113697: sched:sched_wakeup: comm=python pid=3040114 prio=120 target_cpu=031
Tentu saja, untuk memahami apa yang terjadi, Anda harus mengumpulkan alatnya. Ya, hasilnya juga dapat dengan mudah diurai menggunakan per4m , tetapi sebelum melanjutkan, saya ingin memvisualisasikan aliran program yang sedikit lebih kompleks menggunakan VizTracer .
VizTracer
Ini adalah pelacak Python yang mampu memvisualisasikan pekerjaan yang dilakukan program di browser. Mari terapkan ke program yang lebih kompleks :
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()
Hasil operasi pelacak:
$ 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.
Seperti inilah HTML yang dihasilkan:
Tampaknya telah
some_computation
dijalankan secara paralel (dua kali), meskipun kami tahu GIL mencegahnya. Apa yang terjadi di sini?
Menggabungkan hasil VizTracer dan kinerja
Mari terapkan perf seperti pada example0.py. Hanya sekarang mari tambahkan argumen
-k CLOCK_MONOTONIC
untuk menggunakan jam yang sama dengan VizTracer dan memintanya untuk menghasilkan JSON alih-alih 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
Kami kemudian menggunakan per4m untuk mengonversi hasil skrip perf ke JSON yang dapat dibaca VizTracer:
$ perf script | per4m perf2trace sched -o perf1.json
Wrote to perf1.json
Sekarang, menggunakan VizTracer, mari kita gabungkan dua file 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.
Inilah yang kami dapatkan:
Jelas, utas secara teratur tidur karena GIL dan tidak berjalan secara paralel.
Catatan : fase tidur panjangnya sekitar 5ms, yang sesuai dengan sys.getswitchinterval default
Definisi GIL
Proses kami pergi ke mode tidur, tetapi kami tidak melihat perbedaan antara status tidur yang diprakarsai oleh panggilan
time.sleep
atau GIL. Ada beberapa cara untuk membedakannya, mari kita lihat dua di antaranya.
Melalui jejak tumpukan
Dengan bantuan
perf record -g
(atau lebih baik dengan
perf record --call-graph dwarf
, itu berarti
-g
), kita mendapatkan pelacakan tumpukan untuk setiap peristiwa kinerja.
$ 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) ]
Melihat hasil dari perf script (yang kami tambahkan untuk alasan performance
--no-inline
), kami mendapatkan banyak informasi. Lihat event perubahan status, ternyata take_gil dipanggil !
Teks tersembunyi
$ 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)
…
Catatan : disebut juga
pthread_cond_timedwait
, ini digunakan oleh https://github.com/sumerc/gilstats.py untuk eBPF jika Anda tertarik dengan mutex lainnya.
Catatan lain : perhatikan bahwa tidak ada pelacakan tumpukan Python di sini, tetapi kami mendapatkan
_PyEval_EvalFrameDefault
lebih banyak. Di masa mendatang, saya berencana untuk menulis cara menyisipkan pelacakan tumpukan.
Alat konversi
per4m perf2trace
memahami hal ini dan memberikan hasil yang berbeda jika jejak berisi
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.
Kita mendapatkan:
Sekarang kita dapat melihat dengan tepat di mana GIL berperan!
Melalui probing (kprobes / uprobe)
Kami tahu kapan proses pergi tidur (karena GIL atau alasan lain), tetapi jika Anda ingin tahu lebih banyak tentang kapan GIL dihidupkan atau dimatikan, maka Anda perlu tahu kapan hasilnya dipanggil dan dikembalikan
take_gil
dan
drop_gil
. Jejak ini dapat diperoleh dengan probing dengan perf. Dalam lingkungan pengguna, probe adalah uprobe, yang serupa dengan kprobes, yang, seperti yang Anda duga, bekerja di lingkungan kernel. Sekali lagi, Julia Evans adalah sumber informasi tambahan yang bagus .
Pasang 4 probe:
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
Ada beberapa keluhan, dan karena yang inline
drop_gil
,
take_gil
beberapa probe / event ditambahkan (yaitu, fungsinya ditampilkan beberapa kali dalam file biner), tetapi semuanya bekerja.
Catatan : Saya mungkin beruntung bahwa biner Python saya (dari conda-forge) telah dikompilasi sehingga
take_gil
/
drop_gil
(dan hasilnya) yang sesuai bekerja dengan sukses untuk menyelesaikan masalah ini.
Harap dicatat bahwa probe tidak mempengaruhi kinerja, dan hanya ketika mereka "aktif" (misalnya, ketika kami memantaunya dari perf), mereka menjalankan kode pada cabang yang berbeda. Selama pemantauan, halaman yang terpengaruh disalin untuk proses yang dipantau, dan pos pemeriksaan disisipkan di tempat yang tepat(INT3 untuk prosesor x86). Pos pemeriksaan memicu acara untuk kinerja dengan sedikit biaya tambahan. Jika Anda ingin menghapus probe, jalankan perintah:
$ sudo perf probe --del 'python*'
Sekarang perf tahu tentang peristiwa baru yang dapat didengarkan, jadi mari kita jalankan lagi dengan argumen tambahan
-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
Catatan : kami menghapusnya
--call-graph dwarf
, jika tidak kinerja tidak akan tepat waktu dan kami akan kehilangan acara.
Kemudian, menggunakan per4m perf2trace, kami mengubahnya menjadi JSON, yang dapat dimengerti oleh VizTracer, dan pada saat yang sama kami mendapatkan statistik baru.
$ 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
Subperintah
per4m perf2trace gil
juga memberikan gil_load akibatnya . Dari situ, kami belajar bahwa kedua utas menunggu GIL sekitar separuh waktu, seperti yang diharapkan.
Dengan file perf.data yang sama yang direkam oleh perf, kita juga dapat menghasilkan informasi tentang status utas atau proses. Tetapi karena kami berjalan tanpa pelacakan tumpukan, kami tidak tahu apakah prosesnya tertidur karena GIL atau tidak.
$ perf script --no-inline | per4m perf2trace sched -o perf1-state.json
Wrote to perf1-state.json
Terakhir, mari gabungkan ketiga hasil tersebut:
$ 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 memberikan ide bagus tentang siapa yang memiliki GIL dan siapa yang menunggunya:
Di atas setiap utas ditulis ketika utas atau proses menunggu GIL dan ketika dinyalakan (ditandai sebagai LOCK). Perhatikan bahwa periode ini tumpang tindih dengan periode ketika benang atau proses adalah terjaga (berjalan!). Perhatikan juga bahwa kami hanya melihat satu utas atau proses dalam status berjalan, sebagaimana mestinya karena GIL.
Waktu antara panggilan
take_gil
, yaitu, antara kunci (dan karena itu antara tidur atau bangun), persis sama seperti pada tabel di atas di kolom%%. Durasi penyalaan GIL untuk setiap utas, berlabel LOCK, sesuai dengan waktu di kolom gil%.
Melepaskan Kraken ... ghm, GIL
Kami telah melihat bagaimana, ketika program Python murni multithread, GIL membatasi kinerja dengan hanya mengizinkan satu utas atau proses untuk dieksekusi pada satu waktu (untuk satu proses Python, tentu saja, dan mungkin di masa depan untuk satu (sub) penerjemah) . Sekarang mari kita lihat apa yang terjadi jika Anda menonaktifkan GIL, seperti yang terjadi saat menjalankan fungsi NumPy.
Contoh kedua mengeksekusi
some_numpy_computation
yang memanggil fungsi NumPy M = 4 kali secara paralel pada dua utas, sedangkan utas utama mengeksekusi kode Python murni.
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()
Alih-alih menjalankan skrip ini dengan perf dan VizTracer, kami akan menggunakan utilitas
per4m giltracer
yang mengotomatiskan semua langkah di atas. Dia akan membuatnya sedikit lebih pintar. Pada dasarnya, kita akan menjalankan perf dua kali, sekali tanpa jejak tumpukan, dan yang kedua dengan itu, dan mengimpor modul / skrip sebelum menjalankan fungsi utamanya untuk menghilangkan jejak yang tidak menarik seperti impor yang sama. Ini akan terjadi cukup cepat sehingga kami tidak kehilangan acara.
$ giltracer --state-detect -o example2-uprobes.html -m per4m.example2 ...
Total aliran:
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 ...
...
Meskipun utas utama menjalankan kode Python (GIL diaktifkan untuknya, yang dilambangkan dengan kata LOCK), utas lain juga dieksekusi secara paralel. Perhatikan bahwa dalam contoh Python murni, kami memiliki satu utas atau proses yang berjalan pada waktu yang sama. Dan di sini sebenarnya tiga utas dijalankan secara paralel. Hal ini dimungkinkan karena rutinitas NumPy yang disertakan dengan C / C ++ / Fortran menonaktifkan GIL.
Namun, GIL masih mempengaruhi utas, karena ketika fungsi NumPy kembali ke Python, ia perlu mendapatkan GIL lagi, seperti yang terlihat pada blok yang panjang
take_gil
. Ini membutuhkan 10% dari waktu setiap utas.
Integrasi Jupyter
Karena alur kerja saya sering kali melibatkan menjalankan MacBook (yang tidak menjalankan perf, tetapi mendukung dtrace) yang terhubung ke mesin Linux dari jarak jauh, saya menggunakan notebook Jupyter untuk mengeksekusi kode dari jarak jauh. Dan karena saya adalah pengembang Jupyter, saya harus melakukan pembungkus
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.
Unduh giltracer.html
Buka giltracer.html di tab baru (mungkin tidak berfungsi karena keamanan)
Kesimpulan
Dengan perf, kita dapat menentukan status proses atau utas, yang membantu untuk memahami mana di antara mereka yang GIL-nya diaktifkan dengan Python. Dan dengan bantuan pelacakan tumpukan, Anda dapat menentukan bahwa GIL adalah penyebab tidur, dan bukan
time.sleep
, misalnya.
Menggabungkan uprobe dengan perf memungkinkan Anda untuk melacak pemanggilan dan pengembalian hasil fungsi
take_gil
dan mendapatkan
drop_gil
lebih banyak wawasan tentang dampak GIL pada program Python Anda.
Pekerjaan kami difasilitasi oleh paket per4m eksperimental, yang mengubah skrip perf ke format JSON VizTracer, serta beberapa alat orkestrasi.
Banyak bukaf, tidak menguasai
Jika Anda hanya ingin melihat dampak GIL, jalankan ini sekali:
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"
Contoh penggunaan:
# 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
Rencana masa depan
Saya berharap saya tidak perlu mengembangkan alat ini. Semoga saya dapat menginspirasi seseorang untuk menciptakan produk yang lebih baik dari saya. Saya ingin fokus menulis kode kinerja tinggi. Namun, saya punya rencana seperti itu untuk masa depan:
- Gali pengukur kinerja di VizTracer untuk melihat cache hilang atau proses downtime.
- Menerapkan jejak tumpukan python di jejak kinerja untuk digabungkan dengan alat seperti http://www.brendangregg.com/offcpuanalysis.html
- Ulangi latihan yang sama dengan dtrace untuk digunakan di macOS.
- Secara otomatis mendeteksi fungsi C mana yang tidak menonaktifkan GIL ( https://github.com/vaexio/vaex/pull/1114 , https://github.com/apache/arrow/pull/7756 )
- , https://github.com/h5py/h5py/issues/1516