Latenz in der Java-Clientbibliothek beheben

Einführung

Wenn in Ihrer App eine höhere als die übliche Latenz, ein geringer Durchsatz oder Zeitüberschreitungen mit dem Java Datastore-Client auftreten, liegt das Problem möglicherweise an der clientseitigen gRPC-Konfiguration und nicht am Firestore-/Datastore-Backend. In diesem Leitfaden erfahren Sie, wie Sie häufige Probleme mit clientseitiger Drosselung, falsche Channelpool-Einstellungen und übermäßigen Channel-Churn diagnostizieren und beheben.

Diagnose

Bei der Verwendung von Java-Clients ist es wichtig, das ausführliche gRPC- und gax-java-Logging zu aktivieren, um die Dynamik des Channel-Pools zu überwachen, Drosselungsprobleme, Probleme mit der Wiederverwendung von Verbindungen oder übermäßigen Channel-Churn zu diagnostizieren.

Logging für Java-Clients aktivieren

So aktivieren Sie die detaillierte Protokollierung:logging.properties

## 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

Aktualisieren Sie außerdem die Ausgabelogebene in logging.properties, um diese Logs zu erfassen:


# 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

Wenden Sie die Konfiguration an

Die logging.properties-Datei kann auf zwei Arten angewendet werden:

1. Über eine JVM-Systemeigenschaft

Fügen Sie dieses Argument beim Starten der Java-Anwendung hinzu:

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

2. Programmatisch laden

Diese Methode ist nützlich für Integrationstests oder Anwendungen, bei denen die Protokollierungskonfiguration im Code verwaltet wird. Achten Sie darauf, dass dieser Code früh im Lebenszyklus der Anwendung ausgeführt wird.

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

Beispiel für das Logging

Nachdem Sie das ausführliche Logging aktiviert haben, sehen Sie eine Mischung aus Nachrichten von com.google.api.gax.grpc.ChannelPool und io.grpc.ChannelLogger:

Kanäle mit zu geringer Bereitstellung, die eine Erweiterung des Channel-Pools ausgelöst haben:

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}}

Kanäle mit zu vielen Ressourcen, die eine Verkleinerung des Kanalpools ausgelöst haben:

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

Diese Logeinträge sind nützlich für:

  1. Entscheidungen zur Kanalgrößenanpassung im Blick behalten
  2. Wiederverwendung von Kanälen erkennen Abwanderung
  3. Probleme mit der Transportverbindung erkennen

Logs zur Symptomdiagnose interpretieren

Wenn Sie Leistungsprobleme wie hohe Latenz oder Fehler beheben möchten, aktivieren Sie zuerst die Protokollierung für com.google.api.gax.grpc.ChannelPool und io.grpc.ChannelLogger. Vergleichen Sie dann die beobachteten Symptome mit den häufigen Szenarien in diesem Leitfaden, um die Logs zu interpretieren und eine Lösung zu finden.

Symptom 1: Hohe Latenz beim Start oder während Traffic-Spitzen

Möglicherweise stellen Sie fest, dass die ersten Anfragen nach dem Start Ihrer Anwendung langsam sind oder dass die Latenz bei einem plötzlichen Anstieg des Traffics drastisch zunimmt.

Mögliche Ursache

Diese Latenz tritt häufig auf, wenn Ihr Channel-Pool unterdimensioniert ist. Jeder gRPC-Channel kann eine begrenzte Anzahl gleichzeitiger Anfragen verarbeiten (100, begrenzt durch die Google-Middleware). Sobald dieses Limit erreicht ist, werden neue RPCs clientseitig in die Warteschlange gestellt und warten auf einen verfügbaren Slot. Diese Warteschlange ist die Hauptursache für Latenz.

Der Channelpool ist zwar so konzipiert, dass er sich an Laständerungen anpasst, seine Größenanpassungslogik wird jedoch regelmäßig (standardmäßig jede Minute) ausgeführt und wird schrittweise erweitert (standardmäßig werden jeweils höchstens 2 Channels hinzugefügt). Daher gibt es eine inhärente Verzögerung zwischen dem anfänglichen Traffic-Anstieg und der Erweiterung des Pools. Die Latenz tritt in diesem Zeitraum auf, während neue Anfragen darauf warten, dass die gesättigten Channels geleert werden oder dem Pool im nächsten Anpassungszyklus neue Channels hinzugefügt werden.

Zu suchende Logs

Suchen Sie nach Protokollen, die darauf hinweisen, dass der Channel-Pool erweitert wird. Dies ist der primäre Beweis dafür, dass der Client auf einen Traffic-Peak reagiert, der seine aktuelle Kapazität überschritten hat.

Channel Pool Expansion Log (Protokoll zur Erweiterung des Channel-Pools):

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

Interpretation: Im Pool wurde ein Traffic-Spike erkannt und es werden neue Verbindungen geöffnet, um die erhöhte Last zu bewältigen. Häufige Erweiterungen, insbesondere kurz nach dem Start, sind ein deutliches Zeichen dafür, dass Ihre ursprüngliche Konfiguration für Ihre typische Arbeitslast nicht ausreicht.

Lösung

Das Ziel ist, genügend Channels vorzubereiten, bevor der Traffic eintrifft, damit der Client sie nicht unter Zeitdruck erstellen muss.

initialChannelCount erhöhen (hohe Latenz beim Start):

Wenn Sie beim Start eine hohe Latenz feststellen, ist es am effektivsten, den Wert von initialChannelCount in ChannelPoolSettings zu erhöhen. Standardmäßig ist dieser Wert auf 10 festgelegt. Das kann für Anwendungen, die beim Start viel Traffic verarbeiten, zu niedrig sein.

So finden Sie den richtigen Wert für die Anwendung:

  1. Aktivieren Sie das Logging auf der Ebene FINEST für com.google.api.gax.grpc.ChannelPool.
  2. Führen Sie Ihre Anwendung unter einer typischen Startarbeitslast oder einem typischen Traffic-Spike aus.
  3. Sehen Sie sich die Protokolle zur Erweiterung des Channel-Pools an, um zu sehen, bei welcher Größe sich der Pool stabilisiert.

Wenn Sie beispielsweise Logs wie diese sehen:
[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 80, expanding channel pool size: 4 -> 6.

Eine Minute später werden dann Logs angezeigt:

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

Wenn die erweiterte Channelpool-Größe bei 8 Channels stabilisiert ist und keine weiteren Erweiterungslogs gefunden werden können, bedeutet das, dass Ihre Anwendung 8 Channels benötigt, um ihre Arbeitslast zu bewältigen. Ein guter Ausgangspunkt ist, initialChannelCount auf 8 festzulegen. So werden die Verbindungen im Voraus hergestellt, wodurch die Latenz, die durch die dynamische Skalierung verursacht wird, reduziert oder eliminiert wird.

Ziel ist es, dass der Pool genügend Kapazität hat, um Spitzenlasten zu bewältigen, ohne Anfragen in die Warteschlange zu stellen.

Anstieg von minChannelCount (Trafficspitzen):

Wenn Sie eine hohe Latenz speziell zu Beginn von Traffic-Spitzen feststellen, ist das ein Zeichen dafür, dass Ihr Traffic schneller zunimmt, als der Channel-Pool reaktiv neue Verbindungen erstellen kann. Dies ist häufig bei Anwendungen mit vorhersehbaren, plötzlichen Trafficspitzen der Fall.

Der Pool stabilisiert sich bei normalem Traffic mit einer kleinen Anzahl von Channels und fügt proaktiv weitere hinzu, wenn der Traffic zunimmt, um eine Sättigung zu verhindern. Dieser Skalierungsvorgang dauert eine Weile. Die ersten Anfragen in einem Burst werden in die Warteschlange gestellt, was zu einer hohen Latenz führt.

Durch Erhöhen von minChannelCount wird eine höhere Baseline für dauerhaft geöffnete Channels festgelegt. So ist bereits genügend Kapazität vorhanden, um den ersten Burst zu bewältigen. Dadurch werden die Skalierungsverzögerung und der damit verbundene Latenzspitzenwert vermieden.

Anstieg von maxChannelCount (Trafficspitzen):

Wenn Sie während Trafficspitzen eine hohe Latenz beobachten und Ihre Logs zeigen, dass der Channelpool durchgehend seine maximale Größe (maxChannelCount) erreicht, ist das aktuelle Limit wahrscheinlich zu niedrig für Ihren Spitzen-Traffic. Standardmäßig ist maxChannelCount auf 200 festgelegt. Um einen besseren Wert zu ermitteln, können Sie anhand des Leitfadens zur Konfiguration des Verbindungspools die optimale Anzahl von Verbindungen basierend auf den Spitzen-QPS (Queries Per Second) und der durchschnittlichen Anfragelatenz Ihrer Anwendung berechnen.

Symptom 2: Zeitweilige Zeitüberschreitungen oder RPC-Fehler

Manchmal läuft die Anwendung die meiste Zeit einwandfrei, aber es kommt gelegentlich zu Zeitüberschreitungen oder fehlgeschlagenen RPCs, auch bei normalem Traffic.

Mögliche Ursache: Netzwerk instabil

Verbindungen zwischen dem Client und dem Datastore-Dienst werden unterbrochen. Der gRPC-Client versucht automatisch, die Verbindung wiederherzustellen. Dieser Vorgang kann jedoch zu vorübergehenden Fehlern und Latenz führen.

Zu suchende Logs

Das wichtigste Log zur Diagnose von Netzwerkproblemen ist TRANSIENT_FAILURE.

  • Log für vorübergehende Fehler:
[grpc-nio-worker-ELG-1-7] DEBUG io.grpc.ChannelLogger - [Channel<9>: (datastore.googleapis.com:443)] Entering TRANSIENT_FAILURE state
  • Interpretation: Dieses Log ist ein großes Warnsignal dafür, dass die Verbindung zum Channel unterbrochen wurde. Ein einzelner, isolierter Fehler kann nur ein kleiner Netzwerkfehler sein. Wenn diese Meldungen jedoch häufig angezeigt werden oder ein Kanal in diesem Status hängen bleibt, deutet das auf ein erhebliches zugrunde liegendes Problem hin.

Lösung

Netzwerkumgebung untersuchen Prüfen Sie, ob es Probleme mit Firewalls, Proxys, Routern oder der allgemeinen Netzwerkinstabilität zwischen der Anwendung und datastore.googleapis.com gibt.

Symptom 3: Hohe Latenz bei über 20.000 gleichzeitigen Anfragen pro Client

Dieses spezielle Symptom tritt bei Anwendungen auf, die in sehr großem Umfang ausgeführt werden, in der Regel, wenn eine einzelne Clientinstanz mehr als 20.000 gleichzeitige Anfragen verarbeiten muss. Die Anwendung funktioniert unter normalen Bedingungen gut, aber wenn der Traffic auf mehr als 20.000 gleichzeitige Anfragen pro Client ansteigt, beobachten Sie einen starken und plötzlichen Leistungsabfall. Die Latenz steigt deutlich an und bleibt während des gesamten Zeitraums mit Spitzenlast hoch. Dies liegt daran, dass der Verbindungspool des Clients seine maximale Größe erreicht hat und nicht weiter skaliert werden kann.

Mögliche Ursache

Der Kunde leidet unter einer Channelsättigung, da der Channel-Pool die konfigurierte maxChannelCount erreicht hat. Standardmäßig ist der Pool mit einem Limit von 200 Channels konfiguriert. Da jeder gRPC-Channel bis zu 100 gleichzeitige Anfragen verarbeiten kann, wird dieses Limit erst erreicht,wenn eine einzelne Clientinstanz etwa 20.000 Anfragen gleichzeitig verarbeitet.

Sobald der Pool diese Obergrenze erreicht hat, können keine weiteren Verbindungen mehr erstellt werden. Alle 200 Kanäle sind überlastet und neue Anfragen werden clientseitig in die Warteschlange gestellt, was zu dem starken Anstieg der Latenz führt.

Die folgenden Logs können bestätigen, dass maxChannelCount erreicht wurde.

Zu suchende Logs

Der wichtigste Indikator ist, dass der Channel-Pool genau an seinem konfigurierten Limit nicht mehr erweitert wird, obwohl die Last weiter zunimmt.

  • Logs: Hier sehen Sie frühere Logs der Poolerweiterung. Bei Standardeinstellungen ist das letzte Erweiterungsprotokoll, das Sie vor Latenzspitzen sehen, das, in dem der Pool 200 Kanäle erreicht:
[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - ... expanding channel pool size: 198 -> 200.
  • Indikator: Während des Zeitraums mit hoher Latenz werden keine weiteren Logs zum Erweitern der Channelpoolgröße angezeigt. Das Fehlen dieser Logs in Kombination mit der hohen Latenz ist ein starker Hinweis darauf, dass das maxChannelCount-Limit erreicht wurde.

Lösung

Ziel ist es, dass der Pool genügend Kapazität hat, um Spitzenlasten zu bewältigen, ohne Anfragen in die Warteschlange zu stellen.

  • maxChannelCount erhöhen: Die primäre Lösung besteht darin, die Einstellung für maxChannelCount auf einen Wert zu erhöhen, der den Spitzen-Traffic der Anwendung bewältigen kann. Im Leitfaden zur Konfiguration von Verbindungspools finden Sie Informationen dazu, wie Sie die optimale Anzahl von Verbindungen basierend auf den maximalen Abfragen pro Sekunde (Queries Per Second, QPS) und der durchschnittlichen Anfragelatenz der Anwendung berechnen.

Anhang

Die folgenden Abschnitte enthalten zusätzliche Informationen zur Fehlerbehebung.

Channelstatus

In den Logs können die folgenden Channel-Status angezeigt werden, die Aufschluss über das Verbindungsverhalten geben:

Bundesland Beschreibung
IDLE Der Kanal wird erstellt, hat aber keine aktiven Verbindungen oder RPCs. Es wird auf Zugriffe gewartet.
VERBINDUNG WIRD HERGESTELLT Der Channel versucht aktiv, einen neuen Netzwerktransport (eine neue Verbindung) zum gRPC-Server herzustellen.
BEREIT Der Channel hat einen etablierten und fehlerfreien Transport und ist bereit, RPCs zu senden.
TRANSIENT_FAILURE Auf dem Kanal ist ein behebbarer Fehler aufgetreten, z.B. ein Netzwerkproblem oder eine vorübergehende Nichtverfügbarkeit des Servers. Es wird automatisch versucht, die Verbindung wiederherzustellen.
SHUTDOWN Der Kanal wurde geschlossen, entweder manuell (z.B. shutdown() aufgerufen wurde oder aufgrund eines Leerlaufzeitlimits. Es können keine neuen RPCs initiiert werden.

Tipps

  • Wenn Sie ein Framework für strukturiertes Logging wie SLF4J oder Logback verwenden, müssen Sie entsprechende Log-Ebenen in logback.xml oder anderen Logger-Konfigurationsdateien konfigurieren. Die java.util.logging-Ebenen werden von der Logging-Fassade zugeordnet.