Skip to content

Commit

Permalink
Add support for Go GC logging
Browse files Browse the repository at this point in the history
The Go programming language has a very dense GC logging format, which
is difficult to read for humans. It looks like this:

gc 1 @0.027s 35%: 15+3.3+0.41 ms clock, 46+0.66/2.3/3.0+1.2 ms cpu...
gc 2 @0.060s 28%: 3.6+7.6+0.37 ms clock, 10+0.33/0/6.5+1.1 ms cpu,...
gc 3 @0.079s 26%: 0.072+6.7+0.68 ms clock, 0.21+3.9/0.060/11+2.0 m...
gc 4 @0.104s 21%: 0.16+14+0.31 ms clock, 0.48+5.2/0.16/14+0.94 ms ...
gc 5 @0.140s 18%: 0.12+14+0.73 ms clock, 0.36+3.8/4.1/16+2.1 ms cp...
gc 6 @0.179s 17%: 0.20+15+0.48 ms clock, 0.62+5.1/10/19+1.4 ms cpu...
gc 7 @0.222s 16%: 0.12+19+0.21 ms clock, 0.37+11/0.064/19+0.64 ms ...
gc 8 @0.292s 15%: 0.10+13+0.34 ms clock, 0.32+10/11/13+1.0 ms cpu,...
gc 9 @0.936s 4%: 0.053+25+0.67 ms clock, 0.16+0.30/0.36/30+2.0 ms ...
gc 10 @1.123s 5%: 0.073+30+0.52 ms clock, 0.22+1.7/29/1.4+1.5 ms c...
gc 11 @1.369s 4%: 0.066+34+0.47 ms clock, 0.19+10/20/2.1+1.4 ms cp...

It fits well into the GCViewer model, although Go has nothing to do with
the JVM.
  • Loading branch information
rillig committed Feb 25, 2018
1 parent 12f1f94 commit deda507
Show file tree
Hide file tree
Showing 6 changed files with 772 additions and 0 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -207,6 +207,10 @@ else if (s.indexOf("starting collection, threshold allocation reached.") != -1)
if (getLogger().isLoggable(Level.INFO)) getLogger().info("File format: IBM i5/OS 1.4.2");
return new DataReaderIBMi5OS1_4_2(gcResource, in);
}
else if (s.contains("\ngc ")) {
if (getLogger().isLoggable(Level.INFO)) getLogger().info("File format: Go");
return new DataReaderGo(gcResource, in);
}
return null;
}

Expand Down
89 changes: 89 additions & 0 deletions src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderGo.java
Original file line number Diff line number Diff line change
@@ -0,0 +1,89 @@
package com.tagtraum.perf.gcviewer.imp;

import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
import com.tagtraum.perf.gcviewer.model.GCEvent;
import com.tagtraum.perf.gcviewer.model.GCModel;
import com.tagtraum.perf.gcviewer.model.GCResource;
import com.tagtraum.perf.gcviewer.util.ParseInformation;
import java.io.IOException;
import java.io.InputStream;
import java.io.LineNumberReader;
import java.io.UnsupportedEncodingException;
import java.util.logging.Level;
import java.util.regex.Matcher;
import java.util.regex.Pattern;

/**
* Parses GC log output from Go 1.9.
*
* @author <a href="mailto:[email protected]">Roland Illig</a>
* @see <a href="https://golang.org/pkg/runtime/#hdr-Environment_Variables">Go documentation</a>
*/
public class DataReaderGo extends AbstractDataReader {

private static final Pattern GCLINE = Pattern.compile(""
+ "gc "
+ "(\\d+) "
+ "@(\\d+\\.\\d+)s "
+ "(\\d+)%: "
+ "(\\d+(?:\\.\\d+)?)\\+"
+ "(\\d+(?:\\.\\d+)?)\\+"
+ "(\\d+(?:\\.\\d+)?) ms clock, "
+ "(\\d+(?:\\.\\d+)?)\\+"
+ "(\\d+(?:\\.\\d+)?)/"
+ "(\\d+(?:\\.\\d+)?)/"
+ "(\\d+(?:\\.\\d+)?)\\+"
+ "(\\d+(?:\\.\\d+)?) ms cpu, "
+ "(\\d+)->"
+ "(\\d+)->"
+ "(\\d+) MB, "
+ "(\\d+) MB goal, "
+ "(\\d+) P");

public DataReaderGo(GCResource gcResource, InputStream in) throws UnsupportedEncodingException {
super(gcResource, in);
}

public GCModel read() throws IOException {
if (getLogger().isLoggable(Level.INFO)) getLogger().info("Reading Go format...");

try (LineNumberReader in = this.in) {
GCModel model = new GCModel();
model.setFormat(GCModel.Format.GO);
ParseInformation parsePosition = new ParseInformation(0);

Matcher matcher = GCLINE.matcher("");
String line;
while ((line = in.readLine()) != null && shouldContinue()) {
parsePosition.setIndex(0);
parsePosition.setLineNumber(in.getLineNumber());
if (!matcher.reset(line).matches()) {
continue;
}

try {
AbstractGCEvent<?> gcEvent = parseMatch(matcher);
model.add(gcEvent);
} catch (Exception pe) {
if (getLogger().isLoggable(Level.WARNING)) getLogger().warning(pe.toString());
if (getLogger().isLoggable(Level.FINE)) getLogger().log(Level.FINE, pe.getMessage(), pe);
}
}
return model;
} finally {
if (getLogger().isLoggable(Level.INFO)) getLogger().info("Done reading.");
}
}

private AbstractGCEvent<?> parseMatch(Matcher matcher) {
double relativeTime = Double.parseDouble(matcher.group(2));
double stopTheWorld1Time = Double.parseDouble(matcher.group(4)) / 1000.0;
double stopTheWorld2Time = Double.parseDouble(matcher.group(6)) / 1000.0;
int preUsed = Integer.parseInt(matcher.group(12)) * 1024;
int alive = Integer.parseInt(matcher.group(13)) * 1024;
int postUsed = Integer.parseInt(matcher.group(14)) * 1024;

double pause = stopTheWorld1Time + stopTheWorld2Time;
return new GCEvent(relativeTime, preUsed, postUsed, alive, pause, AbstractGCEvent.Type.GC);
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -1065,5 +1065,6 @@ public String toString() {
public static final Format IBM_VERBOSE_GC = new Format("IBM -verbose:gc");
public static final Format SUN_1_2_2VERBOSE_GC = new Format("Sun 1.2.2 -verbose:gc");
public static final Format UNIFIED_JVM_LOGGING = new Format("Unified jvm logging -Xlog:gc");
public static final Format GO = new Format("Go");
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -31,6 +31,7 @@ public class UnittestHelper {

private static final String FOLDER_OPENJDK = "openjdk";
public enum FOLDER {
GO("go"),
HP("hp"),
IBM("ibm"),
JROCKIT("jrockit"),
Expand Down
39 changes: 39 additions & 0 deletions src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderGo.java
Original file line number Diff line number Diff line change
@@ -0,0 +1,39 @@
package com.tagtraum.perf.gcviewer.imp;

import static org.junit.Assert.assertEquals;

import com.tagtraum.perf.gcviewer.UnittestHelper;
import com.tagtraum.perf.gcviewer.model.GCModel;
import com.tagtraum.perf.gcviewer.model.GcResourceFile;
import java.io.ByteArrayInputStream;
import java.io.IOException;
import java.io.InputStream;
import org.junit.Test;

public class TestDataReaderGo {

@Test
public void test() throws IOException {
String gcLog = ""
+ "gc starting...\n" // Such a line is not produced by the Go GC; it is just for testing
+ "gc 1 @997.597s 3%: 68+0.36+0.51 ms clock, 205+0/16/89+1.5 ms cpu, 84->84->42 MB, 86 MB goal, 3 P\n"
+ "a line unrelated to GC logging\n"
+ "gc 2 @997.597s 3%: 68+0.36+0.51 ms clock, 205+0/16/89+1.5 ms cpu, 11111111111111111111111111111111111->84->42 MB, 86 MB goal, 3 P\n"
+ "gc 3 @997.597s 3%: 68+0.36+0.51 ms clock, 205+0/16/89+1.5 ms cpu, 84->84->42 MB, 86 MB goal, 3 P\n";
ByteArrayInputStream in = new ByteArrayInputStream(gcLog.getBytes("US-ASCII"));
DataReader reader = new DataReaderGo(new GcResourceFile("byteArray"), in);
GCModel model = reader.read();

assertEquals(2, model.size());
}

@Test
public void exampleLog() throws IOException {
String fileName = "go1.9.txt";
InputStream in = UnittestHelper.getResourceAsStream(UnittestHelper.FOLDER.GO, fileName);
DataReader reader = new DataReaderGo(new GcResourceFile(fileName), in);
GCModel model = reader.read();

assertEquals(635, model.size());
}
}
Loading

0 comments on commit deda507

Please sign in to comment.