Freut mich zu sehen, dass Sie jHiccup verwenden, und dass es Realitäts-basierte Schluckauf zu zeigen scheint.
jHiccup beobachtet "Schluckauf", die auch von Anwendungsthreads auf der JVM erkannt werden. Es ist nicht der Grund dafür - nur meldet die Tatsache. Gründe können alles sein, was dazu führt, dass ein Prozess nicht fehlerfrei ausgeführt wird: GC-Pausen sind eine häufige Ursache, aber ein temporäres^Z an der Tastatur oder eines dieser "Live-Migration" -Dinge über virtualisierte Hosts hinweg genau so gut beobachtet. Es gibt eine Vielzahl von möglichen Gründen, einschließlich der Planung von Druck auf der Betriebssystem- oder Hypervisor-Ebene (falls vorhanden), Power-Management-Verrücktheit, Swapping und viele andere. Ich habe gesehen, Linux-Dateisystem Druck und Transparent Huge Page "Hintergrund" Defragmentierung verursachen mehrere Sekunden Schluckauf sowie ...
Ein guter erster Schritt bei der Isolierung der Ursache der Pause ist die Verwendung der Option "-c" in jHiccup: Es wird ein separater Kontrollprozess gestartet (mit ansonsten ungenutzter Arbeitslast). Wenn sowohl Ihre Anwendung als auch der Steuerungsprozess Schluckauf zeigen, die grob in Größe und Zeit korrelieren, wissen Sie, dass Sie nach einem (im Gegensatz zu einem prozesstechnischen) Grund auf Systemebene suchen. Wenn sie nicht korrelieren, werden Sie das Innere Ihrer JVM vermuten - was höchstwahrscheinlich darauf hindeutet, dass Ihre JVM für etwas Großes pausiert hat; entweder GC oder etwas anderes, wie ein Lock-Debiasing oder eine Class-Loading-Derived-Deoptimization, die bei manchen JVMs eine sehr lange (und oft nicht gemeldete) Zeit in Anspruch nehmen kann, wenn Time-to-Safepoint aus irgendeinem Grund lang ist (und weiter Bei den meisten JVM gibt es viele mögliche Ursachen für eine lange Zeit bis zum sicheren Punkt.
Die Messung von jHiccup ist so einfach, dass es schwer ist, sich zu irren. Die ganze Sache ist weniger als 650 Zeilen Java-Code, so dass Sie die Logik für sich selbst betrachten können. Der HiccupRecorder-Thread von jHiccup geht wiederholt für 1 ms in den Ruhezustand, und wenn er aufwacht, zeichnet er jeden Zeitunterschied auf (vor dem Schlaf), der größer ist als 1 ms als Schluckauf. Die einfache Annahme ist, dass wenn ein vorbereiteter Thread (der HiccupRecorder) 5 Sekunden lang nicht ausgeführt wurde, andere Threads in demselben Prozess auch einen ähnlich großen Schluckauf sahen. Wie Sie oben bemerkt haben, scheinen jHiccups Beobachtungen in Ihren unabhängigen Netzwerkprotokollen bestätigt zu sein, wo Sie eine Antwortzeit von 5 Sekunden sahen. Beachten Sie, dass nicht alle Schluckaufe von den Netzwerkprotokollen beobachtet wurden, wie nur Anfragen während der Schluckauf wäre von einem Netzwerk-Logger beobachtet worden.Im Gegensatz dazu kann sich kein Hiccup, der größer als ~ 1 ms ist, vor jHiccup verbergen, da er selbst bei keiner anderen Aktivität 1000 Mal pro Sekunde aufwacht.
Dieser kann nicht GC sein, aber bevor Sie GC ausschließen, würde ich vorschlagen, dass Sie in die GC-Protokollierung ein wenig mehr suchen. Zu Beginn ist ein JVM-Hinweis zur Begrenzung von Pausen auf 200 ms für alle bekannten JVMs nutzlos. Ein Pausenhinweis ist gleichbedeutend mit "Bitte". Außerdem glauben Sie Ihren GC-Protokollen nicht, wenn Sie -XX: + PrintGCApplicationStoppedTime nicht in Optionen einschließen (und sie auch dann noch verdächtigen). Es gibt Pausen und Teile von Pausen, die sehr lang sein können und nicht gemeldet werden, es sei denn, Sie fügen dieses Flag hinzu. Z.B. Ich habe Pausen gesehen, die durch die gelegentliche lange gezählte Schleife verursacht wurden, die 15 Sekunden dauerte, um einen sicheren Punkt zu erreichen, wo GC nur den .08 Sekunden-Teil der Pause berichtete, wo es tatsächlich etwas Arbeit geleistet hat. Es gibt auch viele Pausen, deren Ursachen nicht als Teil von "GC" betrachtet werden und daher durch GC-Logging-Flags nicht gemeldet werden können.
- Gil. [jHiccups Autor]
