|
| 1 | +package com.tagtraum.perf.gcviewer.imp; |
| 2 | + |
| 3 | +import java.io.IOException; |
| 4 | +import java.io.InputStream; |
| 5 | +import java.io.InputStreamReader; |
| 6 | +import java.io.LineNumberReader; |
| 7 | +import java.util.logging.Level; |
| 8 | +import java.util.logging.Logger; |
| 9 | + |
| 10 | +import com.tagtraum.perf.gcviewer.model.AbstractGCEvent; |
| 11 | +import com.tagtraum.perf.gcviewer.model.GCEvent; |
| 12 | +import com.tagtraum.perf.gcviewer.model.GCModel; |
| 13 | +import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Generation; |
| 14 | + |
| 15 | +/** |
| 16 | + * DataReaderJRockit1_4_2. |
| 17 | + * <p/> |
| 18 | + * Date: Jan 5, 2006 |
| 19 | + * Time: 5:31:50 AM |
| 20 | + * |
| 21 | + * @author <a href="mailto:hs@tagtraum.com">Hendrik Schreiber</a> |
| 22 | + */ |
| 23 | +public class DataReaderJRockit1_6_0 implements DataReader { |
| 24 | + private static Logger LOG = Logger.getLogger(DataReaderJRockit1_6_0.class.getName()); |
| 25 | + |
| 26 | + private LineNumberReader in; |
| 27 | + private static final String MEMORY_MARKER = "[memory ] "; |
| 28 | + private static final String NURSERY_SIZE = "nursery size: "; |
| 29 | + private static final String PAUSE_MARKER = "longest pause "; |
| 30 | + |
| 31 | + public DataReaderJRockit1_6_0(InputStream in) { |
| 32 | + this.in = new LineNumberReader(new InputStreamReader(in)); |
| 33 | + } |
| 34 | + |
| 35 | + public GCModel read() throws IOException { |
| 36 | + if (LOG.isLoggable(Level.INFO)) LOG.info("Reading JRockit 1.6.0 format..."); |
| 37 | + boolean gcSummary = false; |
| 38 | + try { |
| 39 | + GCModel model = new GCModel(true); |
| 40 | + model.setFormat(GCModel.Format.SUN_X_LOG_GC); |
| 41 | + String line = null; |
| 42 | + GCEvent event = null; |
| 43 | + int nurserySize = -1; |
| 44 | + while ((line = in.readLine()) != null) { |
| 45 | + // Sample JRockit log entry types to be parsed: |
| 46 | + // |
| 47 | + // [INFO ][memory ] GC mode: Garbage collection optimized for throughput, strategy: Generational Parallel Mark & Sweep |
| 48 | + // [INFO ][memory ] Heap size: 8388608KB, maximal heap size: 8388608KB, nursery size: 4194304KB |
| 49 | + // [INFO ][memory ] <start>-<end>: <type>.. |
| 50 | + // [INFO ][memory ] [OC#2] 34.287-34.351: OC 460781KB->214044KB (524288KB), 0.064 s, sum of pauses 5.580 ms, longest pause 4.693 ms. |
| 51 | + |
| 52 | + final int memoryIndex = line.indexOf(MEMORY_MARKER); |
| 53 | + if (memoryIndex == -1) { |
| 54 | + if (LOG.isLoggable(Level.FINE)) LOG.fine("Ignoring line " + in.getLineNumber() + ". Missing \"[memory ]\" marker: " + line); |
| 55 | + continue; |
| 56 | + } |
| 57 | + if (line.endsWith(MEMORY_MARKER)) { |
| 58 | + continue; |
| 59 | + } |
| 60 | + final int startLog = memoryIndex + MEMORY_MARKER.length(); |
| 61 | + // Skip "[INFO ][memory ] " |
| 62 | + |
| 63 | + // print some special JRockit summary statements to the log. |
| 64 | + if (!gcSummary) { |
| 65 | + gcSummary = line.endsWith("Memory usage report"); |
| 66 | + } |
| 67 | + if (gcSummary) { |
| 68 | + if (LOG.isLoggable(Level.INFO)) LOG.info(line.substring(startLog)); |
| 69 | + continue; |
| 70 | + } |
| 71 | + else if (line.indexOf("Prefetch distance") != -1) { |
| 72 | + if (LOG.isLoggable(Level.INFO)) LOG.info(line.substring(startLog)); |
| 73 | + continue; |
| 74 | + } |
| 75 | + else if (line.indexOf("GC mode") != -1) { |
| 76 | + if (LOG.isLoggable(Level.INFO)) LOG.info(line.substring(startLog)); |
| 77 | + continue; |
| 78 | + } |
| 79 | + else if (line.toLowerCase().indexOf("heap size:") != -1) { |
| 80 | + if (LOG.isLoggable(Level.INFO)) LOG.info(line.substring(startLog)); |
| 81 | + final int nurserySizeStart = line.indexOf(NURSERY_SIZE); |
| 82 | + final int nurserySizeEnd = line.indexOf('K', nurserySizeStart + NURSERY_SIZE.length()); |
| 83 | + if (nurserySizeStart != -1) { |
| 84 | + nurserySize = Integer.parseInt(line.substring(nurserySizeStart + NURSERY_SIZE.length(), nurserySizeEnd)); |
| 85 | + } |
| 86 | + continue; |
| 87 | + } |
| 88 | + else if (line.substring(startLog).startsWith("<")) { |
| 89 | + // ignore |
| 90 | + if (LOG.isLoggable(Level.FINE)) LOG.fine(line.substring(startLog)); |
| 91 | + continue; |
| 92 | + } |
| 93 | + else if (line.indexOf("strategy") != -1) { |
| 94 | + // ignore logs like: |
| 95 | + // [INFO ][memory ] [OC#3] Changing GC strategy from: genconcon to: genconpar, reason: Emergency parallel sweep requested. |
| 96 | + if (LOG.isLoggable(Level.FINE)) LOG.fine(line.substring(startLog)); |
| 97 | + continue; |
| 98 | + } |
| 99 | + else if ((line.indexOf("->") == -1) || (line.indexOf(']') == -1)) { |
| 100 | + // ignore logs like: |
| 101 | + // [INFO ][memory ] Run with -Xverbose:gcpause to see individual phases |
| 102 | + if (LOG.isLoggable(Level.FINE)) LOG.fine(line.substring(startLog)); |
| 103 | + continue; |
| 104 | + } |
| 105 | + // Assume this is an actual GC log. Look for time string, skip ahead of [OC#2]] |
| 106 | + // [OC#2] 34.287-34.351: OC 460781KB->214044KB (524288KB), 0.064 s, sum of pauses 5.580 ms, longest pause 4.693 ms. |
| 107 | + final int startTimeIndex = line.indexOf(']', startLog) + 1; // go to end of "[OC#2]" in above example |
| 108 | + |
| 109 | + final int colon = line.indexOf(':', startTimeIndex); |
| 110 | + if (colon == -1) { |
| 111 | + if (LOG.isLoggable(Level.WARNING)) LOG.warning("Malformed line (" + in.getLineNumber() + "). Missing colon after start time: " + line); |
| 112 | + continue; |
| 113 | + } |
| 114 | + event = new GCEvent(); |
| 115 | + |
| 116 | + //34.287-34.351: OC 460781KB->214044KB (524288KB), 0.064 s, sum of pauses 5.580 ms, longest pause 4.693 ms. |
| 117 | + |
| 118 | + // set timestamp |
| 119 | + final String timestampString = line.substring(startTimeIndex, colon); |
| 120 | + final int minus = timestampString.indexOf('-'); |
| 121 | + if (minus == -1) { |
| 122 | + event.setTimestamp(Double.parseDouble(timestampString)); |
| 123 | + } |
| 124 | + else { |
| 125 | + event.setTimestamp(Double.parseDouble(timestampString.substring(0, minus))); |
| 126 | + } |
| 127 | + |
| 128 | + // set type |
| 129 | + final int typeStart = skipSpaces(colon+1, line); |
| 130 | + int typeEnd = typeStart; |
| 131 | + while (!Character.isDigit(line.charAt(++typeEnd))) {} |
| 132 | + final AbstractGCEvent.Type type = AbstractGCEvent.Type.parse("jrockit." + line.substring(typeStart, typeEnd).trim()); |
| 133 | + if (type == null) { |
| 134 | + if (LOG.isLoggable(Level.INFO)) LOG.info("Failed to determine type: " + line.substring(startTimeIndex)); |
| 135 | + continue; |
| 136 | + } |
| 137 | + event.setType(type); |
| 138 | + |
| 139 | + // Parse GC before/after sizes: "460781KB->214044KB (524288KB)" |
| 140 | + // before |
| 141 | + final int startBefore = typeEnd; |
| 142 | + final int endBefore = line.indexOf('K', startBefore); |
| 143 | + event.setPreUsed(Integer.parseInt(line.substring(startBefore, endBefore))); |
| 144 | + |
| 145 | + // after |
| 146 | + final int startAfter = endBefore+4; |
| 147 | + final int endAfter = line.indexOf('K', startAfter); |
| 148 | + event.setPostUsed(Integer.parseInt(line.substring(startAfter, endAfter))); |
| 149 | + |
| 150 | + // total |
| 151 | + final int startTotal = line.indexOf('(', endAfter) + 1; |
| 152 | + final int endTotal = line.indexOf('K', startTotal); |
| 153 | + event.setTotal(Integer.parseInt(line.substring(startTotal, endTotal))); |
| 154 | + |
| 155 | + // pause |
| 156 | + // 7786210KB->3242204KB (8388608KB), 0.911 s, sum of pauses 865.900 ms, longest pause 865.900 ms. |
| 157 | + final int startPause = line.indexOf(PAUSE_MARKER, endTotal) + PAUSE_MARKER.length(); |
| 158 | + final int endPause = line.indexOf(' ', startPause); |
| 159 | + event.setPause(Double.parseDouble(line.substring(startPause, endPause)) / 1000.0d); |
| 160 | + model.add(event); |
| 161 | + |
| 162 | + // add artificial detail events |
| 163 | + if (nurserySize != -1 && event.getType().getGeneration() == Generation.YOUNG) { |
| 164 | + GCEvent detailEvent = new GCEvent(); |
| 165 | + detailEvent.setType(event.getType()); |
| 166 | + detailEvent.setTimestamp(event.getTimestamp()); |
| 167 | + detailEvent.setTotal(nurserySize); |
| 168 | + event.add(detailEvent); |
| 169 | + } |
| 170 | + if (nurserySize != -1 && event.getType().getGeneration() == Generation.TENURED) { |
| 171 | + GCEvent detailEvent = new GCEvent(); |
| 172 | + detailEvent.setType(event.getType()); |
| 173 | + detailEvent.setTimestamp(event.getTimestamp()); |
| 174 | + detailEvent.setTotal(event.getTotal() - nurserySize); |
| 175 | + event.add(detailEvent); |
| 176 | + } |
| 177 | + } |
| 178 | + return model; |
| 179 | + } finally { |
| 180 | + if (in != null) |
| 181 | + try { |
| 182 | + in.close(); |
| 183 | + } catch (IOException ioe) { |
| 184 | + } |
| 185 | + if (LOG.isLoggable(Level.INFO)) LOG.info("Reading done."); |
| 186 | + } |
| 187 | + } |
| 188 | + |
| 189 | + private static int skipSpaces(int start, String line) { |
| 190 | + int i = start; |
| 191 | + while (line.charAt(i) == ' ') { |
| 192 | + i++; |
| 193 | + } |
| 194 | + return i; |
| 195 | + } |
| 196 | +} |
0 commit comments