1 /* 2 * Copyright (c) 2009, 2015, 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 */ 28 29 package com.sun.hotspot.tools.compiler; 30 31 import java.io.FileReader; 32 import java.io.PrintStream; 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 class Jvms { 138 Jvms(Method method, int bci) { 139 this.method = method; 140 this.bci = bci; 141 } 142 final public Method method; 143 final public int bci; 144 final public String toString() { 145 return "@" + bci + " " + method; 146 } 147 } 148 149 class LockElimination extends BasicLogEvent { 150 151 ArrayList<Jvms> jvms = new ArrayList<Jvms>(1); 152 final String kind; 153 final String classId; 154 final String tagName; 155 LockElimination(String tagName, double start, String id, String kind, String classId) { 156 super(start, id); 157 this.kind = kind; 158 this.classId = classId; 159 this.tagName = tagName; 160 } 161 162 @Override 163 public void print(PrintStream stream) { 164 stream.printf("%s %s %s %s %.3f ", getId(), tagName, kind, classId, getStart()); 165 stream.print(jvms.toString()); 166 stream.print("\n"); 167 } 168 169 void addJVMS(Method method, int bci) { 170 jvms.add(new Jvms(method, bci)); 171 } 172 173 } 174 175 private ArrayList<LogEvent> events = new ArrayList<LogEvent>(); 176 177 private HashMap<String, String> types = new HashMap<String, String>(); 178 private HashMap<String, Method> methods = new HashMap<String, Method>(); 179 private LinkedHashMap<String, NMethod> nmethods = new LinkedHashMap<String, NMethod>(); 180 private HashMap<String, Compilation> compiles = new HashMap<String, Compilation>(); 181 private String failureReason; 182 private int bci; 183 private Stack<CallSite> scopes = new Stack<CallSite>(); 184 private Compilation compile; 185 private CallSite site; 186 private CallSite methodHandleSite; 187 private Stack<Phase> phaseStack = new Stack<Phase>(); 188 private UncommonTrapEvent currentTrap; 189 private Stack<CallSite> lateInlineScope; 190 private boolean lateInlining; 191 192 193 long parseLong(String l) { 194 try { 195 return Long.decode(l).longValue(); 196 } catch (NumberFormatException nfe) { 197 int split = l.length() - 8; 198 String s1 = "0x" + l.substring(split); 199 String s2 = l.substring(0, split); 200 long v1 = Long.decode(s1).longValue() & 0xffffffffL; 201 long v2 = (Long.decode(s2).longValue() & 0xffffffffL) << 32; 202 if (!l.equals("0x" + Long.toHexString(v1 + v2))) { 203 System.out.println(l); 204 System.out.println(s1); 205 System.out.println(s2); 206 System.out.println(v1); 207 System.out.println(v2); 208 System.out.println(Long.toHexString(v1 + v2)); 209 throw new InternalError("bad conversion"); 210 } 211 return v1 + v2; 212 } 213 } 214 215 public static ArrayList<LogEvent> parse(String file, boolean cleanup) throws Exception { 216 return parse(new FileReader(file), cleanup); 217 } 218 219 public static ArrayList<LogEvent> parse(Reader reader, boolean cleanup) throws Exception { 220 // Create the XML input factory 221 SAXParserFactory factory = SAXParserFactory.newInstance(); 222 223 // Create the XML LogEvent reader 224 SAXParser p = factory.newSAXParser(); 225 226 if (cleanup) { 227 // some versions of the log have slightly malformed XML, so clean it 228 // up before passing it to SAX 229 reader = new LogCleanupReader(reader); 230 } 231 232 LogParser log = new LogParser(); 233 try { 234 p.parse(new InputSource(reader), log); 235 } catch (Throwable th) { 236 th.printStackTrace(); 237 // Carry on with what we've got... 238 } 239 240 // Associate compilations with their NMethods 241 for (NMethod nm : log.nmethods.values()) { 242 Compilation c = log.compiles.get(nm.getId()); 243 nm.setCompilation(c); 244 // Native wrappers for methods don't have a compilation 245 if (c != null) { 246 c.setNMethod(nm); 247 } 248 } 249 250 // Initially we want the LogEvent log sorted by timestamp 251 Collections.sort(log.events, sortByStart); 252 253 return log.events; 254 } 255 256 String search(Attributes attr, String name) { 257 String result = attr.getValue(name); 258 if (result != null) { 259 return result; 260 } else { 261 throw new InternalError("can't find " + name); 262 } 263 } 264 265 String search(Attributes attr, String name, String defaultValue) { 266 String result = attr.getValue(name); 267 if (result != null) { 268 return result; 269 } 270 return defaultValue; 271 } 272 int indent = 0; 273 274 String type(String id) { 275 String result = types.get(id); 276 if (result == null) { 277 throw new InternalError(id); 278 } 279 String remapped = typeMap.get(result); 280 if (remapped != null) { 281 return remapped; 282 } 283 return result; 284 } 285 286 void type(String id, String name) { 287 assert type(id) == null; 288 types.put(id, name); 289 } 290 291 Method method(String id) { 292 Method result = methods.get(id); 293 if (result == null) { 294 throw new InternalError(id); 295 } 296 return result; 297 } 298 299 public String makeId(Attributes atts) { 300 String id = atts.getValue("compile_id"); 301 String kind = atts.getValue("kind"); 302 if (kind != null && kind.equals("osr")) { 303 id += "%"; 304 } 305 return id; 306 } 307 308 @Override 309 public void startElement(String uri, 310 String localName, 311 String qname, 312 Attributes atts) { 313 if (qname.equals("phase")) { 314 Phase p = new Phase(search(atts, "name"), 315 Double.parseDouble(search(atts, "stamp")), 316 Integer.parseInt(search(atts, "nodes", "0")), 317 Integer.parseInt(search(atts, "live", "0"))); 318 phaseStack.push(p); 319 } else if (qname.equals("phase_done")) { 320 Phase p = phaseStack.pop(); 321 String phaseName = search(atts, "name", null); 322 if (phaseName != null && !p.getId().equals(phaseName)) { 323 System.out.println("phase: " + p.getId()); 324 throw new InternalError("phase name mismatch"); 325 } 326 p.setEnd(Double.parseDouble(search(atts, "stamp"))); 327 p.setEndNodes(Integer.parseInt(search(atts, "nodes", "0"))); 328 p.setEndLiveNodes(Integer.parseInt(search(atts, "live", "0"))); 329 compile.getPhases().add(p); 330 } else if (qname.equals("task")) { 331 compile = new Compilation(Integer.parseInt(search(atts, "compile_id", "-1"))); 332 compile.setStart(Double.parseDouble(search(atts, "stamp"))); 333 compile.setICount(search(atts, "count", "0")); 334 compile.setBCount(search(atts, "backedge_count", "0")); 335 336 String method = atts.getValue("method"); 337 int space = method.indexOf(' '); 338 method = method.substring(0, space) + "::" + 339 method.substring(space + 1, method.indexOf(' ', space + 1) + 1); 340 String compiler = atts.getValue("compiler"); 341 if (compiler == null) { 342 compiler = ""; 343 } 344 String kind = atts.getValue("compile_kind"); 345 if (kind == null) { 346 kind = "normal"; 347 } 348 if (kind.equals("osr")) { 349 compile.setOsr(true); 350 compile.setOsr_bci(Integer.parseInt(search(atts, "osr_bci"))); 351 } else if (kind.equals("c2i")) { 352 compile.setSpecial("--- adapter " + method); 353 } else { 354 compile.setSpecial(compile.getId() + " " + method + " (0 bytes)"); 355 } 356 events.add(compile); 357 compiles.put(makeId(atts), compile); 358 site = compile.getCall(); 359 } else if (qname.equals("type")) { 360 type(search(atts, "id"), search(atts, "name")); 361 } else if (qname.equals("bc")) { 362 bci = Integer.parseInt(search(atts, "bci")); 363 } else if (qname.equals("klass")) { 364 type(search(atts, "id"), search(atts, "name")); 365 } else if (qname.equals("method")) { 366 String id = search(atts, "id"); 367 Method m = new Method(); 368 m.setHolder(type(search(atts, "holder"))); 369 m.setName(search(atts, "name")); 370 m.setReturnType(type(search(atts, "return"))); 371 m.setArguments(search(atts, "arguments", "void")); 372 373 if (search(atts, "unloaded", "0").equals("0")) { 374 m.setBytes(search(atts, "bytes")); 375 m.setIICount(search(atts, "iicount")); 376 m.setFlags(search(atts, "flags")); 377 } 378 methods.put(id, m); 379 } else if (qname.equals("call")) { 380 if (methodHandleSite != null) { 381 methodHandleSite = null; 382 } 383 Method m = method(search(atts, "method")); 384 if (lateInlining && scopes.size() == 0) { 385 // re-attempting already seen call site (late inlining for MH invokes) 386 if (m != site.getMethod()) { 387 if (bci != site.getBci()) { 388 System.out.println(m + " bci: " + bci); 389 System.out.println(site.getMethod() + " bci: " + site.getBci()); 390 throw new InternalError("bci mismatch after late inlining"); 391 } 392 site.setMethod(m); 393 } 394 } else { 395 site = new CallSite(bci, m); 396 } 397 site.setCount(Integer.parseInt(search(atts, "count", "0"))); 398 String receiver = atts.getValue("receiver"); 399 if (receiver != null) { 400 site.setReceiver(type(receiver)); 401 site.setReceiver_count(Integer.parseInt(search(atts, "receiver_count"))); 402 } 403 int methodHandle = Integer.parseInt(search(atts, "method_handle_intrinsic", "0")); 404 if (lateInlining && scopes.size() == 0) { 405 // The call was added before this round of late inlining 406 } else if (methodHandle == 0) { 407 scopes.peek().add(site); 408 } else { 409 // method handle call site can be followed by another 410 // call (in case it is inlined). If that happens we 411 // discard the method handle call site. So we keep 412 // track of it but don't add it to the list yet. 413 methodHandleSite = site; 414 } 415 } else if (qname.equals("regalloc")) { 416 compile.setAttempts(Integer.parseInt(search(atts, "attempts"))); 417 } else if (qname.equals("inline_fail")) { 418 if (methodHandleSite != null) { 419 scopes.peek().add(methodHandleSite); 420 methodHandleSite = null; 421 } 422 if (lateInlining && scopes.size() == 0) { 423 site.setReason(search(atts, "reason")); 424 lateInlining = false; 425 } else { 426 scopes.peek().last().setReason(search(atts, "reason")); 427 } 428 } else if (qname.equals("inline_success")) { 429 if (methodHandleSite != null) { 430 throw new InternalError("method handle site should have been replaced"); 431 } 432 if (lateInlining && scopes.size() == 0) { 433 site.setReason(null); 434 } 435 } else if (qname.equals("failure")) { 436 failureReason = search(atts, "reason"); 437 } else if (qname.equals("task_done")) { 438 compile.setEnd(Double.parseDouble(search(atts, "stamp"))); 439 if (Integer.parseInt(search(atts, "success")) == 0) { 440 compile.setFailureReason(failureReason); 441 failureReason = null; 442 } 443 } else if (qname.equals("make_not_entrant")) { 444 String id = makeId(atts); 445 NMethod nm = nmethods.get(id); 446 if (nm == null) throw new InternalError(); 447 LogEvent e = new MakeNotEntrantEvent(Double.parseDouble(search(atts, "stamp")), id, 448 atts.getValue("zombie") != null, nm); 449 events.add(e); 450 } else if (qname.equals("uncommon_trap")) { 451 String id = atts.getValue("compile_id"); 452 if (id != null) { 453 id = makeId(atts); 454 currentTrap = new UncommonTrapEvent(Double.parseDouble(search(atts, "stamp")), 455 id, 456 atts.getValue("reason"), 457 atts.getValue("action"), 458 Integer.parseInt(search(atts, "count", "0"))); 459 events.add(currentTrap); 460 } else { 461 // uncommon trap inserted during parsing. 462 // ignore for now 463 } 464 } else if (qname.startsWith("eliminate_lock")) { 465 String id = atts.getValue("compile_id"); 466 if (id != null) { 467 id = makeId(atts); 468 String kind = atts.getValue("kind"); 469 String classId = atts.getValue("class_id"); 470 currentLockElimination = new LockElimination(qname, Double.parseDouble(search(atts, "stamp")), id, kind, classId); 471 events.add(currentLockElimination); 472 } 473 } else if (qname.equals("late_inline")) { 474 long inlineId = Long.parseLong(search(atts, "inline_id")); 475 lateInlineScope = new Stack<CallSite>(); 476 site = new CallSite(-999, method(search(atts, "method"))); 477 site.setInlineId(inlineId); 478 lateInlineScope.push(site); 479 } else if (qname.equals("jvms")) { 480 // <jvms bci='4' method='java/io/DataInputStream readChar ()C' bytes='40' count='5815' iicount='20815'/> 481 if (currentTrap != null) { 482 currentTrap.addJVMS(atts.getValue("method"), Integer.parseInt(atts.getValue("bci"))); 483 } else if (lateInlineScope != null) { 484 bci = Integer.parseInt(search(atts, "bci")); 485 site = new CallSite(bci, method(search(atts, "method"))); 486 lateInlineScope.push(site); 487 } else { 488 // Ignore <eliminate_allocation type='667'>, 489 // <eliminate_lock lock='1'>, 490 // <replace_string_concat arguments='2' string_alloc='0' multiple='0'> 491 } 492 } else if (qname.equals("inline_id")) { 493 if (methodHandleSite != null) { 494 throw new InternalError("method handle site should have been replaced"); 495 } 496 long id = Long.parseLong(search(atts, "id")); 497 site.setInlineId(id); 498 } else if (qname.equals("nmethod")) { 499 String id = makeId(atts); 500 NMethod nm = new NMethod(Double.parseDouble(search(atts, "stamp")), 501 id, 502 parseLong(atts.getValue("address")), 503 parseLong(atts.getValue("size"))); 504 nmethods.put(id, nm); 505 events.add(nm); 506 } else if (qname.equals("parse")) { 507 if (failureReason != null && scopes.size() == 0 && !lateInlining) { 508 failureReason = null; 509 compile.reset(); 510 site = compile.getCall(); 511 } 512 513 if (methodHandleSite != null) { 514 throw new InternalError("method handle site should have been replaced"); 515 } 516 Method m = method(search(atts, "method")); 517 if (lateInlining && scopes.size() == 0) { 518 if (site.getMethod() != m) { 519 System.out.println(site.getMethod()); 520 System.out.println(m); 521 throw new InternalError("Unexpected method mismatch during late inlining"); 522 } 523 } 524 if (scopes.size() == 0 && !lateInlining) { 525 compile.setMethod(m); 526 scopes.push(site); 527 } else { 528 if (site.getMethod() == m) { 529 scopes.push(site); 530 } else if (scopes.peek().getCalls().size() > 2 && m == scopes.peek().last(-2).getMethod()) { 531 scopes.push(scopes.peek().last(-2)); 532 } else { 533 // C1 prints multiple method tags during inlining when it narrows method being inlinied. 534 // Example: 535 // ... 536 // <method id="813" holder="694" name="toString" return="695" flags="1" bytes="36" iicount="1"/> 537 // <call method="813" instr="invokevirtual"/> 538 // <inline_success reason="receiver is statically known"/> 539 // <method id="814" holder="792" name="toString" return="695" flags="1" bytes="5" iicount="3"/> 540 // <parse method="814"> 541 // ... 542 site.setMethod(m); 543 scopes.push(site); 544 } 545 } 546 } else if (qname.equals("parse_done")) { 547 CallSite call = scopes.pop(); 548 call.setEndNodes(Integer.parseInt(search(atts, "nodes", "0"))); 549 call.setEndLiveNodes(Integer.parseInt(search(atts, "live", "0"))); 550 call.setTimeStamp(Double.parseDouble(search(atts, "stamp"))); 551 scopes.push(call); 552 } 553 } 554 555 @Override 556 public void endElement(String uri, 557 String localName, 558 String qname) { 559 if (qname.equals("parse")) { 560 indent -= 2; 561 scopes.pop(); 562 if (scopes.size() == 0) { 563 lateInlining = false; 564 } 565 } else if (qname.equals("uncommon_trap")) { 566 currentTrap = null; 567 } else if (qname.startsWith("eliminate_lock")) { 568 currentLockElimination = null; 569 } else if (qname.equals("late_inline")) { 570 // Populate late inlining info. 571 if (scopes.size() != 0) { 572 throw new InternalError("scopes should be empty for late inline"); 573 } 574 // late inline scopes are specified in reverse order: 575 // compiled method should be on top of stack. 576 CallSite caller = lateInlineScope.pop(); 577 Method m = compile.getMethod(); 578 if (m != caller.getMethod()) { 579 System.err.println(m); 580 System.err.println(caller.getMethod() + " bci: " + bci); 581 throw new InternalError("call site and late_inline info don't match"); 582 } 583 584 // late_inline contains caller+bci info, convert it 585 // to bci+callee info used by LogCompilation. 586 CallSite lateInlineSite = compile.getLateInlineCall(); 587 ArrayDeque<CallSite> thisCallScopes = new ArrayDeque<CallSite>(); 588 do { 589 bci = caller.getBci(); 590 // Next inlined call. 591 caller = lateInlineScope.pop(); 592 CallSite callee = new CallSite(bci, caller.getMethod()); 593 callee.setInlineId(caller.getInlineId()); 594 thisCallScopes.addLast(callee); 595 lateInlineSite.add(callee); 596 lateInlineSite = callee; 597 } while (!lateInlineScope.empty()); 598 599 site = compile.getCall().findCallSite(thisCallScopes); 600 if (site == null) { 601 System.out.println("call scopes:"); 602 for (CallSite c : thisCallScopes) { 603 System.out.println(c.getMethod() + " " + c.getBci() + " " + c.getInlineId()); 604 } 605 CallSite c = thisCallScopes.getLast(); 606 if (c.getInlineId() != 0) { 607 System.out.println("Looking for call site in entire tree:"); 608 ArrayDeque<CallSite> stack = compile.getCall().findCallSite2(c); 609 for (CallSite c2 : stack) { 610 System.out.println(c2.getMethod() + " " + c2.getBci() + " " + c2.getInlineId()); 611 } 612 } 613 System.out.println(caller.getMethod() + " bci: " + bci); 614 throw new InternalError("couldn't find call site"); 615 } 616 lateInlining = true; 617 618 if (caller.getBci() != -999) { 619 System.out.println(caller.getMethod()); 620 throw new InternalError("broken late_inline info"); 621 } 622 if (site.getMethod() != caller.getMethod()) { 623 if (site.getInlineId() == caller.getInlineId()) { 624 site.setMethod(caller.getMethod()); 625 } else { 626 System.out.println(site.getMethod()); 627 System.out.println(caller.getMethod()); 628 throw new InternalError("call site and late_inline info don't match"); 629 } 630 } 631 // late_inline is followed by parse with scopes.size() == 0, 632 // 'site' will be pushed to scopes. 633 lateInlineScope = null; 634 } else if (qname.equals("task")) { 635 types.clear(); 636 methods.clear(); 637 site = null; 638 } 639 } 640 641 @Override 642 public void warning(org.xml.sax.SAXParseException e) { 643 System.err.println(e.getMessage() + " at line " + e.getLineNumber() + ", column " + e.getColumnNumber()); 644 e.printStackTrace(); 645 } 646 647 @Override 648 public void error(org.xml.sax.SAXParseException e) { 649 System.err.println(e.getMessage() + " at line " + e.getLineNumber() + ", column " + e.getColumnNumber()); 650 e.printStackTrace(); 651 } 652 653 @Override 654 public void fatalError(org.xml.sax.SAXParseException e) { 655 System.err.println(e.getMessage() + " at line " + e.getLineNumber() + ", column " + e.getColumnNumber()); 656 e.printStackTrace(); 657 } 658 }