Skip to content

Loading…

JSON format profile printer (additions) #326

Merged
merged 3 commits into from

3 participants

@iconara

This is some additions to pull request #270, as per the discussion there.

I've added a layer of indirection between Ruby#printProfileData and the profile printers to make it possible to write a profile to a file. I also added ProfilePrinter#printHeader and #printFooter to make it possible to write all thread profiles into the same file when the format is HTML or JSON, without the output being all weird. I've also updated all profile printers to support this.

All changes should be backwards compatible, and I've marked the old version of Ruby#printProfileData that took a PrintStream as deprecated.

I've added an optional argument to --profile.xxx that is the file to write to. Please check that part extra carefully so that I haven't done anything stupid. There wasn't any other argument that took optional parameters on the form --xyz optarg, only arguments like -Ioptarg or that always expected a value. The way I did it was by checking if there is one more argument, and making sure that argument doesn't start with a dash. It will fail in this case: ruby --profile.json hello_world.rb, because hello_world.rb will be interpreted as the argument to --profile.json, not the script to run. I don't know if this is acceptable. Maybe it would be better to do it like --profile.json=output.json, but that's not how the other arguments that take values work (e.g. --compat RUBY_18).

I'm not entirely satisfied with the way profiles are printed, and I'd like to do some more changes to structure it differently, but I think that another pull request that can aim for a later release.

iconara added some commits
@iconara iconara Added --profile.json to the command usage message eeef5f1
@iconara iconara Profile reports can now be written to a file
Support for writing profile reports to files, notably support for writing profiles from multiple threads to the same JSON or HTML file without syntax errors.

There's a new abstraction that handles profile printing: ProfileOutput. Together with new methods on ProfilePrinter, printHeader, printFooter and a new parameter to printProfile (first), it can orchestrate the the profile printers so that they print the right things at the right time.
fa914f6
@iconara iconara Added help text about the optional argument to --profile.xxx 1caa496
@iconara iconara referenced this pull request
Merged

JSON format profile printer #270

@enebo
JRuby Team member

Theo, we will merge this right after final for 1.7.1. rc2 (which very very very likely will be 1.7.0) will be out on Monday and although this all looks solid to me is just a tad too close to this release.

@iconara

Thanks! Getting it into 1.7.0 would have been awesome, but I completely understand that that is not possible, no problem at all. I'm just happy that you like it.

@headius headius merged commit 7ba1531 into jruby:master

1 check passed

Details default The Travis build passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Commits on Oct 1, 2012
  1. @iconara
  2. @iconara

    Profile reports can now be written to a file

    iconara committed
    Support for writing profile reports to files, notably support for writing profiles from multiple threads to the same JSON or HTML file without syntax errors.
    
    There's a new abstraction that handles profile printing: ProfileOutput. Together with new methods on ProfilePrinter, printHeader, printFooter and a new parameter to printProfile (first), it can orchestrate the the profile printers so that they print the right things at the right time.
  3. @iconara
View
3 lib/ruby/shared/jruby/profiler/shutdown_hook.rb
@@ -3,9 +3,8 @@
trap 'INT' do
runtime = JRuby.runtime
runtime.thread_service.ruby_thread_map.each do |t, rubythread|
- java.lang.System.err.println "\n#{t} profile results:"
context = JRuby.reference(rubythread).context
- runtime.printProfileData(context.profile_data, java.lang.System.err)
+ runtime.printProfileData(context.profile_data)
end
exit
end
View
22 src/org/jruby/Ruby.java
@@ -115,6 +115,7 @@
import org.jruby.runtime.profile.ProfileData;
import org.jruby.runtime.profile.ProfilePrinter;
import org.jruby.runtime.profile.ProfiledMethod;
+import org.jruby.runtime.profile.ProfileOutput;
import org.jruby.runtime.scope.ManyVarsDynamicScope;
import org.jruby.threading.DaemonThreadFactory;
import org.jruby.util.ByteList;
@@ -2938,9 +2939,8 @@ public void tearDown(boolean systemExit) {
if (config.isProfilingEntireRun()) {
// not using logging because it's formatted
- System.err.println("\nmain thread profile results:");
ProfileData profileData = threadService.getMainThread().getContext().getProfileData();
- printProfileData(profileData, System.err);
+ printProfileData(profileData);
}
if (systemExit && status != 0) {
@@ -2953,13 +2953,25 @@ public void tearDown(boolean systemExit) {
* @param profileData
* @param out
* @see RubyInstanceConfig#getProfilingMode()
+ * @deprecated use printProfileData(ProfileData) or printProfileData(ProfileData,ProfileOutput)
*/
public void printProfileData(ProfileData profileData, PrintStream out) {
+ printProfileData(profileData, new ProfileOutput(out));
+ }
+
+ public void printProfileData(ProfileData profileData) {
+ printProfileData(profileData, config.getProfileOutput());
+ }
+
+ public void printProfileData(ProfileData profileData, ProfileOutput output) {
ProfilePrinter profilePrinter = ProfilePrinter.newPrinter(config.getProfilingMode(), profileData);
- if (profilePrinter != null) profilePrinter.printProfile(out);
- else out.println("\nno printer for profile mode: " + config.getProfilingMode() + " !");
+ if (profilePrinter != null) {
+ output.printProfile(profilePrinter);
+ } else {
+ out.println("\nno printer for profile mode: " + config.getProfilingMode() + " !");
+ }
}
-
+
// new factory methods ------------------------------------------------------------------------
public RubyArray newEmptyArray() {
View
10 src/org/jruby/RubyInstanceConfig.java
@@ -62,6 +62,7 @@
import org.jruby.runtime.backtrace.TraceType;
import org.jruby.runtime.load.LoadService;
import org.jruby.runtime.load.LoadService19;
+import org.jruby.runtime.profile.ProfileOutput;
import org.jruby.util.ClassCache;
import org.jruby.util.InputStreamMarkCursor;
import org.jruby.util.JRubyFile;
@@ -1000,6 +1001,14 @@ public ProfilingMode getProfilingMode() {
return profilingMode;
}
+ public void setProfileOutput(ProfileOutput output) {
+ this.profileOutput = output;
+ }
+
+ public ProfileOutput getProfileOutput() {
+ return profileOutput;
+ }
+
public boolean hasShebangLine() {
return hasShebangLine;
}
@@ -1208,6 +1217,7 @@ public int getProfileMaxMethods() {
private String externalEncoding = null;
private ProfilingMode profilingMode = ProfilingMode.OFF;
+ private ProfileOutput profileOutput = new ProfileOutput(System.err);
private ClassLoader contextLoader = Thread.currentThread().getContextClassLoader();
private ClassLoader loader = contextLoader == null ? RubyInstanceConfig.class.getClassLoader() : contextLoader;
View
2 src/org/jruby/internal/runtime/RubyRunnable.java
@@ -124,7 +124,7 @@ public void run() {
// dump profile, if any
if (runtime.getInstanceConfig().isProfilingEntireRun()) {
- runtime.printProfileData(context.getProfileData(), System.err);
+ runtime.printProfileData(context.getProfileData());
}
}
} catch (ThreadKill tk) {
View
6 src/org/jruby/runtime/profile/FlatProfilePrinter.java
@@ -46,8 +46,12 @@ public FlatProfilePrinter(ProfileData profileData) {
FlatProfilePrinter(ProfileData profileData, Invocation topInvocation) {
super(profileData, topInvocation);
}
+
+ public void printHeader(PrintStream out) {
+ out.printf("\n%s profile results:\n", getThreadName());
+ }
- public void printProfile(PrintStream out) {
+ public void printProfile(PrintStream out, boolean first) {
final Invocation topInvocation = getTopInvocation();
out.printf("Total time: %s\n\n", nanoString(topInvocation.getDuration()));
View
13 src/org/jruby/runtime/profile/GraphProfilePrinter.java
@@ -40,10 +40,19 @@ public GraphProfilePrinter(ProfileData profileData) {
GraphProfilePrinter(ProfileData profileData, Invocation topInvocation) {
super(profileData, topInvocation);
}
+
+ public void printHeader(PrintStream out) {
+ out.printf("\n%s profile results:\n", getThreadName());
+ }
- public void printProfile(PrintStream out) {
+ public void printProfile(PrintStream out, boolean first) {
final Invocation topInvocation = getTopInvocation();
- out.printf("\nTotal time: %s\n\n", nanoString(topInvocation.getDuration()));
+
+ if (!first) {
+ out.println();
+ }
+
+ out.printf("Total time: %s\n\n", nanoString(topInvocation.getDuration()));
out.println(" %total %self total self children calls name");
View
20 src/org/jruby/runtime/profile/HtmlProfilePrinter.java
@@ -43,12 +43,21 @@ public HtmlProfilePrinter(ProfileData profileData) {
super(profileData, topInvocation);
}
- @Override
- public void printProfile(PrintStream out) {
- final Invocation topInvocation = getTopInvocation();
+ public void printHeader(PrintStream out) {
out.println(head);
out.println("<body>");
- out.println("<h1>Profile Report</h1>");
+ }
+
+ public void printFooter(PrintStream out) {
+ out.println("</body>");
+ out.println("</html>");
+ }
+
+ @Override
+ public void printProfile(PrintStream out, boolean first) {
+ final Invocation topInvocation = getTopInvocation();
+
+ out.printf("<h1>Profile Report: %s</h1>\n", getThreadName());
out.println("<h3>Total time: " + nanoString(topInvocation.getDuration()) + "</h3>");
out.println("<table>\n" +
@@ -131,9 +140,6 @@ public int compare(Integer child1, Integer child2) {
}
}
out.println("</table>");
-
- out.println("</body>");
- out.println("</html>");
}
private void printInvocationOfChild(PrintStream out, IntHashMap<MethodData> methods, MethodData data, int childSerial, String callerName, InvocationSet invs) {
View
30 src/org/jruby/runtime/profile/JsonProfilePrinter.java
@@ -44,26 +44,32 @@ public JsonProfilePrinter(ProfileData profileData) {
super(profileData, topInvocation);
}
- public void printProfile(PrintStream out) {
+ public void printHeader(PrintStream out) {
+ out.println("{\n\thread_profiles:[");
+ }
+
+ public void printFooter(PrintStream out) {
+ out.println("\n\t]\n}");
+ }
+
+ public void printProfile(PrintStream out, boolean first) {
Invocation topInvocation = getTopInvocation();
IntHashMap<MethodData> methods = methodData(topInvocation);
- String threadName = null;
+ String threadName = getThreadName();
- if (getProfileData().getThreadContext().getThread() == null) {
- threadName = Thread.currentThread().getName();
- } else {
- threadName = getProfileData().getThreadContext().getThread().getNativeThread().getName();
+ if (!first) {
+ out.println(",");
}
- out.println("{");
- out.printf("\t\"total_time\":%s,\n", nanosToSecondsString(topInvocation.getDuration()));
- out.printf("\t\"thread_name\":\"%s\",\n", threadName);
- out.println("\t\"methods\":[");
+ out.println("\t\t{");
+ out.printf("\t\t\t\"total_time\":%s,\n", nanosToSecondsString(topInvocation.getDuration()));
+ out.printf("\t\t\t\"thread_name\":\"%s\",\n", threadName);
+ out.println("\t\t\t\"methods\":[");
Iterator<MethodData> i = methods.values().iterator();
while (i.hasNext()) {
MethodData method = i.next();
- out.print("\t\t");
+ out.print("\t\t\t\t");
out.print(methodToJson(method));
if (i.hasNext()) {
out.print(",");
@@ -71,7 +77,7 @@ public void printProfile(PrintStream out) {
out.println();
}
- out.print("\t]\n}\n");
+ out.print("\t\t\t]\n\t\t}");
}
private String methodToJson(MethodData method) {
View
43 src/org/jruby/runtime/profile/ProfileOutput.java
@@ -0,0 +1,43 @@
+package org.jruby.runtime.profile;
+
+
+import java.io.PrintStream;
+import java.io.FileOutputStream;
+import java.io.File;
+import java.io.FileNotFoundException;
+
+
+public class ProfileOutput {
+ private final PrintStream stream;
+
+ private boolean headerPrinted = false;
+
+
+ public ProfileOutput(PrintStream out) {
+ this.stream = out;
+ }
+
+ public ProfileOutput(File out) throws FileNotFoundException {
+ this.stream = new PrintStream(new FileOutputStream(out));
+ }
+
+ public void printProfile(ProfilePrinter printer) {
+ if (headerPrinted) {
+ printer.printProfile(stream, false);
+ } else {
+ printer.printHeader(stream);
+ printer.printProfile(stream, true);
+ headerPrinted = true;
+ footerAndCleanupOnShutdown(printer);
+ }
+ }
+
+ private void footerAndCleanupOnShutdown(final ProfilePrinter printer) {
+ Runtime.getRuntime().addShutdownHook(new Thread() {
+ public void run() {
+ printer.printFooter(stream);
+ stream.close();
+ }
+ });
+ }
+}
View
19 src/org/jruby/runtime/profile/ProfilePrinter.java
@@ -47,7 +47,7 @@
* @param mode the profiling mode
* @param profileData
* @param runtime
- * @see Ruby#printProfileData(org.jruby.runtime.profile.ProfileData, java.io.PrintStream)
+ * @see Ruby#printProfileData(org.jruby.runtime.profile.ProfileData)
*/
public static ProfilePrinter newPrinter(ProfilingMode mode, ProfileData profileData) {
return newPrinter(mode, profileData, null);
@@ -93,8 +93,15 @@ public ProfileData getProfileData() {
protected Invocation getTopInvocation() {
return topInvocation;
}
+
+ public void printHeader(PrintStream out) { }
+ public void printFooter(PrintStream out) { }
- public abstract void printProfile(PrintStream out) ;
+ public void printProfile(PrintStream out) {
+ printProfile(out, false);
+ }
+
+ public abstract void printProfile(PrintStream out, boolean first) ;
public void printProfile(RubyIO out) {
printProfile(new PrintStream(out.getOutStream()));
@@ -114,6 +121,14 @@ boolean isThisProfilerInvocation(int serial) {
( name.hashCode() == stop.hashCode() && name.equals(stop) );
}
+ public String getThreadName() {
+ if (getProfileData().getThreadContext().getThread() == null) {
+ return Thread.currentThread().getName();
+ } else {
+ return getProfileData().getThreadContext().getThread().getNativeThread().getName();
+ }
+ }
+
public String methodName(int serial) {
return profileData.methodName(serial);
}
View
39 src/org/jruby/util/cli/ArgumentProcessor.java
@@ -32,12 +32,14 @@
import org.jruby.Ruby;
import org.jruby.RubyInstanceConfig;
import org.jruby.exceptions.MainExitException;
+import org.jruby.runtime.profile.ProfileOutput;
import org.jruby.util.JRubyFile;
import org.jruby.util.KCode;
import org.jruby.util.SafePropertyAccessor;
import java.io.File;
import java.io.IOException;
+import java.io.FileNotFoundException;
import java.util.ArrayList;
import java.util.Arrays;
import java.util.List;
@@ -399,20 +401,29 @@ private void processArgument() {
} else if (argument.equals("--fast")) {
config.setCompileMode(RubyInstanceConfig.CompileMode.FORCE);
break FOR;
- } else if (argument.equals("--profile.api")) {
- config.setProfilingMode(RubyInstanceConfig.ProfilingMode.API);
- break FOR;
- } else if (argument.equals("--profile") || argument.equals("--profile.flat")) {
- config.setProfilingMode(RubyInstanceConfig.ProfilingMode.FLAT);
- break FOR;
- } else if (argument.equals("--profile.graph")) {
- config.setProfilingMode(RubyInstanceConfig.ProfilingMode.GRAPH);
- break FOR;
- } else if (argument.equals("--profile.html")) {
- config.setProfilingMode(RubyInstanceConfig.ProfilingMode.HTML);
- break FOR;
- } else if (argument.equals("--profile.json")) {
- config.setProfilingMode(RubyInstanceConfig.ProfilingMode.JSON);
+ } else if (argument.startsWith("--profile")) {
+ int dotIndex = argument.indexOf(".");
+ if (dotIndex == -1) {
+ config.setProfilingMode(RubyInstanceConfig.ProfilingMode.FLAT);
+ } else {
+ String profilingMode = argument.substring(dotIndex + 1, argument.length());
+ try {
+ config.setProfilingMode(RubyInstanceConfig.ProfilingMode.valueOf(profilingMode.toUpperCase()));
+ } catch (IllegalArgumentException e) {
+ throw new MainExitException(1, String.format("jruby: unknown profiler mode \"%s\"", profilingMode));
+ }
+ }
+ if (config.getProfilingMode() != RubyInstanceConfig.ProfilingMode.API) {
+ characterIndex = argument.length();
+ if (argumentIndex < arguments.size() && !arguments.get(argumentIndex + 1).originalValue.startsWith("-")) {
+ String outputFile = grabValue(""); // no error message, since we already checked that the arg exists
+ try {
+ config.setProfileOutput(new ProfileOutput(new File(outputFile)));
+ } catch (FileNotFoundException e) {
+ throw new MainExitException(1, String.format("jruby: %s", e.getMessage()));
+ }
+ }
+ }
break FOR;
} else if (argument.equals("--1.9")) {
config.setCompatVersion(CompatVersion.RUBY1_9);
View
3 src/org/jruby/util/cli/OutputStrings.java
@@ -59,6 +59,9 @@ public static String getBasicUsageHelp() {
.append(" --profile.flat synonym for --profile\n")
.append(" --profile.graph run with instrumented (timed) profiling, graph format\n")
.append(" --profile.html run with instrumented (timed) profiling, graph format in HTML\n")
+ .append(" --profile.json run with instrumented (timed) profiling, graph format in JSON\n")
+ .append(" --profile.xxx accepts a file to output the profile into\n")
+ .append(" as an optional argument.\n")
.append(" --client use the non-optimizing \"client\" JVM\n")
.append(" (improves startup; default)\n")
.append(" --server use the optimizing \"server\" JVM (improves perf)\n")
Something went wrong with that request. Please try again.