1s hingga 10ms: Mengurangi Penundaan Prometheus di API Gateway

Permintaan dengan Penundaan 1 hingga 2 Detik

Di komunitas APISIX, pengguna melaporkan fenomena misterius: ketika permintaan lalu lintas masuk ke kluster APISIX yang telah dideploy secara normal, sejumlah kecil permintaan mengalami penundaan yang sangat lama, yaitu 1 hingga 2 detik. Skala QPS pengguna sekitar 10.000, dan permintaan abnormal seperti ini jarang terjadi, hanya muncul 1 hingga 3 kali setiap beberapa menit.

Pengguna memberikan tangkapan mereka tentang permintaan dengan latensi tinggi dalam beberapa issue. Dari tangkapan layar tersebut, terlihat bahwa memang ada permintaan dengan latensi tinggi, bahkan beberapa bisa mencapai level detik.

High Latency Requests 1.png

High Latency Requests 2.png

Fenomena lain yang menyertai ini adalah: salah satu worker process menggunakan CPU hingga 100%.

100% CPU.png

Tim pengembangan mempelajari kondisi terjadinya fenomena ini:

Plugin Prometheus diaktifkan, dan Prometheus Exporter mengakses endpoint APISIX /apisix/prometheus/metrics untuk mengumpulkan metrik.
Jumlah metrik yang dihitung oleh plugin Prometheus mencapai skala tertentu, biasanya puluhan ribu.

Fenomena ini disebut "long tail requests" dalam industri. Ini merujuk pada situasi ketika sebagian kecil permintaan memiliki waktu respons yang sangat lama, sementara sebagian besar permintaan memiliki waktu respons yang normal dalam kelompok permintaan. Hal ini bisa disebabkan oleh kemacetan kinerja di sistem backend, sumber daya yang tidak mencukupi, atau alasan lainnya. Ini bukan bug yang fatal, tetapi sangat memengaruhi pengalaman pengguna akhir.

Memecah Masalah

Berdasarkan pustaka Lua sumber terbuka nginx-lua-prometheus, APISIX telah mengembangkan plugin Prometheus yang menyediakan fungsi untuk melacak dan mengumpulkan metrik. Ketika Prometheus Exporter mengakses endpoint metrik Prometheus yang diekspos oleh APISIX, APISIX akan memanggil fungsi yang disediakan oleh pustaka nginx-lua-prometheus untuk mengekspos hasil perhitungan metrik.

Tim pengembangan menemukan masalah: fungsi prometheus:metric_data() yang digunakan untuk mengekspos indikator metrik di nginx-lua-prometheus.

Namun, ini hanya kesimpulan awal, dan diperlukan bukti langsung untuk membuktikan bahwa long tail requests terkait dengan ini, serta beberapa masalah berikut perlu dijelaskan:

Apa sebenarnya yang dilakukan fungsi ini?
Mengapa fungsi ini menyebabkan long tail requests?

Tim pengembangan membangun lingkungan lokal untuk mereproduksi masalah, yang terutama mensimulasikan skenario berikut:

Klien simulasi mengirim permintaan normal yang diproksi ke upstream oleh APISIX.
Mensimulasikan Prometheus Exporter mengunjungi /apisix/prometheus/metrics setiap 5 detik, memicu APISIX untuk memanggil fungsi prometheus:metric_data().

Lingkungan yang Direproduksi:

Reproduced Environment.png

Saat melakukan pengujian, kami mengamati P100 dan indikator lainnya dalam hasil pengujian wrk2 untuk memastikan apakah ada fenomena long tail request. Kami menghasilkan flame graph APISIX untuk mengamati penggunaan CPU saat long tail request terjadi.

Hasil pengujian dari wrk2:

  Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
   50.000%    1.13ms
   75.000%    2.56ms
   90.000%    4.82ms
   99.000%   14.70ms
   99.900%   27.95ms
   99.990%   74.75ms
   99.999%  102.78ms
  100.000%  102.78ms

Berdasarkan hasil pengujian ini, dapat disimpulkan bahwa selama pengujian, 99% permintaan selesai dalam 14,70 milidetik, dan sejumlah kecil permintaan memakan waktu lebih dari 100 milidetik. Kami menggunakan jumlah metrik sebagai variabel untuk melakukan beberapa pengujian, dan menemukan bahwa jumlah metrik meningkat secara linear dengan penundaan P100. Jika metrik mencapai level 100.000, P100 akan mencapai level detik.

Flame graph yang dihasilkan:

Flame Graph1.png

Seperti yang terlihat dari function stack pada flame graph, prometheus:metric_data() menempati lebar horizontal terpanjang, membuktikan banyaknya konsumsi CPU, dan secara langsung menentukan bahwa prometheus:metric_data() menyebabkan long tail requests.

Mari kita menganalisis secara singkat apa yang dilakukan fungsi prometheus:metric_data().

prometheus:metric_data() akan mengambil metrik dari memori bersama, mengkategorikannya, dan memprosesnya menjadi format teks yang kompatibel dengan Prometheus. Dalam proses ini, semua metrik akan diurutkan secara leksikografis, dan awalan metrik akan diproses dengan ekspresi reguler. Secara empiris, operasi ini sangat mahal.

Upaya Optimasi yang Tidak Sempurna

Setelah kami menemukan kode yang menyebabkan penundaan, langkah selanjutnya adalah menggabungkan flame graph untuk menganalisis kode secara detail dan menemukan ruang untuk optimasi.

Dari flame graph, kami menemukan fungsi fix_histogram_bucket_labels. Setelah meninjau fungsi ini, kami menemukan dua fungsi sensitif: string:match dan string:gusb. Kedua fungsi ini tidak dapat dikompilasi JIT oleh LuaJIT. Mereka hanya dapat diinterpretasikan dan dieksekusi.

LuaJIT adalah kompiler JIT untuk bahasa pemrograman Lua, yang dapat mengkompilasi kode Lua menjadi kode mesin dan menjalankannya. Ini dapat memberikan kinerja yang lebih tinggi daripada menggunakan interpreter untuk menjalankan kode Lua.

Salah satu keuntungan menggunakan LuaJIT untuk menjalankan kode Lua adalah dapat meningkatkan kecepatan eksekusi kode secara signifikan. Ini memungkinkan APISIX untuk mempertahankan latensi rendah saat memproses sejumlah besar permintaan, dan berkinerja lebih baik dalam lingkungan dengan konkurensi tinggi.

Oleh karena itu, kode yang tidak dapat dikompilasi oleh LuaJIT akan menjadi potensi kemacetan kinerja.

Kami mengumpulkan informasi di atas dan mengirimkan issue: optimize the long tail request phenomenon ke nginx-lua-prometheus, di mana kami terhubung dengan penulis Knyar dari proyek ini dan mengeksplorasi ruang yang dapat dioptimasi. Knyar merespons dengan cepat, dan kami menjelaskan tempat-tempat yang dapat dioptimasi. Jadi, sebuah PR diajukan: chore: use ngx.re.match instead of string match to improve performance untuk optimasi.

Dalam PR ini, kami terutama menyelesaikan:

Menggunakan ngx.re.match sebagai ganti string:match
Mengganti string:gusb dengan ngx.re.gsub

Setelah menyelesaikan optimasi ini, kami tahu bahwa peningkatan kinerja yang dihasilkan terbatas, tidak dapat menyelesaikan masalah secara fundamental. Masalah utamanya adalah:

NGINX adalah arsitektur multi-proses dengan satu thread. Semua worker process akan memantau koneksi TCP (Transmission Control Protocol), tetapi begitu koneksi masuk ke worker process, koneksi tersebut tidak dapat dipindahkan ke worker process lain untuk diproses.

Ini berarti jika sebuah worker process sangat sibuk, koneksi lain dalam worker process tersebut mungkin tidak diproses tepat waktu. Di sisi lain, model single-threaded dalam sebuah proses berarti semua tugas yang intensif CPU dan IO harus dilakukan secara berurutan. Jika sebuah tugas membutuhkan waktu lama untuk dieksekusi, tugas lain mungkin diabaikan, mengakibatkan waktu pemrosesan tugas yang tidak merata.

prometheus:metric_data() mengambil banyak time slice CPU untuk perhitungan, memeras sumber daya CPU untuk memproses permintaan normal. Inilah mengapa Anda melihat worker process menggunakan CPU hingga 100%.

Berdasarkan masalah ini, kami terus menganalisis setelah menyelesaikan optimasi di atas, dan menangkap flame graph:

Flame Graph2.png

Flame graph di atas builtin#100 mewakili fungsi pustaka luajit/lua (seperti string.find), yang dapat diakses melalui https://github.com/openresty/openresty-devel-utils/blob/master/ljff.lua di proyek ini untuk mendapatkan nama fungsi yang sesuai.

Cara penggunaan:

$ luajit ljff.lua 100
FastFunc table.sort

Karena perhitungan metrik mengambil terlalu banyak CPU, kami mempertimbangkan untuk melepaskan time slice CPU saat menghitung metrik.

Untuk APISIX, prioritas memproses permintaan normal adalah yang tertinggi, dan sumber daya CPU harus condong ke arah ini. Pada saat yang sama, prometheus:metric_data() hanya akan memengaruhi efisiensi pengambilan metrik Prometheus Exporter.

Di dunia OpenResty, ada cara tersembunyi untuk melepaskan time slice CPU: ngx.sleep(0). Kami memperkenalkan metode ini dalam prometheus:metric_data(). Saat memproses metrik, kami akan melepaskan time slice CPU setelah memproses sejumlah metrik tertentu (misalnya, 200 metrik) sehingga permintaan baru yang masuk memiliki kesempatan untuk diproses.

Kami mengajukan PR untuk optimasi ini: feat: performance optimization.

Dalam skenario pengujian kami, ketika total metrik mencapai level 100.000, hasil yang diperoleh dengan pengujian menggunakan wrk2 sebelum memperkenalkan optimasi ini:

  Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
 50.000%   10.21ms
 75.000%   12.03ms
 90.000%   13.25ms
 99.000%   92.80ms
 99.900%  926.72ms
 99.990%  932.86ms
 99.999%  934.40ms
100.000%  934.91ms

Hasil wrk2 setelah optimasi:

  Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
 50.000%    4.34ms
 75.000%   12.81ms
 90.000%   16.12ms
 99.000%   82.75ms
 99.900%  246.91ms
 99.990%  349.44ms
 99.999%  390.40ms
100.000%  397.31ms

Indeks P100 sekitar 1/3 hingga 1/2 dari sebelum optimasi.

Namun, ini tidak menyelesaikan masalah ini dengan sempurna. Dengan menganalisis flame graph yang dioptimasi:

Flame Graph After Optimization.png

Anda dapat melihat bahwa builtin#100 (table.sort) dan builtin#92 (string.format) masih menempati lebar horizontal yang cukup besar karena:

prometheus:metric_data() akan pertama kali memanggil table.sort untuk mengurutkan semua metrik. Ketika metrik mencapai level 100.000, itu setara dengan mengurutkan 100.000 string, dan table.sort tidak dapat diinterupsi oleh ngx.sleep(0).
Tempat di mana string.format dan fix_histogram_bucket_labels digunakan tidak dapat dioptimasi. Setelah berkomunikasi dengan knyar, saya mengetahui bahwa langkah-langkah ini diperlukan untuk memastikan bahwa prometheus:metric_data() dapat menghasilkan metrik dalam format yang benar.

Sejauh ini, metode optimasi pada level kode telah habis, tetapi sayangnya, masalah masih belum terselesaikan dengan sempurna. Masih ada lag yang terlihat pada metrik P100.

Apa yang Harus Dilakukan?

Mari kita kembali ke masalah inti: prometheus:metric_data() mengambil banyak time slice CPU untuk perhitungan, memeras sumber daya CPU untuk memproses permintaan normal.

Dalam sistem Linux, time slice yang dialokasikan CPU adalah untuk thread atau process? Secara tepat, itu adalah thread, dan thread adalah unit kerja yang sebenarnya. Namun, NGINX adalah arsitektur multi-proses dengan satu thread, dengan hanya satu thread di setiap proses.

Pada titik ini kami memikirkan arah optimasi: memindahkan prometheus:metric_data() ke thread lain (atau, lebih tepatnya, proses). Jadi kami menyelidiki dua arah:

Menggunakan ngx.run_worker_thread untuk menjalankan tugas perhitungan prometheus:metric_data(), setara dengan menyerahkan tugas intensif CPU ke thread pool.
Menggunakan proses terpisah untuk menangani tugas perhitungan prometheus:metric_data(), proses ini tidak akan menangani permintaan normal.

Setelah PoC (proof of concept), kami menolak opsi 1 dan mengadopsi opsi 2. Opsi 1 ditolak karena ngx.run_worker_thread hanya cocok untuk menjalankan tugas komputasi yang tidak terkait dengan permintaan, sementara prometheus:metric_data() terkait dengan permintaan.

Implementasi opsi 2: Biarkan privileged agent (proses istimewa) menangani prometheus:metric_data(). Tetapi proses istimewa tidak mendengarkan port apa pun atau menangani permintaan apa pun. Oleh karena itu, kami perlu memodifikasi proses istimewa sehingga dapat mendengarkan port.

Akhirnya, kami menggunakan feat: allow privileged agent to listen port dan feat(prometheus): support collect metrics works in the privileged agent untuk mengimplementasikan opsi 2.

Kami menggunakan APISIX dengan optimasi ini untuk menguji, dan menemukan bahwa indeks penundaan P100 telah berkurang ke kisaran yang wajar, dan masalah long tail requests tidak ada lagi.

  Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
 50.000%    3.74ms
 75.000%    4.66ms
 90.000%    5.77ms
 99.000%    9.99ms
 99.900%   13.41ms
 99.990%   16.77ms
 99.999%   18.38ms
100.000%   18.40ms

Ini adalah solusi yang cermat dan menyelesaikan masalah inti. Kami mengamati dan memverifikasi solusi ini di lingkungan produksi. Ini menghilangkan fenomena long tail request, dan tidak menyebabkan pengecualian tambahan.

Kesimpulan

Ketika kami memperbaiki masalah ini, muncul pemikiran baru: apakah pustaka sumber terbuka nginx-lua-prometheus cocok untuk APISIX?

Kami menyelesaikan masalah prometheus:metric_data() di sisi APISIX. Pada saat yang sama, kami juga menemukan masalah lain di nginx-lua-prometheus dan memperbaikinya. Seperti fix memory leak, dan LRU cache elimination.

nginx-lua-prometheus awalnya dirancang untuk NGINX, bukan untuk OpenResty dan aplikasi berbasis OpenResty. Namun, tidak ada proyek sumber terbuka di ekosistem OpenResty yang terhubung ke ekosistem Prometheus lebih matang daripada nginx-lua-prometheus. Oleh karena itu, nginx-lua-prometheus terus dipromosikan oleh komunitas sumber terbuka untuk ekosistem OpenResty.

Mungkin kita harus menjelajahi lebih banyak dan menemukan cara untuk terhubung ke ekosistem Prometheus tanpa memodifikasi kode sumber APISIX. Misalnya, merancang pustaka dependensi yang lebih cocok untuk APISIX, atau terhubung ke proyek matang di ekosistem Prometheus dengan cara tertentu, dan memindahkan proses pengumpulan dan perhitungan metrik ke proyek-proyek matang tersebut.