Skip to content

Commit e61a3d6

Browse files
davleopodavleopo
committed
report hot metrics: improve logging of data
1 parent 48837f5 commit e61a3d6

File tree

2 files changed

+82
-42
lines changed

2 files changed

+82
-42
lines changed

‎compiler/src/jdk.graal.compiler/src/jdk/graal/compiler/graph/NodeSourcePosition.java‎

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -34,7 +34,6 @@
3434
import jdk.graal.compiler.bytecode.BytecodeDisassembler;
3535
import jdk.graal.compiler.bytecode.Bytecodes;
3636
import jdk.graal.compiler.debug.Assertions;
37-
3837
import jdk.graal.compiler.serviceprovider.GraalServices;
3938
import jdk.vm.ci.code.BytecodeFrame;
4039
import jdk.vm.ci.code.BytecodePosition;
@@ -219,9 +218,14 @@ public NodeSourcePosition addCaller(SourceLanguagePosition newSourceLanguagePosi
219218

220219
@Override
221220
public String toString() {
221+
return toString("");
222+
}
223+
224+
public String toString(String indent) {
222225
StringBuilder sb = new StringBuilder(100);
223226
NodeSourcePosition pos = this;
224227
while (pos != null) {
228+
sb.append(indent);
225229
format(sb, pos);
226230
if (pos.sourceLanguagePosition != null) {
227231
sb.append(" source=" + pos.sourceLanguagePosition.toShortString());

‎compiler/src/jdk.graal.compiler/src/jdk/graal/compiler/phases/common/ReportHotCodePhase.java‎

Lines changed: 77 additions & 41 deletions
Original file line numberDiff line numberDiff line change
@@ -52,6 +52,7 @@
5252
import jdk.graal.compiler.options.OptionKey;
5353
import jdk.graal.compiler.options.OptionType;
5454
import jdk.graal.compiler.phases.BasePhase;
55+
import jdk.graal.compiler.phases.schedule.SchedulePhase;
5556

5657
/**
5758
* Analyzes and reports performance-critical aspects of a structured graph's intermediate
@@ -64,15 +65,20 @@
6465
* <p>
6566
* The resulting report can be used to guide further performance analysis or optimization efforts.
6667
* </p>
68+
*
69+
* The phase is written in an agnostic way so it can be applied at any point in time in the
70+
* compilation pipeline.
6771
*/
6872
public class ReportHotCodePhase<C> extends BasePhase<C> {
6973

7074
public static class Options {
7175
//@formatter:off
72-
@Option(help = "", type = OptionType.Debug)
76+
@Option(help = "Dumps the hottest code parts to the Ideal Graph Visualizer (IGV) for further analysis and visualization.", type = OptionType.Debug)
7377
public static final OptionKey<Boolean> ReportHotCodePartsToIGV = new OptionKey<>(false);
74-
@Option(help = "", type = OptionType.Debug)
78+
@Option(help = "Specifies the debug level for dumping hottest code parts to the Ideal Graph Visualizer (IGV).", type = OptionType.Debug)
7579
public static final OptionKey<Integer> ReportHotCodIGVLevel = new OptionKey<>(1);
80+
@Option(help = "", type = OptionType.Debug)
81+
public static final OptionKey<Double> MinimalFrequencyToReport = new OptionKey<>(1D);
7682
//@formatter:on
7783
}
7884

@@ -92,12 +98,20 @@ enum BlockToStringMode {
9298
GLOBAL_FREQUENCY,
9399
}
94100

95-
private static final String INFO_KEY = "[HOT CODE INFO]";
101+
private static final String INFO_KEY = "[Hot Code Info] ";
96102

97-
private static final String WARNING_KEY = "[HOT CODE WARNING]";
103+
private static final String WARNING_KEY = "[Hot Code Warning] ";
98104

99105
private static String blocksToString(List<HIRBlock> blocks, BlockToStringMode mode) {
100106
StringBuilder sb = new StringBuilder();
107+
switch (mode) {
108+
case BEGIN_NODE:
109+
sb.append("BeginNodeIDs=");
110+
break;
111+
case GLOBAL_FREQUENCY:
112+
sb.append("GlobalFrequencies=");
113+
break;
114+
}
101115
sb.append("[");
102116
for (int i = 0; i < blocks.size(); i++) {
103117
switch (mode) {
@@ -118,6 +132,17 @@ private static String blocksToString(List<HIRBlock> blocks, BlockToStringMode mo
118132

119133
private static String loopBlocksToString(List<Loop> loops, LoopToStringMode mode) {
120134
StringBuilder sb = new StringBuilder();
135+
switch (mode) {
136+
case BLOCK:
137+
sb.append("Blocks=");
138+
break;
139+
case GLOBAL_FREQUENCY:
140+
sb.append("BasicBlockFrequencies=");
141+
break;
142+
case LOCAL_FREQUENCY:
143+
sb.append("LocalLoopFrequencies=");
144+
break;
145+
}
121146
sb.append("[");
122147
for (int i = 0; i < loops.size(); i++) {
123148
switch (mode) {
@@ -143,10 +168,13 @@ private static <X> List<X> takeUntil(List<X> list, int length) {
143168
return list.subList(0, Math.min(length, list.size()));
144169
}
145170

171+
/**
172+
* The number of hottest code regions (blocks or loops) to report.
173+
*/
146174
private static final int REPORT_HOT_FIRST_N = 3;
147175

148176
private static int getLengthCap(int len, int cap) {
149-
return len > cap ? cap : len;
177+
return Math.min(len, cap);
150178
}
151179

152180
private static void info(String format, Object... args) {
@@ -168,7 +196,12 @@ protected void run(StructuredGraph graph, C c) {
168196

169197
CoreProviders context = (CoreProviders) c;
170198

171-
final LoopsData ld = context.getLoopsDataProvider().getLoopsData(graph);
199+
SchedulePhase.runWithoutContextOptimizations(graph, SchedulePhase.SchedulingStrategy.LATEST_OUT_OF_LOOPS, true);
200+
final StructuredGraph.ScheduleResult scheduleResult = graph.getLastSchedule();
201+
202+
final double minimalReportFrequency = Options.MinimalFrequencyToReport.getValue(graph.getOptions());
203+
204+
final LoopsData ld = context.getLoopsDataProvider().getLoopsData(scheduleResult.getCFG());
172205
final ControlFlowGraph cfg = ld.getCFG();
173206
// report the 3 hottest blocks and the 3 hottest loops and 3 hottest loops by local loop
174207
// frequency
@@ -188,7 +221,7 @@ protected void run(StructuredGraph graph, C c) {
188221

189222
final List<HIRBlock> hottestFirstBlocks = takeUntil(hottestBlocks, REPORT_HOT_FIRST_N);
190223
if (!hottestFirstBlocks.isEmpty()) {
191-
String hottestGlobalBlocksString = String.format("Hottest %s blocks are %s %s %s", getLengthCap(hottestFirstBlocks.size(), 3), hottestFirstBlocks,
224+
String hottestGlobalBlocksString = String.format("Hottest %s blocks are %s %s %s", getLengthCap(hottestFirstBlocks.size(), REPORT_HOT_FIRST_N), hottestFirstBlocks,
192225
blocksToString(hottestFirstBlocks, BlockToStringMode.BEGIN_NODE),
193226
blocksToString(hottestFirstBlocks, BlockToStringMode.GLOBAL_FREQUENCY));
194227
info("%s\n", hottestGlobalBlocksString);
@@ -199,7 +232,7 @@ protected void run(StructuredGraph graph, C c) {
199232

200233
final List<Loop> hottestFirstLocalLoops = takeUntil(hottestLocalLoops, REPORT_HOT_FIRST_N);
201234
if (!hottestFirstLocalLoops.isEmpty()) {
202-
String hottestLocalLoopString = String.format("Hottest %s local loops are %s %s", getLengthCap(hottestFirstLocalLoops.size(), 3),
235+
String hottestLocalLoopString = String.format("Hottest %s local loops are %s %s", getLengthCap(hottestFirstLocalLoops.size(), REPORT_HOT_FIRST_N),
203236
loopBlocksToString(hottestFirstLocalLoops, LoopToStringMode.BLOCK),
204237
loopBlocksToString(hottestFirstLocalLoops, LoopToStringMode.LOCAL_FREQUENCY));
205238
info("%s\n", hottestLocalLoopString);
@@ -210,7 +243,7 @@ protected void run(StructuredGraph graph, C c) {
210243

211244
final List<Loop> hottestFirstGlobalLoops = takeUntil(hottestGlobalLoops, REPORT_HOT_FIRST_N);
212245
if (!hottestGlobalLoops.isEmpty()) {
213-
String hottestGlobalLoopString = String.format("Hottest %s global loops are %s %s", getLengthCap(hottestGlobalLoops.size(), 3),
246+
String hottestGlobalLoopString = String.format("Hottest %s global loops are %s %s", getLengthCap(hottestGlobalLoops.size(), REPORT_HOT_FIRST_N),
214247
loopBlocksToString(hottestFirstGlobalLoops, LoopToStringMode.BLOCK),
215248
loopBlocksToString(hottestFirstGlobalLoops, LoopToStringMode.GLOBAL_FREQUENCY));
216249
info("%s\n", hottestGlobalLoopString);
@@ -219,13 +252,17 @@ protected void run(StructuredGraph graph, C c) {
219252
}
220253
}
221254

222-
reportHotLoopGuardsInside(hottestGlobalLoops);
223-
224255
for (Loop l : hottestGlobalLoops) {
225256
for (Node inside : l.inside().nodes()) {
257+
// ignore slow paths in loops
258+
HIRBlock insideBlock = scheduleResult.blockFor(inside);
259+
if (insideBlock != null && insideBlock.getRelativeFrequency() < minimalReportFrequency) {
260+
continue;
261+
}
226262
reportUnknownProfile(l, inside, cfg);
227263
reportInvariantLoopIf(l, inside);
228264
reportMemoryKillANYInLoop(l, inside, cfg);
265+
reportHotLoopGuardsInside(inside, l);
229266
}
230267
}
231268
}
@@ -245,8 +282,9 @@ protected void run(StructuredGraph graph, C c) {
245282
private static void reportUnknownProfile(Loop l, Node inside, ControlFlowGraph cfg) {
246283
if (inside instanceof IfNode ifNode) {
247284
if (ifNode.profileSource().isUnknown()) {
248-
warn("Unknown profile for %s with f=%s in hot loop %s, nsp is %n\t%s%n", ifNode, cfg.blockFor(inside).getRelativeFrequency(), l,
249-
ifNode.getNodeSourcePosition());
285+
warn("Unknown profile for %s with f=%s in hot loop %s, nsp is %n%s%n\tPotential Action Item: Add profile to the top-of-stack source location.%n", ifNode,
286+
cfg.blockFor(inside).getRelativeFrequency(), l,
287+
ifNode.getNodeSourcePosition().toString("\t"));
250288
}
251289
}
252290
}
@@ -263,7 +301,7 @@ private static void reportInvariantLoopIf(Loop l, Node inside) {
263301
if (inside instanceof IfNode ifNode) {
264302
LogicNode logicNode = ifNode.condition();
265303
if (!l.whole().contains(logicNode)) {
266-
warn("If %s with condition %s is inside loop %s while condition is not%n", ifNode, logicNode, l);
304+
warn("If %s with condition %s is inside loop %s while condition is not%n\tPotential Action Item: Determine why compiler does not unswitch the loop.%n", ifNode, logicNode, l);
267305
}
268306
}
269307
}
@@ -289,7 +327,8 @@ private static void reportMemoryKillANYInLoop(Loop l, Node inside, ControlFlowGr
289327
if (sk.getKilledLocationIdentity().isAny()) {
290328
if (inside instanceof FixedNode) {
291329
// else we dont have a cfg position
292-
warn("Node %s kills any and has relative f=%s in loop %s %n", inside, cfg.blockFor(inside).getRelativeFrequency(), l);
330+
warn("Node %s kills any and has relative f=%s in loop %s %n\tPotential Action Item: Determine if operation is required and replace with less intrusive memory effect if possible.%n",
331+
inside, cfg.blockFor(inside).getRelativeFrequency(), l);
293332
} else {
294333
warn("Node %s kills any in loop %s %n", inside, l);
295334
}
@@ -313,33 +352,30 @@ private static void reportMemoryKillANYInLoop(Loop l, Node inside, ControlFlowGr
313352
* opportunities for speculative optimization.
314353
* </p>
315354
*/
316-
private static void reportHotLoopGuardsInside(List<Loop> hottestGlobalLoops) {
317-
for (Loop l : hottestGlobalLoops) {
318-
for (Node inside : l.inside().nodes()) {
319-
CompareNode compare = null;
320-
if (inside instanceof FixedGuardNode fg && fg.condition() instanceof CompareNode c1) {
321-
compare = c1;
322-
} else if (inside instanceof GuardNode g && g.getCondition() instanceof CompareNode c2) {
323-
compare = c2;
324-
}
325-
if (compare != null) {
326-
ValueNode x = compare.getX();
327-
ValueNode y = compare.getY();
328-
329-
InductionVariable iv = null;
330-
ValueNode limit = null;
331-
if (l.getInductionVariables().get(x) != null && l.isOutsideLoop(y)) {
332-
iv = l.getInductionVariables().get(x);
333-
limit = y;
334-
} else if (l.getInductionVariables().get(y) != null && l.isOutsideLoop(x)) {
335-
iv = l.getInductionVariables().get(y);
336-
limit = x;
337-
}
355+
private static void reportHotLoopGuardsInside(Node inside, Loop loop) {
356+
CompareNode compare = null;
357+
if (inside instanceof FixedGuardNode fg && fg.condition() instanceof CompareNode c1) {
358+
compare = c1;
359+
} else if (inside instanceof GuardNode g && g.getCondition() instanceof CompareNode c2) {
360+
compare = c2;
361+
}
362+
if (compare != null) {
363+
ValueNode x = compare.getX();
364+
ValueNode y = compare.getY();
365+
366+
InductionVariable iv = null;
367+
ValueNode limit = null;
368+
if (loop.getInductionVariables().get(x) != null && loop.isOutsideLoop(y)) {
369+
iv = loop.getInductionVariables().get(x);
370+
limit = y;
371+
} else if (loop.getInductionVariables().get(y) != null && loop.isOutsideLoop(x)) {
372+
iv = loop.getInductionVariables().get(y);
373+
limit = x;
374+
}
338375

339-
if (iv != null && limit != null) {
340-
warn("Guard %s condition %s inside loop with iv %s and limit %s%n", inside, compare, iv, limit);
341-
}
342-
}
376+
if (iv != null && limit != null) {
377+
warn("Guard %s condition %s inside loop with iv %s and limit %s%n\tPotential Action Item: Determine why speculative guard movement does not consider them for optimization.%n", inside,
378+
compare, iv, limit);
343379
}
344380
}
345381
}

0 commit comments

Comments
 (0)