Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add support for Go GC logging #196

Merged
merged 1 commit into from
Jul 26, 2018
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
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;
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why are you only using groups 4 + 6 for the pause time? What is group 5?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Group 5 is the "concurrent mark and scan". I left it out because I only considered the stop-the-world times relevant. Maybe I'm wrong, though. I was missing some Javadoc on the fields of the GCEvent class, therefore I could only guess what is important and what is not.

The full documentation is at https://golang.org/pkg/runtime/#hdr-Environment_Variables, the paragraph starting with gctrace:. I thought mentioning the above URL in the Javadoc would be sufficient. But sure, it wouldn't hurt to document each capturing group.

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"
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So, the pause for this event is 68 + 0.51 ms. What about the 0.36 ms?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The 0.36 ms is part of the GC time. I did not count it since I was only interested in the stop-the-world time. You can add it if you want. As I said above, the GC fields were not documented enough for me to decide which duration to include and which to omit.

+ "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