<html><head>
<meta http-equiv="Content-Type" content="text/html; charset=utf-8">
</head>
<body>
<font face="monospace">Hi Misha,</font><br>
<br>
<div class="moz-cite-prefix">On 2023-09-06 21:15, Misha Dmitriev
wrote:<br>
</div>
<blockquote type="cite" cite="mid:SA1PR21MB12867D093EF615DE6D6BDB89C2EFA@SA1PR21MB1286.namprd21.prod.outlook.com">
<style type="text/css" style="display:none;">P {margin-top:0;margin-bottom:0;}</style>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
Hi ZGC developers,</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
I work at LinkedIn, where we have internal tooling for
end-to-end GC performance monitoring and analysis. To record GC
pauses and other interesting events, we parse GC logs as they
are generated, in near real time. Since JDK 11, the unified
logging format allowed us to extract STW pauses for all GCs in
the same straightforward way: we look for lines such as:</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
</div>
<div class="elementToProof"><span style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">[2020-03-09T19:12:22.542+0000][info][gc
] GC(62189) Pause Young (Allocation Failure)
14263M->9334M(14745M) 41.359ms</span></div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
that is, we check every line for the following condition (we
don't use pattern matching for speed):</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
if (line.endsWith("ms") && line.contains("[gc ")
&& line.contains("Pause ")) {</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
// Extract pause time in ms from the end of the line</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
However, looks like ZGC, though it uses the unified logging
format, has a different format for STW pause lines. From the
logs that we have, I am not 100% sure I understand everything.
So far looks like the candidates lines look like</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
[2023-09-05T18:47:27.323+0000][505881.615s][info ][gc,phases
] GC(76657) Pause Mark Start 0.024ms</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
i.e. the condition should be</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<span style="letter-spacing: normal; font-size: 16px;
font-weight: 400; background-color: rgb(255, 255, 255);">if
(line.endsWith("ms") && line.contains("[gc,phases ")
&& line.contains("Pause ")) {</span></div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<span style="letter-spacing: normal; font-size: 16px;
font-weight: 400; background-color: rgb(255, 255, 255);"> //
Extract pause time in ms from the end of line</span></div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<span style="letter-spacing: normal; font-size: 16px;
font-weight: 400; background-color: rgb(255, 255, 255);"><br>
</span></div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<span style="letter-spacing: normal; font-size: 16px;
font-weight: 400; background-color: rgb(255, 255, 255);">I
wonder if this is all we need or I am missing something?</span></div>
</blockquote>
<br>
I think you also need to search for 'info' to make sure you don't
get the more detailed breakdown of the pauses.<br>
<br>
<blockquote type="cite" cite="mid:SA1PR21MB12867D093EF615DE6D6BDB89C2EFA@SA1PR21MB1286.namprd21.prod.outlook.com">
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<span style="letter-spacing: normal; font-size: 16px;
font-weight: 400; background-color: rgb(255, 255, 255);"><br>
</span></div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<span style="letter-spacing: normal; font-size: 16px;
font-weight: 400; background-color: rgb(255, 255, 255);">Also,
what's the meaning of lines like these:</span></div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<span style="letter-spacing: normal; font-size: 16px;
font-weight: 400; background-color: rgb(255, 255, 255);"><br>
</span></div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
[2023-09-05T18:47:44.003+0000][505898.295s][debug ][gc,phases
] GC(76661) Pause Mark Try Complete (ZWorker#2) 0.002ms</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
Formally they look similar to the previous line, but "debug" and
"ZWorker#2" suggests that it may not be a STW pause but pausing
just one thread? Please advise.</div>
</blockquote>
<br>
This line prints what one of the GC worker threads was doing during
the Mark End pause. The "(ZWorker#2)" indicates that this a GC
worker thread. You should filter out these lines if you try to
collect the GC pauses.<br>
<br>
FWIW, in the version you are running this line is printed on the
'debug' level. However, in the latest source code this has changed
and worker logging has been moved to the 'trace' level. There we
have this breakdown:<br>
1) 'info' logs a full pause or concurrent phase<br>
2) 'debug' logs a subphase of (1)<br>
3) 'trace' logs what individual worker threads are doing<br>
<br>
HTH,<br>
StefanK<br>
<br>
<blockquote type="cite" cite="mid:SA1PR21MB12867D093EF615DE6D6BDB89C2EFA@SA1PR21MB1286.namprd21.prod.outlook.com">
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
Thank you,</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
Misha<br>
</div>
<div class="elementToProof" style="font-family: Aptos,
Aptos_EmbeddedFont, Aptos_MSFontService, Calibri, Helvetica,
sans-serif; font-size: 12pt; color: rgb(0, 0, 0);">
<br>
</div>
</blockquote>
<br>
</body>
</html>