jHiccup Analyse summiert sich nicht

Schön zu sehen, dass Sie jHiccup verwenden, und dass es scheint, Realitäts-basierte Schluckauf zu zeigen.

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 zum Isolieren der Ursache der Pause ist die Verwendung der Option "-c" in jHiccup: Sie startet einen separaten Steuerungsprozess (mit einer sonst nicht ausgelasteten Arbeitslast). Wenn sowohl Ihre Anwendung als auch der Steuerungsprozess Schluckauf zeigen, die grob in Größe und Zeit korreliert sind, wissen Sie, dass Sie nach einem (im Gegensatz zu prozesslokalen) 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 meisten JVMs gibt es viele mögliche Ursachen für eine lange Zeit bis zum sicheren Punkt.

jHiccups Messung ist so einfach, dass es schwer ist, falsch zu liegen. 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, da nur Anfragen während der Schluckauf wurde von einem Netzwerk-Logger beobachtet. 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.

Dies darf nicht GC sein, aber bevor Sie GC ausschließen, würde ich vorschlagen, dass Sie sich etwas mehr in die GC-Protokollierung ansehen. 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 benötigt, 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]