🤑 🚾 🕠 Bagaimana cara kerja profiler di Ruby dan Python? 👦🏼 🧐 🛐

Terjemahan artikel disiapkan untuk mengantisipasi dimulainya kursus lanjutan "Pengembang Python" .

Artikel aslinya bisa dibaca disini .

Halo! Sebagai minuman beralkohol Ruby profiler, saya ingin berbicara tentang cara kerja profiler Ruby dan Python yang ada. Ini juga akan membantu menjawab pertanyaan yang banyak orang tanyakan kepada saya: "Bagaimana cara menulis profiler?"

Pada artikel ini, kita akan fokus pada profiler prosesor (dan bukan, katakanlah, profiler memori / heap). Saya akan membahas beberapa pendekatan dasar untuk menulis profiler, memberikan contoh kode dan menunjukkan banyak contoh profiler populer di Ruby dan Python, dan juga menunjukkan kepada Anda bagaimana mereka bekerja di bawah tenda.

Mungkin, mungkin ada kesalahan dalam artikel (dalam persiapan untuk menulisnya, saya melihat sebagian kode dari 14 pustaka untuk pembuatan profil, dan saya tidak terbiasa dengan banyak dari mereka sampai sekarang), jadi tolong beri tahu saya jika Anda menemukannya ...

2 jenis profiler

Ada dua jenis utama profiler prosesor - profiler pengambilan sampel dan penelusuran .

Tracing profiler merekam setiap pemanggilan fungsi dalam program Anda, yang pada akhirnya memberikan laporan. Pengambil sampel profiler menggunakan pendekatan statistik, mereka menulis tumpukan setiap beberapa milidetik, menghasilkan laporan berdasarkan data ini.

Alasan utama untuk menggunakan sampling profiler daripada tracing profiler adalah karena sifatnya yang ringan. Anda mengambil 20 atau 200 gambar per detik - tidak membutuhkan banyak waktu. Profiler ini akan sangat efektif jika Anda memiliki masalah kinerja yang serius (80% dari waktu dihabiskan untuk memanggil satu fungsi lambat), karena 200 snapshot per detik akan cukup untuk mengidentifikasi fungsi masalah!

Profiler

Selanjutnya, saya akan memberikan ringkasan umum tentang profiler yang dibahas dalam artikel ini ( dari sini ). Saya akan menjelaskan istilah yang digunakan dalam artikel ini ( setitimer , rb_add_event_hook , ptrace ) nanti. Menariknya, semua profiler diimplementasikan menggunakan sekumpulan kecil fitur dasar.

Profiler Python

"Peretasan Gdb" sebenarnya bukan profiler Python - ini menautkan ke situs web yang menjelaskan cara menerapkan profiler peretas sebagai pembungkus skrip shell di sekitar gdb . Ini secara khusus tentang Python, karena versi gbd yang lebih baru akan benar - benar menerapkan tumpukan Python untuk Anda. Sesuatu seperti pyflame untuk orang miskin.

Profiler Ruby

Hampir semua profiler ini hidup di dalam proses Anda

Sebelum kita membahas detail profiler ini, ada satu hal yang sangat penting - semua profiler ini, kecuali pyflame , dijalankan di dalam proses Python / Ruby Anda. Jika Anda berada di dalam program Python / Ruby, Anda biasanya memiliki akses mudah ke stack. Misalnya, berikut adalah program Python sederhana yang mencetak konten dari tumpukan setiap utas yang berjalan:

import sys
import traceback

def bar():
    foo()

def foo():
    for _, frame in sys._current_frames().items():
        for line in traceback.extract_stack(frame):
            print line

bar()

Berikut adalah keluaran konsol. Anda dapat melihat bahwa ia memiliki nama fungsi dari tumpukan, nomor baris, nama file - apa pun yang Anda perlukan jika Anda membuat profil.

('test2.py', 12, '<module>', 'bar()')
('test2.py', 5, 'bar', 'foo()')
('test2.py', 9, 'foo', 'for line in traceback.extract_stack(frame):')

Ini bahkan lebih sederhana di Ruby: Anda dapat menggunakan put pemanggil untuk mendapatkan stack.

Sebagian besar profiler ini adalah ekstensi kinerja C, sehingga sedikit berbeda, tetapi ekstensi tersebut untuk program Ruby / Python juga memiliki akses mudah ke tumpukan panggilan.

Cara kerja tracing profiler

Saya telah mencantumkan semua profil penelusuran Ruby dan Python pada tabel di atas: rblineprof, ruby-prof, line_profiler dan cProfile . Mereka semua bekerja dengan cara yang sama. Mereka merekam setiap panggilan fungsi dan merupakan ekstensi C untuk mengurangi overhead.

Bagaimana mereka bekerja? Di Ruby dan Python, Anda bisa menentukan callback yang dipicu ketika berbagai peristiwa interpreter terjadi (misalnya, "panggilan fungsi" atau "baris eksekusi kode"). Saat dipanggil, callback akan menulis tumpukan untuk analisis nanti.

Sangat membantu untuk melihat dengan tepat di mana callback ini berada dalam kode, jadi saya akan menautkan ke baris kode yang relevan di github.

Dengan Python, Anda dapat menyesuaikan callback dengan PyEval_SetTraceatau PyEval_SetProfile. Ini dijelaskan di bagian dokumentasiProfiling dan Tracing dengan Python. Ia mengatakan " PyEval_SetTracemirip dengan PyEval_SetProfilekecuali bahwa fungsi jejak menerima peristiwa nomor baris."

Kode:

line_profilermengatur panggilan baliknya menggunakan PyEval_SetTrace: lihat line_profiler.pyxbaris 157
cProfilemenyiapkan callbacknya menggunakan PyEval_SetProfile: lihat _lsprof.c baris 693 (cProfile diimplementasikan menggunakan lsprof )

Di Ruby, Anda dapat menyesuaikan panggilan balik Anda dengan rb_add_event_hook. Saya tidak dapat menemukan dokumentasi apa pun tentangnya, tetapi seperti inilah tampilannya.

rb_add_event_hook(prof_event_hook,
      RUBY_EVENT_CALL | RUBY_EVENT_RETURN |
      RUBY_EVENT_C_CALL | RUBY_EVENT_C_RETURN |
      RUBY_EVENT_LINE, self);

Tanda tangan prof_event_hook:

static void
prof_event_hook(rb_event_flag_t event, VALUE data, VALUE self, ID mid, VALUE klass)

Sesuatu seperti PyEval_SetTracedi Python, tetapi dalam bentuk yang lebih fleksibel - Anda dapat memilih acara mana yang ingin Anda beri tahu (misalnya, "hanya panggilan fungsi").

Kode:

ruby-prof rb_add_event_hook : ruby-prof.c 329
rblineprof rb_add_event_hook : rblineprof.c 649

tracing-

Kerugian utama dari tracing profiler yang diimplementasikan dengan cara ini adalah mereka menambahkan sejumlah kode tetap untuk setiap panggilan fungsi / baris yang dijalankan. Itu bisa membuat Anda membuat keputusan yang salah! Misalnya, jika Anda memiliki dua implementasi untuk sesuatu - satu dengan banyak panggilan fungsi dan yang lainnya tanpa, yang biasanya membutuhkan waktu yang sama, maka implementasi pertama dengan banyak panggilan fungsi akan tampak lebih lambat saat membuat profil.

Untuk mengilustrasikan, saya membuat file kecil bernama test.pydengan konten berikut dan membandingkan waktu eksekusi python -mcProfile test.pydan python test.py. python. test.pyselesai dalam waktu sekitar 0,6 detik, dan dalam waktu python -mcProfile test.pysekitar 1 detik. Jadi untuk contoh khusus ini saya cProfilemenambahkan overhead ekstra ~ 60%.

Dokumentasinya cProfilemengatakan:

Sifat Python yang diinterpretasikan menambahkan begitu banyak run-time overhead sehingga pembuatan profil deterministik cenderung menambahkan sedikit overhead pemrosesan dalam aplikasi normal.

Ini sepertinya pernyataan yang cukup masuk akal - contoh sebelumnya (yang membuat 3,5 juta panggilan fungsi dan tidak ada yang lain) jelas bukan program Python biasa, dan hampir semua program lain akan memiliki lebih sedikit overhead.

Saya belum memeriksa ruby-proftracing profiler Ruby, tetapi README-nya mengatakan yang berikut:

Kebanyakan program akan berjalan sekitar dua kali lebih lambat, sementara program yang sangat rekursif (seperti tes seri Fibonacci) akan berjalan tiga kali lebih lambat .

Cara kerja sampling profiler secara umum: setitimer

Saatnya berbicara tentang jenis kedua profiler: profiler pengambilan sampel!

Sebagian besar sampling profiler di Ruby dan Python diimplementasikan menggunakan panggilan sistem setitimer. Apa itu?

Katakanlah Anda ingin mengambil snapshot dari tumpukan program 50 kali per detik. Hal ini dapat dilakukan sebagai berikut:

Minta kernel Linux untuk mengirimi Anda sinyal setiap 20 milidetik (menggunakan panggilan sistem setitimer);
Daftarkan penangan sinyal untuk snapshot tumpukan ketika sinyal diterima;
Saat pembuatan profil selesai, minta Linux untuk berhenti memberi sinyal kepada Anda dan berikan hasilnya!

Jika Anda ingin melihat kasus penggunaan praktis setitimeruntuk mengimplementasikan profiler pengambilan sampel, saya pikir stacksampler.pycontoh terbaik adalah profiler yang berguna dan berfungsi, dan ini adalah sekitar 100 baris dengan Python. Dan ini sangat keren!

Alasan stacksampler.pyhanya membutuhkan 100 baris dengan Python adalah karena ketika Anda mendaftarkan fungsi Python sebagai penangan sinyal, fungsi tersebut diteruskan ke tumpukan program Anda saat ini. Oleh karena itu, stacksampler.pysangat mudah untuk mendaftarkan penangan sinyal :

def _sample(self, signum, frame):
   stack = []
   while frame is not None:
       stack.append(self._format_frame(frame))
       frame = frame.f_back

   stack = ';'.join(reversed(stack))
   self._stack_counts[stack] += 1

Ini hanya memunculkan tumpukan dari bingkai dan menambah berapa kali tumpukan tertentu telah dilihat. Sangat sederhana! Keren abis!

Mari kita lihat semua profiler lain yang mereka gunakan setitimerdan cari tahu di bagian mana dalam kode yang mereka panggil setitimer:

stackprof (Ruby): stackprof.c 118
perftools.rb (Ruby): , , , , gem (?)
stacksampler (Python): stacksampler.py 51
statprof (Python): statprof.py 239
vmprof (Python): vmprof_unix.c 294

Hal penting tentang setitimer- Anda perlu memutuskan bagaimana menghitung waktu. Apakah Anda ingin waktu nyata 20ms? Waktu cpu pengguna 20ms? 20ms pengguna + waktu cpu sistem? Jika Anda mencermati tautan di atas, Anda akan melihat bahwa pembuat profil ini sebenarnya menggunakan hal yang berbeda setitimer- terkadang perilakunya dapat disesuaikan dan terkadang tidak. Halaman manual setitimerpendek dan layak dibaca untuk semua kemungkinan konfigurasi. menunjukkan satu kasus penggunaan yang menarik

@mgedmindi Twittersetitimer . Ini masalah dan ini masalah mengungkapkan rincian lebih lanjut.

Satu kelemahan MENARIK berdasarkan profilersetitimer- timer apa yang memicu sinyal! Sinyal terkadang mengganggu panggilan sistem! Panggilan sistem terkadang membutuhkan waktu beberapa milidetik! Jika Anda mengambil snapshot terlalu sering, Anda dapat membuat program menjalankan panggilan sistem tanpa batas!

Pengambilan sampel profiler yang tidak menggunakan setitimer

Ada beberapa profiler pengambilan sampel yang tidak menggunakan setitimer:

pyinstrumentmenggunakan PyEval_SetProfile(jadi ini semacam tracing profiler), tetapi tidak selalu mengumpulkan snapshot tumpukan saat menjalankan callback pelacakan. Berikut adalah kode yang mengambil waktu snapshot stack trace . Baca lebih lanjut tentang solusi ini di blog ini . (pada dasarnya: setitimermemungkinkan Anda untuk membuat profil hanya utas utama dengan Python)
pyflameprofil kode Python di luar proses menggunakan panggilan sistem ptrace. Dia menggunakan loop di mana dia mengambil gambar, tidur untuk jangka waktu tertentu dan melakukan hal yang sama lagi. Ini panggilan untuk menunggu.
python-flamegraphmengambil pendekatan serupa di mana ia memulai utas baru dalam proses Python Anda dan mendapatkan pelacakan tumpukan, tidur, dan coba ulang lagi. Ini panggilan untuk menunggu .

Ketiga profiler ini mengambil snapshot waktu nyata.

Posting blog Pyflame

Saya telah menghabiskan hampir seluruh waktu saya dalam posting ini di luar profiler pyflame, tetapi sebenarnya itulah yang paling menarik bagi saya karena profil program Python Anda dari proses terpisah, itulah sebabnya saya ingin profiler Ruby saya bekerja dengan cara yang sama.

Tentu saja, semuanya sedikit lebih rumit dari yang saya jelaskan. Saya tidak akan menjelaskan secara detail, tetapi Evan Klitzke telah menulis banyak artikel bagus tentang ini di blognya:

Pyflame: Profiler Ptracing dari Uber Engineering untuk Python - Pengantar pyflame
Pyflame Dual Interpreter Mode - Bagaimana ini mendukung Python 2 dan Python 3 secara bersamaan
Perubahan ABI Python yang Tidak Terduga - tentang menambahkan dukungan untuk Python 3.6;
Membuang Tumpukan Python Multi-Thread ;
Paket Pyflame ;
ptrace dan panggilan sistem dengan Python;
Menggunakan ptrace untuk kesenangan dan keuntungan, ptrace (lanjutan) ;

Informasi lebih lanjut dapat ditemukan di eklitzke.org . Ini semua adalah hal yang sangat menarik yang akan saya baca lebih dekat - mungkin ini ptraceakan menjadi lebih baik daripada process_vm_readvmengimplementasikan profiler Ruby! Ini memiliki process_vm_readvlebih sedikit overhead karena tidak menghentikan proses, tetapi juga dapat memberi Anda snapshot yang salah karena tidak menghentikan proses :). Dalam eksperimen saya, mendapatkan gambar yang bertentangan bukanlah masalah besar, tetapi saya rasa di sini saya akan melakukan serangkaian eksperimen.

Sekian untuk hari ini!

Ada banyak seluk-beluk penting yang tidak saya bahas dalam posting ini - misalnya, saya pada dasarnya mengatakan itu vmprofdan stacksampler- serupa (mereka tidak -vmprofmendukung pembuatan profil string dan pembuatan profil fungsi Python yang ditulis dalam C, yang menurut saya membuat profiler lebih kompleks). Tetapi mereka memiliki beberapa prinsip dasar yang sama, jadi saya pikir ulasan hari ini akan menjadi titik awal yang baik.

TDD dengan dan tanpa pytest. Webinar gratis

Bagaimana cara kerja profiler di Ruby dan Python?