1 /*
2 * Copyright (c) 2009, 2013, Oracle and/or its affiliates. All rights reserved.
3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
4 *
5 * This code is free software; you can redistribute it and/or modify it
6 * under the terms of the GNU General Public License version 2 only, as
7 * published by the Free Software Foundation.
8 *
9 * This code is distributed in the hope that it will be useful, but WITHOUT
10 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
11 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
12 * version 2 for more details (a copy is included in the LICENSE file that
13 * accompanied this code).
14 *
15 * You should have received a copy of the GNU General Public License version
16 * 2 along with this work; if not, write to the Free Software Foundation,
17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
18 *
19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
20 * or visit www.oracle.com if you need additional information or have any
21 * questions.
22 *
23 */
24
25 /**
26 * A SAX based parser of LogCompilation output from HotSpot. It takes a complete
27 * @author never
28 */
29
30 package com.sun.hotspot.tools.compiler;
31
32 import java.io.FileReader;
33 import java.io.Reader;
34 import java.util.ArrayDeque;
35 import java.util.ArrayList;
36 import java.util.Collections;
37 import java.util.Comparator;
38 import java.util.HashMap;
39 import java.util.LinkedHashMap;
40 import java.util.Stack;
41 import javax.xml.parsers.SAXParser;
42 import javax.xml.parsers.SAXParserFactory;
43 import org.xml.sax.Attributes;
44 import org.xml.sax.ErrorHandler;
45 import org.xml.sax.InputSource;
46 import org.xml.sax.helpers.DefaultHandler;
47
48 public class LogParser extends DefaultHandler implements ErrorHandler, Constants {
49
50 static final HashMap<String, String> typeMap;
51 static {
52 typeMap = new HashMap<String, String>();
53 typeMap.put("[I", "int[]");
54 typeMap.put("[C", "char[]");
55 typeMap.put("[Z", "boolean[]");
56 typeMap.put("[L", "Object[]");
57 typeMap.put("[B", "byte[]");
58 }
59
60 static Comparator<LogEvent> sortByStart = new Comparator<LogEvent>() {
61
62 public int compare(LogEvent a, LogEvent b) {
63 double difference = (a.getStart() - b.getStart());
64 if (difference < 0) {
65 return -1;
66 }
67 if (difference > 0) {
68 return 1;
69 }
70 return 0;
71 }
72
73 @Override
74 public boolean equals(Object other) {
75 return false;
76 }
77
78 @Override
79 public int hashCode() {
80 return 7;
81 }
82 };
83 static Comparator<LogEvent> sortByNameAndStart = new Comparator<LogEvent>() {
84
85 public int compare(LogEvent a, LogEvent b) {
86 Compilation c1 = a.getCompilation();
87 Compilation c2 = b.getCompilation();
88 if (c1 != null && c2 != null) {
89 int result = c1.getMethod().toString().compareTo(c2.getMethod().toString());
90 if (result != 0) {
91 return result;
92 }
93 }
94 double difference = (a.getStart() - b.getStart());
95 if (difference < 0) {
96 return -1;
97 }
98 if (difference > 0) {
99 return 1;
100 }
101 return 0;
102 }
103
104 public boolean equals(Object other) {
105 return false;
106 }
107
108 @Override
109 public int hashCode() {
110 return 7;
111 }
112 };
113 static Comparator<LogEvent> sortByElapsed = new Comparator<LogEvent>() {
114
115 public int compare(LogEvent a, LogEvent b) {
116 double difference = (a.getElapsedTime() - b.getElapsedTime());
117 if (difference < 0) {
118 return -1;
119 }
120 if (difference > 0) {
121 return 1;
122 }
123 return 0;
124 }
125
126 @Override
127 public boolean equals(Object other) {
128 return false;
129 }
130
131 @Override
132 public int hashCode() {
133 return 7;
134 }
135 };
136
137 private ArrayList<LogEvent> events = new ArrayList<LogEvent>();
138
139 private HashMap<String, String> types = new HashMap<String, String>();
140 private HashMap<String, Method> methods = new HashMap<String, Method>();
141 private LinkedHashMap<String, NMethod> nmethods = new LinkedHashMap<String, NMethod>();
142 private HashMap<String, Compilation> compiles = new HashMap<String, Compilation>();
143 private String failureReason;
144 private int bci;
145 private Stack<CallSite> scopes = new Stack<CallSite>();
146 private Compilation compile;
147 private CallSite site;
148 private CallSite methodHandleSite;
149 private Stack<Phase> phaseStack = new Stack<Phase>();
150 private UncommonTrapEvent currentTrap;
151 private Stack<CallSite> lateInlineScope;
152 private boolean lateInlining;
153
154
155 long parseLong(String l) {
156 try {
157 return Long.decode(l).longValue();
158 } catch (NumberFormatException nfe) {
159 int split = l.length() - 8;
160 String s1 = "0x" + l.substring(split);
161 String s2 = l.substring(0, split);
162 long v1 = Long.decode(s1).longValue() & 0xffffffffL;
163 long v2 = (Long.decode(s2).longValue() & 0xffffffffL) << 32;
164 if (!l.equals("0x" + Long.toHexString(v1 + v2))) {
165 System.out.println(l);
166 System.out.println(s1);
167 System.out.println(s2);
168 System.out.println(v1);
169 System.out.println(v2);
170 System.out.println(Long.toHexString(v1 + v2));
171 throw new InternalError("bad conversion");
172 }
173 return v1 + v2;
174 }
175 }
176
177 public static ArrayList<LogEvent> parse(String file, boolean cleanup) throws Exception {
178 return parse(new FileReader(file), cleanup);
179 }
180
181 public static ArrayList<LogEvent> parse(Reader reader, boolean cleanup) throws Exception {
182 // Create the XML input factory
183 SAXParserFactory factory = SAXParserFactory.newInstance();
184
185 // Create the XML LogEvent reader
186 SAXParser p = factory.newSAXParser();
187
188 if (cleanup) {
189 // some versions of the log have slightly malformed XML, so clean it
190 // up before passing it to SAX
191 reader = new LogCleanupReader(reader);
192 }
193
194 LogParser log = new LogParser();
195 p.parse(new InputSource(reader), log);
196
197 // Associate compilations with their NMethods
198 for (NMethod nm : log.nmethods.values()) {
199 Compilation c = log.compiles.get(nm.getId());
200 nm.setCompilation(c);
201 // Native wrappers for methods don't have a compilation
202 if (c != null) {
203 c.setNMethod(nm);
204 }
205 }
206
207 // Initially we want the LogEvent log sorted by timestamp
208 Collections.sort(log.events, sortByStart);
209
210 return log.events;
211 }
212
213 String search(Attributes attr, String name) {
214 String result = attr.getValue(name);
215 if (result != null) {
216 return result;
217 } else {
218 throw new InternalError("can't find " + name);
219 }
220 }
221
222 String search(Attributes attr, String name, String defaultValue) {
223 String result = attr.getValue(name);
224 if (result != null) {
225 return result;
226 }
227 return defaultValue;
228 }
229 int indent = 0;
230
231 String type(String id) {
232 String result = types.get(id);
233 if (result == null) {
234 throw new InternalError(id);
235 }
236 String remapped = typeMap.get(result);
237 if (remapped != null) {
238 return remapped;
239 }
240 return result;
241 }
242
243 void type(String id, String name) {
244 assert type(id) == null;
245 types.put(id, name);
246 }
247
248 Method method(String id) {
249 Method result = methods.get(id);
250 if (result == null) {
251 throw new InternalError(id);
252 }
253 return result;
254 }
255
256 public String makeId(Attributes atts) {
257 String id = atts.getValue("compile_id");
258 String kind = atts.getValue("kind");
259 if (kind != null && kind.equals("osr")) {
260 id += "%";
261 }
262 return id;
263 }
264
265 @Override
266 public void startElement(String uri,
267 String localName,
268 String qname,
269 Attributes atts) {
270 if (qname.equals("phase")) {
271 Phase p = new Phase(search(atts, "name"),
272 Double.parseDouble(search(atts, "stamp")),
273 Integer.parseInt(search(atts, "nodes", "0")),
274 Integer.parseInt(search(atts, "live", "0")));
275 phaseStack.push(p);
276 } else if (qname.equals("phase_done")) {
277 Phase p = phaseStack.pop();
278 String phaseName = search(atts, "name", null);
279 if (phaseName != null && !p.getId().equals(phaseName)) {
280 System.out.println("phase: " + p.getId());
281 throw new InternalError("phase name mismatch");
282 }
283 p.setEnd(Double.parseDouble(search(atts, "stamp")));
284 p.setEndNodes(Integer.parseInt(search(atts, "nodes", "0")));
285 p.setEndLiveNodes(Integer.parseInt(search(atts, "live", "0")));
286 compile.getPhases().add(p);
287 } else if (qname.equals("task")) {
288 compile = new Compilation(Integer.parseInt(search(atts, "compile_id", "-1")));
289 compile.setStart(Double.parseDouble(search(atts, "stamp")));
290 compile.setICount(search(atts, "count", "0"));
291 compile.setBCount(search(atts, "backedge_count", "0"));
292
293 String method = atts.getValue("method");
294 int space = method.indexOf(' ');
295 method = method.substring(0, space) + "::" +
296 method.substring(space + 1, method.indexOf(' ', space + 1) + 1);
297 String compiler = atts.getValue("compiler");
298 if (compiler == null) {
299 compiler = "";
300 }
301 String kind = atts.getValue("compile_kind");
302 if (kind == null) {
303 kind = "normal";
304 }
305 if (kind.equals("osr")) {
306 compile.setOsr(true);
307 compile.setOsr_bci(Integer.parseInt(search(atts, "osr_bci")));
308 } else if (kind.equals("c2i")) {
309 compile.setSpecial("--- adapter " + method);
310 } else {
311 compile.setSpecial(compile.getId() + " " + method + " (0 bytes)");
312 }
313 events.add(compile);
314 compiles.put(makeId(atts), compile);
315 site = compile.getCall();
316 } else if (qname.equals("type")) {
317 type(search(atts, "id"), search(atts, "name"));
318 } else if (qname.equals("bc")) {
319 bci = Integer.parseInt(search(atts, "bci"));
320 } else if (qname.equals("klass")) {
321 type(search(atts, "id"), search(atts, "name"));
322 } else if (qname.equals("method")) {
323 String id = search(atts, "id");
324 Method m = new Method();
325 m.setHolder(type(search(atts, "holder")));
326 m.setName(search(atts, "name"));
327 m.setReturnType(type(search(atts, "return")));
328 m.setArguments(search(atts, "arguments", "void"));
329
330 if (search(atts, "unloaded", "0").equals("0")) {
331 m.setBytes(search(atts, "bytes"));
332 m.setIICount(search(atts, "iicount"));
333 m.setFlags(search(atts, "flags"));
334 }
335 methods.put(id, m);
336 } else if (qname.equals("call")) {
337 if (methodHandleSite != null) {
338 methodHandleSite = null;
339 }
340 Method m = method(search(atts, "method"));
341 if (lateInlining && scopes.size() == 0) {
342 // re-attempting already seen call site (late inlining for MH invokes)
343 if (m != site.getMethod()) {
344 if (bci != site.getBci()) {
345 System.out.println(m + " bci: " + bci);
346 System.out.println(site.getMethod() + " bci: " + site.getBci());
347 throw new InternalError("bci mismatch after late inlining");
348 }
349 site.setMethod(m);
350 }
351 } else {
352 site = new CallSite(bci, m);
353 }
354 site.setCount(Integer.parseInt(search(atts, "count", "0")));
355 String receiver = atts.getValue("receiver");
356 if (receiver != null) {
357 site.setReceiver(type(receiver));
358 site.setReceiver_count(Integer.parseInt(search(atts, "receiver_count")));
359 }
360 int methodHandle = Integer.parseInt(search(atts, "method_handle_intrinsic", "0"));
361 if (lateInlining && scopes.size() == 0) {
362 // The call was added before this round of late inlining
363 } else if (methodHandle == 0) {
364 scopes.peek().add(site);
365 } else {
366 // method handle call site can be followed by another
367 // call (in case it is inlined). If that happens we
368 // discard the method handle call site. So we keep
369 // track of it but don't add it to the list yet.
370 methodHandleSite = site;
371 }
372 } else if (qname.equals("regalloc")) {
373 compile.setAttempts(Integer.parseInt(search(atts, "attempts")));
374 } else if (qname.equals("inline_fail")) {
375 if (methodHandleSite != null) {
376 scopes.peek().add(methodHandleSite);
377 methodHandleSite = null;
378 }
379 if (lateInlining && scopes.size() == 0) {
380 site.setReason(search(atts, "reason"));
381 lateInlining = false;
382 } else {
383 scopes.peek().last().setReason(search(atts, "reason"));
384 }
385 } else if (qname.equals("inline_success")) {
386 if (methodHandleSite != null) {
387 throw new InternalError("method handle site should have been replaced");
388 }
389 if (lateInlining && scopes.size() == 0) {
390 site.setReason(null);
391 }
392 } else if (qname.equals("failure")) {
393 failureReason = search(atts, "reason");
394 } else if (qname.equals("task_done")) {
395 compile.setEnd(Double.parseDouble(search(atts, "stamp")));
396 if (Integer.parseInt(search(atts, "success")) == 0) {
397 compile.setFailureReason(failureReason);
398 failureReason = null;
399 }
400 } else if (qname.equals("make_not_entrant")) {
401 String id = makeId(atts);
402 NMethod nm = nmethods.get(id);
403 if (nm == null) throw new InternalError();
404 LogEvent e = new MakeNotEntrantEvent(Double.parseDouble(search(atts, "stamp")), id,
405 atts.getValue("zombie") != null, nm);
406 events.add(e);
407 } else if (qname.equals("uncommon_trap")) {
408 String id = atts.getValue("compile_id");
409 if (id != null) {
410 id = makeId(atts);
411 currentTrap = new UncommonTrapEvent(Double.parseDouble(search(atts, "stamp")),
412 id,
413 atts.getValue("reason"),
414 atts.getValue("action"),
415 Integer.parseInt(search(atts, "count", "0")));
416 events.add(currentTrap);
417 } else {
418 // uncommon trap inserted during parsing.
419 // ignore for now
420 }
421 } else if (qname.equals("late_inline")) {
422 long inlineId = Long.parseLong(search(atts, "inline_id"));
423 lateInlineScope = new Stack<CallSite>();
424 site = new CallSite(-999, method(search(atts, "method")));
425 site.setInlineId(inlineId);
426 lateInlineScope.push(site);
427 } else if (qname.equals("jvms")) {
428 // <jvms bci='4' method='java/io/DataInputStream readChar ()C' bytes='40' count='5815' iicount='20815'/>
429 if (currentTrap != null) {
430 currentTrap.addJVMS(atts.getValue("method"), Integer.parseInt(atts.getValue("bci")));
431 } else if (lateInlineScope != null) {
432 bci = Integer.parseInt(search(atts, "bci"));
433 site = new CallSite(bci, method(search(atts, "method")));
434 lateInlineScope.push(site);
435 } else {
436 // Ignore <eliminate_allocation type='667'>,
437 // <eliminate_lock lock='1'>,
438 // <replace_string_concat arguments='2' string_alloc='0' multiple='0'>
439 }
440 } else if (qname.equals("inline_id")) {
441 if (methodHandleSite != null) {
442 throw new InternalError("method handle site should have been replaced");
443 }
444 long id = Long.parseLong(search(atts, "id"));
445 site.setInlineId(id);
446 } else if (qname.equals("nmethod")) {
447 String id = makeId(atts);
448 NMethod nm = new NMethod(Double.parseDouble(search(atts, "stamp")),
449 id,
450 parseLong(atts.getValue("address")),
451 parseLong(atts.getValue("size")));
452 nmethods.put(id, nm);
453 events.add(nm);
454 } else if (qname.equals("parse")) {
455 if (failureReason != null && scopes.size() == 0 && !lateInlining) {
456 failureReason = null;
457 compile.reset();
458 site = compile.getCall();
459 }
460
461 if (methodHandleSite != null) {
462 throw new InternalError("method handle site should have been replaced");
463 }
464 Method m = method(search(atts, "method"));
465 if (lateInlining && scopes.size() == 0) {
466 if (site.getMethod() != m) {
467 System.out.println(site.getMethod());
468 System.out.println(m);
469 throw new InternalError("Unexpected method mismatch during late inlining");
470 }
471 }
472 if (scopes.size() == 0 && !lateInlining) {
473 compile.setMethod(m);
474 scopes.push(site);
475 } else {
476 if (site.getMethod() == m) {
477 scopes.push(site);
478 } else if (scopes.peek().getCalls().size() > 2 && m == scopes.peek().last(-2).getMethod()) {
479 scopes.push(scopes.peek().last(-2));
480 } else {
481 // C1 prints multiple method tags during inlining when it narrows method being inlinied.
482 // Example:
483 // ...
484 // <method id="813" holder="694" name="toString" return="695" flags="1" bytes="36" iicount="1"/>
485 // <call method="813" instr="invokevirtual"/>
486 // <inline_success reason="receiver is statically known"/>
487 // <method id="814" holder="792" name="toString" return="695" flags="1" bytes="5" iicount="3"/>
488 // <parse method="814">
489 // ...
490 site.setMethod(m);
491 scopes.push(site);
492 }
493 }
494 } else if (qname.equals("parse_done")) {
495 CallSite call = scopes.pop();
496 call.setEndNodes(Integer.parseInt(search(atts, "nodes", "0")));
497 call.setEndLiveNodes(Integer.parseInt(search(atts, "live", "0")));
498 call.setTimeStamp(Double.parseDouble(search(atts, "stamp")));
499 scopes.push(call);
500 }
501 }
502
503 @Override
504 public void endElement(String uri,
505 String localName,
506 String qname) {
507 if (qname.equals("parse")) {
508 indent -= 2;
509 scopes.pop();
510 if (scopes.size() == 0) {
511 lateInlining = false;
512 }
513 } else if (qname.equals("uncommon_trap")) {
514 currentTrap = null;
515 } else if (qname.equals("late_inline")) {
516 // Populate late inlining info.
517 if (scopes.size() != 0) {
518 throw new InternalError("scopes should be empty for late inline");
519 }
520 // late inline scopes are specified in reverse order:
521 // compiled method should be on top of stack.
522 CallSite caller = lateInlineScope.pop();
523 Method m = compile.getMethod();
524 if (m != caller.getMethod()) {
525 System.out.println(m);
526 System.out.println(caller.getMethod() + " bci: " + bci);
527 throw new InternalError("call site and late_inline info don't match");
528 }
529
530 // late_inline contains caller+bci info, convert it
531 // to bci+callee info used by LogCompilation.
532 CallSite lateInlineSite = compile.getLateInlineCall();
533 ArrayDeque<CallSite> thisCallScopes = new ArrayDeque<CallSite>();
534 do {
535 bci = caller.getBci();
536 // Next inlined call.
537 caller = lateInlineScope.pop();
538 CallSite callee = new CallSite(bci, caller.getMethod());
539 callee.setInlineId(caller.getInlineId());
540 thisCallScopes.addLast(callee);
541 lateInlineSite.add(callee);
542 lateInlineSite = callee;
543 } while (!lateInlineScope.empty());
544
545 site = compile.getCall().findCallSite(thisCallScopes);
546 if (site == null) {
547 System.out.println("call scopes:");
548 for (CallSite c : thisCallScopes) {
549 System.out.println(c.getMethod() + " " + c.getBci() + " " + c.getInlineId());
550 }
551 CallSite c = thisCallScopes.getLast();
552 if (c.getInlineId() != 0) {
553 System.out.println("Looking for call site in entire tree:");
554 ArrayDeque<CallSite> stack = compile.getCall().findCallSite2(c);
555 for (CallSite c2 : stack) {
556 System.out.println(c2.getMethod() + " " + c2.getBci() + " " + c2.getInlineId());
557 }
558 }
559 System.out.println(caller.getMethod() + " bci: " + bci);
560 throw new InternalError("couldn't find call site");
561 }
562 lateInlining = true;
563
564 if (caller.getBci() != -999) {
565 System.out.println(caller.getMethod());
566 throw new InternalError("broken late_inline info");
567 }
568 if (site.getMethod() != caller.getMethod()) {
569 if (site.getInlineId() == caller.getInlineId()) {
570 site.setMethod(caller.getMethod());
571 } else {
572 System.out.println(site.getMethod());
573 System.out.println(caller.getMethod());
574 throw new InternalError("call site and late_inline info don't match");
575 }
576 }
577 // late_inline is followed by parse with scopes.size() == 0,
578 // 'site' will be pushed to scopes.
579 lateInlineScope = null;
580 } else if (qname.equals("task")) {
581 types.clear();
582 methods.clear();
583 site = null;
584 }
585 }
586
587 @Override
588 public void warning(org.xml.sax.SAXParseException e) {
589 System.err.println(e.getMessage() + " at line " + e.getLineNumber() + ", column " + e.getColumnNumber());
590 e.printStackTrace();
591 }
592
593 @Override
594 public void error(org.xml.sax.SAXParseException e) {
595 System.err.println(e.getMessage() + " at line " + e.getLineNumber() + ", column " + e.getColumnNumber());
596 e.printStackTrace();
597 }
598
599 @Override
600 public void fatalError(org.xml.sax.SAXParseException e) {
601 System.err.println(e.getMessage() + " at line " + e.getLineNumber() + ", column " + e.getColumnNumber());
602 e.printStackTrace();
603 }
604 }