Memecahkan masalah latensi di library klien Java

Pengantar

Jika aplikasi Anda mengalami latensi yang lebih tinggi dari biasanya, throughput yang buruk, atau waktu tunggu habis dengan klien Java Datastore, masalahnya mungkin berasal dari konfigurasi gRPC sisi klien, bukan backend Firestore/Datastore. Panduan ini akan membantu mendiagnosis dan menyelesaikan masalah throttling sisi klien umum, setelan kumpulan saluran yang tidak tepat, dan churn saluran yang berlebihan.

Diagnosis

Saat menggunakan klien Java, mengaktifkan logging gRPC dan gax-java verbose sangat penting untuk memantau dinamika kumpulan saluran, mendiagnosis pembatasan, masalah penggunaan ulang koneksi, atau mengidentifikasi churn saluran yang berlebihan.

Mengaktifkan logging untuk klien Java

Untuk mengaktifkan logging mendetail, ubah file logging.properties sebagai berikut:

## This tracks the lifecycle events of each grpc channel 
io.grpc.ChannelLogger.level=FINEST
## Tracks channel pool events(resizing, shrinking) from GAX level
com.google.api.gax.grpc.ChannelPool.level=FINEST

Selain itu, perbarui tingkat logging output di logging.properties untuk merekam log ini:


# This could be changed to a file or other log output
handlers=java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level=FINEST
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter

Terapkan konfigurasi:

File logging.properties dapat diterapkan menggunakan salah satu dari dua metode:

1. Melalui Properti Sistem JVM

Tambahkan argumen ini saat memulai aplikasi Java:

-Djava.util.logging.config.file=/path/to/logging.properties

2. Memuat Secara Terprogram

Metode ini berguna untuk pengujian integrasi atau aplikasi yang konfigurasi logging-nya dikelola dalam kode. Pastikan kode ini berjalan lebih awal dalam siklus proses aplikasi.

LogManager logManager = LogManager.getLogManager();
  try (final InputStream is = Main.class.getResourceAsStream("/logging.properties")) {
logManager.readConfiguration(is);
}

Contoh logging

Setelah mengaktifkan logging verbose, Anda akan melihat campuran pesan dari com.google.api.gax.grpc.ChannelPool dan io.grpc.ChannelLogger:

Channel yang kurang disediakan yang memicu perluasan kumpulan channel:

09:15:30.123 [pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 40, expanding channel pool size: 4 -> 6. 
09:15:30.124 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] Entering IDLE state 
09:15:30.124 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] Entering IDLE state 
09:15:30.125 [grpc-nio-worker-ELG-1-5] TRACE io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] newCall() called 
09:15:30.126 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] Entering CONNECTING state 09:15:30.127 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] Entering READY state with picker: Picker{result=PickResult{subchannel=Subchannel<7>: (datastore.googleapis.com:443), streamTracerFactory=null, status=Status{code=OK, description=null, cause=null}, drop=false, authority-override=null}} 
09:15:31.201 [grpc-nio-worker-ELG-1-6] TRACE io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] newCall() called 
09:15:31.202 [grpc-nio-worker-ELG-1-6] DEBUG io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] Entering CONNECTING state 09:15:31.203 [grpc-nio-worker-ELG-1-6] DEBUG io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] Entering READY state with picker: Picker{result=PickResult{subchannel=Subchannel<8>: (datastore.googleapis.com:443), streamTracerFactory=null, status=Status{code=OK, description=null, cause=null}, drop=false, authority-override=null}}

Channel yang terlalu banyak disediakan sehingga memicu penyusutan kumpulan channel:

09:13:59.609 [grpc-nio-worker-ELG-1-4] DEBUG io.grpc.ChannelLogger - [Channel<21>: (datastore.googleapis.com:443)] Entering READY state with picker: Picker{result=PickResult{subchannel=Subchannel<23>: (datastore.googleapis.com:443), streamTracerFactory=null, status=Status{code=OK, description=null, cause=null}, drop=false, authority-override=null}}
09:14:01.998 [pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput drop to 0, shrinking channel pool size: 8 -> 6.
09:14:01.999 [pool-1-thread-1] TRACE io.grpc.ChannelLogger - [Channel<13>: (datastore.googleapis.com:443)] shutdown() called
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<13>: (datastore.googleapis.com:443)] Entering SHUTDOWN state
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<13>: (datastore.googleapis.com:443)] Terminated
09:14:01.999 [pool-1-thread-1] TRACE io.grpc.ChannelLogger - [Channel<15>: (datastore.googleapis.com:443)] shutdown() called
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<15>: (datastore.googleapis.com:443)] Entering SHUTDOWN state
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<15>: (datastore.googleapis.com:443)] Terminated

Entri log ini berguna untuk:

  1. Memantau Keputusan Pengubahan Ukuran Channel
  2. Mengidentifikasi Penggunaan Ulang Channel vs. Churn
  3. Mendeteksi Masalah Konektivitas Transportasi

Menafsirkan log untuk mendiagnosis gejala

Saat memecahkan masalah performa seperti latensi tinggi atau error, mulailah dengan mengaktifkan logging untuk com.google.api.gax.grpc.ChannelPool dan io.grpc.ChannelLogger. Kemudian, cocokkan gejala yang Anda amati dengan skenario umum dalam panduan ini untuk menafsirkan log dan menemukan solusi.

Gejala 1: Latensi tinggi saat startup atau selama lonjakan traffic

Anda mungkin mendapati bahwa beberapa permintaan pertama setelah aplikasi Anda dimulai berjalan lambat, atau latensi meningkat secara drastis setiap kali traffic tiba-tiba meningkat.

Kemungkinan penyebab

Latensi ini sering terjadi saat kumpulan channel Anda kurang disediakan. Setiap channel gRPC dapat menangani sejumlah permintaan serentak yang terbatas (100 dibatasi oleh Middleware Google). Setelah batas ini tercapai, RPC baru akan diantrekan di sisi klien, menunggu slot yang tersedia. Antrean ini adalah sumber utama latensi.

Meskipun kumpulan saluran dirancang untuk beradaptasi dengan perubahan beban, logika pengubahan ukurannya berjalan secara berkala (secara default, setiap menit) dan diperluas secara bertahap (secara default, menambahkan paling banyak 2 saluran dalam satu waktu). Oleh karena itu, ada penundaan inheren antara lonjakan traffic awal dan perluasan kumpulan. Latensi akan terjadi selama periode ini, sementara permintaan baru menunggu hingga saluran yang penuh dibersihkan atau hingga pool menambahkan saluran baru dalam siklus pengubahan ukurannya berikutnya.

Log yang harus dicari

Cari log yang menunjukkan bahwa kumpulan channel sedang diperluas. Ini adalah bukti utama bahwa klien bereaksi terhadap lonjakan traffic yang telah melampaui kapasitasnya saat ini.

Log Perluasan Kumpulan Channel:

[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 40, expanding channel pool size: 4 -> 6.

Interpretasi: Kumpulan telah mendeteksi lonjakan traffic dan membuka koneksi baru untuk menangani peningkatan beban. Perluasan yang sering, terutama saat startup, adalah tanda jelas bahwa konfigurasi awal Anda tidak cukup untuk beban kerja umum Anda.

Cara mengatasi

Tujuannya adalah menyiapkan cukup banyak channel sebelum traffic tiba, sehingga klien tidak perlu membuat channel dalam kondisi tertekan.

Meningkatkan initialChannelCount (Latensi Tinggi saat Pengaktifan):

Jika Anda melihat latensi tinggi saat startup, solusi yang paling efektif adalah meningkatkan initialChannelCount di ChannelPoolSettings. Secara default, nilai ini ditetapkan ke 10, yang mungkin terlalu rendah untuk aplikasi yang menangani traffic signifikan saat startup.

Untuk menemukan nilai yang tepat bagi aplikasi, Anda harus:

  1. Aktifkan logging tingkat FINEST untuk com.google.api.gax.grpc.ChannelPool.
  2. Jalankan aplikasi Anda di bawah beban kerja awal atau lonjakan traffic yang umum.
  3. Amati log ekspansi kumpulan saluran untuk melihat ukuran stabil kumpulan tersebut.

Misalnya, jika Anda melihat log seperti ini:
[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 80, expanding channel pool size: 4 -> 6.

dan satu menit kemudian, Anda akan melihat log:

[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 95, expanding channel pool size: 6 -> 8.

Jika Anda melihat ukuran kumpulan saluran yang diperluas distabilkan pada 8 saluran dan tidak ada lagi log yang diperluas, hal ini menunjukkan bahwa aplikasi Anda memerlukan 8 saluran untuk menangani workload-nya. Titik awal yang baik adalah dengan menyetel initialChannelCount Anda ke 8. Hal ini memastikan koneksi dibuat di awal, sehingga mengurangi atau menghilangkan latensi yang disebabkan oleh penskalaan secara langsung.

Tujuannya adalah untuk memastikan pool memiliki kapasitas yang cukup untuk menangani beban puncak tanpa mengantrekan permintaan.

Peningkatan minChannelCount (Lonjakan traffic):

Jika Anda mengalami latensi tinggi, khususnya di awal lonjakan traffic, hal ini menandakan bahwa traffic Anda meningkat lebih cepat daripada kemampuan kumpulan channel untuk membuat koneksi baru secara reaktif. Hal ini umum terjadi pada aplikasi dengan lonjakan traffic yang dapat diprediksi dan tiba-tiba.

Kumpulan ini distabilkan dengan sejumlah kecil saluran selama traffic normal dan secara proaktif menambahkan lebih banyak saluran saat traffic meningkat untuk mencegah saturasi. Proses penskalaan ini memerlukan waktu, sehingga permintaan awal dalam lonjakan akan diantrekan, yang mengakibatkan latensi tinggi.

Meningkatkan minChannelCount menetapkan dasar pengukuran yang lebih tinggi untuk channel yang selalu buka. Hal ini memastikan bahwa kapasitas yang cukup sudah tersedia untuk menangani lonjakan awal, sehingga menghilangkan penundaan penskalaan dan lonjakan latensi terkait.

Peningkatan maxChannelCount (Lonjakan traffic):

Jika Anda mengamati latensi tinggi selama lonjakan traffic dan log Anda menunjukkan bahwa pool channel selalu berada pada ukuran maksimumnya (maxChannelCount), batas saat ini kemungkinan terlalu rendah untuk traffic puncak Anda. Secara default, maxChannelCount ditetapkan ke 200. Untuk menentukan nilai yang lebih baik, gunakan panduan konfigurasi kumpulan koneksi untuk menghitung jumlah koneksi optimal berdasarkan Kueri Per Detik (QPS) puncak dan latensi permintaan rata-rata aplikasi Anda.

Gejala 2: Waktu tunggu habis atau kegagalan RPC yang terjadi sesekali

Terkadang, aplikasi berjalan dengan baik hampir sepanjang waktu, tetapi terkadang mengalami timeout terputus-putus, atau RPC gagal, bahkan selama periode traffic normal.

Kemungkinan penyebab: ketidakstabilan jaringan

Koneksi antara klien dan layanan Datastore terputus. Klien gRPC akan mencoba terhubung kembali secara otomatis, tetapi proses ini dapat menyebabkan kegagalan dan latensi sementara.

Log yang harus dicari

Log yang paling penting untuk mendiagnosis masalah jaringan adalah TRANSIENT_FAILURE.

  • Log Kegagalan Sementara:
[grpc-nio-worker-ELG-1-7] DEBUG io.grpc.ChannelLogger - [Channel<9>: (datastore.googleapis.com:443)] Entering TRANSIENT_FAILURE state
  • Interpretasi: Log ini adalah tanda bahaya utama yang menunjukkan bahwa channel telah kehilangan koneksinya. Kegagalan tunggal dan terisolasi mungkin hanya gangguan jaringan kecil. Namun, jika kami sering melihat pesan ini atau channel mengalami masalah ini, berarti ada masalah mendasar yang signifikan.

Cara mengatasi

Selidiki lingkungan jaringan Anda. Periksa masalah pada firewall, proxy, router, atau ketidakstabilan jaringan umum antara aplikasi dan datastore.googleapis.com.

Gejala 3: Latensi tinggi dengan lebih dari 20.000 permintaan serentak per klien

Gejala khusus ini berlaku untuk aplikasi yang berjalan dalam skala yang sangat tinggi, biasanya saat satu instance klien harus menangani lebih dari 20.000 permintaan serentak. Aplikasi ini berperforma baik dalam kondisi normal, tetapi saat traffic meningkat menjadi lebih dari 20.000 permintaan serentak per klien, Anda mengamati penurunan performa yang tajam dan tiba-tiba. Latensi meningkat secara signifikan dan tetap tinggi selama durasi periode traffic puncak. Hal ini terjadi karena pool koneksi klien telah mencapai ukuran maksimumnya dan tidak dapat melakukan penskalaan lebih lanjut.

Kemungkinan penyebab

Klien mengalami saturasi saluran karena pool saluran telah mencapai maxChannelCount yang dikonfigurasi. Secara default, kumpulan ini dikonfigurasi dengan batas 200 saluran. Karena setiap saluran gRPC dapat menangani hingga 100 permintaan serentak, batas ini hanya tercapai saat satu instance klien memproses sekitar 20.000 permintaan secara bersamaan.

Setelah pool mencapai batas ini, pool tidak dapat membuat koneksi lagi. Semua 200 saluran menjadi kelebihan beban, dan permintaan baru diantrekan di sisi klien, sehingga menyebabkan lonjakan latensi yang tajam.

Log berikut dapat membantu mengonfirmasi bahwa maxChannelCount telah tercapai.

Log yang harus dicari

Indikator utamanya adalah mengamati bahwa kumpulan channel berhenti meluas tepat pada batas yang dikonfigurasi, meskipun beban terus berlanjut.

  • Log: Anda akan melihat log sebelumnya dari perluasan kumpulan. Dengan setelan default, log perluasan terakhir yang Anda lihat sebelum lonjakan latensi akan menjadi log saat pool mencapai 200 channel:
[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - ... expanding channel pool size: 198 -> 200.
  • Indikator: Selama periode latensi tinggi, Anda tidak akan melihat lagi log "expanding channel pool size". Tidak adanya log ini, dikombinasikan dengan latensi tinggi, merupakan indikator kuat bahwa batas maxChannelCount telah tercapai.

Cara mengatasi

Tujuannya adalah untuk memastikan pool memiliki kapasitas yang cukup untuk menangani beban puncak tanpa mengantrekan permintaan.

  • Tingkatkan maxChannelCount: Solusi utama adalah meningkatkan setelan maxChannelCount ke nilai yang dapat mendukung traffic puncak aplikasi. Lihat panduan konfigurasi kumpulan koneksi untuk menghitung jumlah koneksi yang optimal berdasarkan Kueri Per Detik (QPS) puncak dan latensi permintaan rata-rata aplikasi.

Lampiran

Bagian berikut memberikan informasi tambahan untuk membantu pemecahan masalah.

Memahami status saluran

Status saluran berikut dapat muncul di log, yang memberikan insight tentang perilaku koneksi:

Negara bagian/Provinsi Deskripsi
IDLE Channel dibuat, tetapi tidak memiliki koneksi atau RPC aktif. Ini menunggu traffic.
MENGHUBUNGKAN Channel sedang aktif mencoba membuat transport jaringan (koneksi) baru ke server gRPC.
SIAP Channel memiliki transport yang stabil dan berfungsi dengan baik serta siap mengirim RPC.
TRANSIENT_FAILURE Saluran mengalami kegagalan yang dapat dipulihkan (misalnya, gangguan jaringan, server tidak tersedia untuk sementara). Perangkat akan otomatis mencoba terhubung kembali.
SHUTDOWN Saluran telah ditutup, baik secara manual (misalnya, shutdown() dipanggil) atau karena waktu tunggu tidak ada aktivitas. Tidak ada RPC baru yang dapat dimulai.

Tips

  • Jika Anda menggunakan framework logging terstruktur seperti SLF4J atau Logback, Anda harus mengonfigurasi tingkat log yang setara di logback.xml atau file konfigurasi logger lainnya. Level java.util.logging akan dipetakan oleh fasad logging.