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 }