Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with
or
.
Download ZIP

Loading…

JSON format profile printer #270

Merged
merged 5 commits into from

4 participants

@iconara

This is the start of a conversation, I don't expect this pull request to be merged in as-is. I hope that with your help I can make it into something that, IMHO, would improve the JRuby profilers usefulness greatly.

I've written a profile printer that outputs a raw profile in the form of a JSON document. My motivation is that I want to visualize the profiler output with GraphViz, like perftools.rb does, but I figured that instead of writing a DOT profile printer and add to the list of specialized profiler printers, I'd add a generic profile output format that could be used by others to visualize the profiler output in different ways. The existing HTML format could easily be ported to use the raw output, and be moved out of JRuby core, for example.

To give you an idea of what I'm trying to do, here's a picture (it's generated from an actual run of the profiler):

I've previously spiked the DOT format printing, but because of how the profiler API works it's hard to do exactly what I want from the outside.

To go forward with this I'd like your input on a few things:

  • Is this a good idea? (I spoke to Tom at JRubyConf EU and he seemed to like it)
  • To be useful you need to be able to write the output to a file (this actually goes for the existing HTML format too), what do you think of making ruby --profile.json=path/to/file.json possible?
  • Currently JRuby prints the profile of each thread separately. I would like to change that so that it would be possible to write the profiles of all threads into the same file. I can make the changes, but it would require much more invasive changes, so far I've only made additions, and if you have any opinions on how it should be done, please let me know.
  • I've written tests for my JSON output, and I've run all the profiler printer tests, and the whole test suite. There's lots of failures, both with and without my code, so I can't be absolutely sure I haven't broken anything. It looks as if I get the same failures. Either I don't understand properly how to run the tests, or they haven't been updated in a while. If you like this patch, and if I'll continue to make changes to the profiler output, maybe I can clean up the old tests too.
  • The output is JSON, but I didn't want to add a dependency on a full-fledged JSON library just to create the JSON, but maybe there's already something there I could use, I couldn't really tell. Since I didn't want to buffer the whole document in memory before printing it, but printing it completely streaming would require much more code, I made a hybrid: each method is rendered as a string, and printed separately, and since each method is just a few hundred bytes it felt like a good trade off. I think that part looks ok, but unfortunately printing the header properties and the ending "}" is different and ugly.
  • All durations are in nanoseconds, but it seems to me like they only have millisecond resolution. I output the durations in decimal seconds, but if the resolution isn't greater than milliseconds I think I prefer to output in integer milliseconds.

Sorry if this way way too long, but I wanted to get all my thoughts down. This is my first JRuby patch and I want to get it right.

@travisbot

This pull request fails (merged 3a720ed into ff42564).

@travisbot

This pull request passes (merged e5d068d into ff42564).

@nirvdrum
Collaborator

Overall, I'm +1 on the idea. --profile is great to have, but I very much miss perftools.rb and the various output formats.

@headius headius merged commit cc2a6a2 into jruby:master

1 check passed

Details default The Travis build passed
@headius
Owner

Ugh, I got on a pull parade and pulled this accidentally. Reviewing it now...

@headius
Owner

Ok, well this looks ok after a quick review. We'll happily accept additional patches to improve it.

WRT your questions above...

  • Is this a good idea? (I spoke to Tom at JRubyConf EU and he seemed to like it)

Yes, I think it's a great idea!

  • To be useful you need to be able to write the output to a file (this actually goes for the existing HTML format too), what do you think of making ruby --profile.json=path/to/file.json possible?

Hmm...yes I believe this is possible. We would just need to tweak the argument processing to expect a value after --profile.json flag. See ArgumentProcessor.java logic for --compat.

  • Currently JRuby prints the profile of each thread separately. I would like to change that so that it would be possible to write the profiles of all threads into the same file. I can make the changes, but it would require much more invasive changes, so far I've only made additions, and if you have any opinions on how it should be done, please let me know.

Yes, ideally this would output as a single batch. Perhaps the logic for printing could simply do an outer json structure that holds each thread within it? Or did you mean to merge the results across threads (to which I might respond "it's just data...the tool consuming it can merge results if it wants").

  • I've written tests for my JSON output, and I've run all the profiler printer tests, and the whole test suite. There's lots of failures, both with and without my code, so I can't be absolutely sure I haven't broken anything. It looks as if I get the same failures. Either I don't understand properly how to run the tests, or they haven't been updated in a while. If you like this patch, and if I'll continue to make changes to the profiler output, maybe I can clean up the old tests too.

There are two failures when I run rake spec:profiler that appear to be there with or without your changes. We need to fix those, but I'm not worried about them for the moment.

  • The output is JSON, but I didn't want to add a dependency on a full-fledged JSON library just to create the JSON, but maybe there's already something there I could use, I couldn't really tell. Since I didn't want to buffer the whole document in memory before printing it, but printing it completely streaming would require much more code, I made a hybrid: each method is rendered as a string, and printed separately, and since each method is just a few hundred bytes it felt like a good trade off. I think that part looks ok, but unfortunately printing the header properties and the ending "}" is different and ugly.

We do ship the equivalent of the 'json' gem...perhaps we could leverage that? Write the printing in Ruby?

  • All durations are in nanoseconds, but it seems to me like they only have millisecond resolution. I output the durations in decimal seconds, but if the resolution isn't greater than milliseconds I think I prefer to output in integer milliseconds.

We can probably make then nanoseconds; somewhere must be normalizing to milliseconds, either by using System.currentTimeMillis instead of nanoTime or by forcibly truncating values. Good one for another PR.

@iconara

Great, I'll try to the file output things in as soon as I can. Would be great to get into 1.7.

I meant that I wanted to get all thread profiles into the same file, one after the other. The problem is that threads exit at any time, and currently RubyRunnable hard codes System.err as the output for profiling data. I will have to do a few things to make it possible to direct things elsewhere. It doesn't look too hard, I'm just not familiar enough with the JRuby code.

About JSON, I'll dig a little more. Writing the printer in Ruby isn't a bad idea, it would be lots of code less.

@headius
Owner

Probably won't make 1.7. @enebo is probably already prepared to kill me for merging a bunch of stuff in this week. But 1.7.1 should come a month (or less) later.

I think the simplest way would be to set up a stream in the profile data structures that can be set to any stream. By default, it would be System.err. Then when printing profile data, it just gets the profile stuff from Ruby and gets the stream from that.

FWIW, the JRuby ruby "kernel" is in src/jruby...might give you some pointers.

@iconara

Ok, 1.7.1 is more than good enough for me. Thanks for the pointers.

@iconara

I've opened pull request #326 with new additions, including writing profiles to a file.

@nirvdrum
Collaborator

@iconara If you get a chance, could you please add a wiki page on how to use the profiler? I've figured out how to dump the JSON to file, which was a bit non-obvious, but I haven't gotten much further than that. Directions on how to generate a graph live perftools.rb does would be extremely helpful. Thanks!

@iconara

@nirvdrum sure thing. I've been meaning to for a long time, but it got lost in all other things to do.

@nirvdrum
Collaborator

@iconara I don't mean to bother, but have you made any progress on this?

@iconara

@nirvdrum sorry no, but thanks for bumping this -- I really would like to get something written.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
This page is out of date. Refresh to see the latest.
View
1  lib/ruby/shared/jruby/profiler.rb
@@ -7,6 +7,7 @@ module Profiler
java_import org.jruby.runtime.profile.FlatProfilePrinter
java_import org.jruby.runtime.profile.GraphProfilePrinter
java_import org.jruby.runtime.profile.HtmlProfilePrinter
+ java_import org.jruby.runtime.profile.JsonProfilePrinter
def self.profile(&block)
start
View
79 spec/profiler/json_profile_printer_spec.rb
@@ -0,0 +1,79 @@
+require 'spec/profiler/profiler_spec_helpers'
+
+describe JRuby::Profiler, "::JsonProfilePrinter" do
+ include JRuby::Profiler::SpecHelpers
+
+ context 'when printing an empty profile' do
+ before do
+ @profile_data = JRuby::Profiler.profile {}
+ end
+
+ it 'contains only the top invocation' do
+ json_output['methods'].should have(1).items
+ json_output['methods'].first['name'].should == '(top)'
+ end
+
+ it 'contains the total duration' do
+ json_output['total_time'].should == 0.0
+ end
+
+ it 'outputs the name of the thread' do
+ json_output['thread_name'].should == 'main'
+ end
+ end
+
+ context 'when printing a profile' do
+ before do
+ obj = ProfilerTest.new
+ @profile_data = JRuby::Profiler.profile do
+ obj.wait(0.01)
+ obj.test_instance_method
+ end
+ end
+
+ it 'outputs the total duration' do
+ json_output['total_time'].should > 0.0
+ end
+
+ it 'outputs the name of the thread' do
+ json_output['thread_name'].should == 'main'
+ end
+
+ context 'outputs method data which' do
+ let :method_invocation do
+ json_output['methods'].find { |m| m['name'] == 'ProfilerTest#test_instance_method' }
+ end
+
+ let :top_invocation do
+ json_output['methods'].find { |m| m['name'] == '(top)' }
+ end
+
+ it 'contains the number of calls, total, self and child time' do
+ method_invocation.should include('total_calls' => 1, 'total_time' => anything, 'self_time' => anything, 'child_time' => anything)
+ end
+
+ it 'contains data on the calls from parents, including calls, total, self and child time' do
+ method_invocation['parents'].should have(1).item
+ call_data = method_invocation['parents'].find { |c| c['id'] == top_invocation['id'] }
+ call_data.should include('total_calls' => 1, 'total_time' => anything, 'self_time' => anything, 'child_time' => anything)
+ end
+
+ it 'contains data on the calls to children' do
+ method1_invocation = json_output['methods'].find { |m| m['name'] == 'ProfilerTest#wait' }
+ method2_invocation = json_output['methods'].find { |m| m['name'] == 'ProfilerTest#test_instance_method' }
+ call1_data = top_invocation['children'].find { |c| c['id'] == method1_invocation['id'] }
+ call1_data.should include('total_calls' => 1, 'total_time' => anything, 'self_time' => anything, 'child_time' => anything)
+ call2_data = top_invocation['children'].find { |c| c['id'] == method2_invocation['id'] }
+ call2_data.should include('total_calls' => 1, 'total_time' => anything, 'self_time' => anything, 'child_time' => anything)
+ end
+ end
+ end
+end
+
+
+
+
+
+
+
+
View
7 spec/profiler/profiler_spec_helpers.rb
@@ -1,5 +1,5 @@
-
require 'jruby/profiler'
+require 'json'
module JRuby::Profiler::SpecHelpers
@@ -30,6 +30,11 @@ def graph_output
data_output JRuby::Profiler::GraphProfilePrinter
end
+ def json_output
+ raw_output = data_output(JRuby::Profiler::JsonProfilePrinter)
+ JSON.parse(raw_output)
+ end
+
def flat_output
data_output JRuby::Profiler::FlatProfilePrinter
end
View
2  src/org/jruby/RubyInstanceConfig.java
@@ -1244,7 +1244,7 @@ public LoadService create(Ruby runtime) {
}
public enum ProfilingMode {
- OFF, API, FLAT, GRAPH, HTML
+ OFF, API, FLAT, GRAPH, HTML, JSON
}
public enum CompileMode {
View
173 src/org/jruby/runtime/profile/JsonProfilePrinter.java
@@ -0,0 +1,173 @@
+/***** BEGIN LICENSE BLOCK *****
+ * Version: CPL 1.0/GPL 2.0/LGPL 2.1
+ *
+ * The contents of this file are subject to the Common Public
+ * License Version 1.0 (the "License"); you may not use this file
+ * except in compliance with the License. You may obtain a copy of
+ * the License at http://www.eclipse.org/legal/cpl-v10.html
+ *
+ * Software distributed under the License is distributed on an "AS
+ * IS" basis, WITHOUT WARRANTY OF ANY KIND, either express or
+ * implied. See the License for the specific language governing
+ * rights and limitations under the License.
+ *
+ * Alternatively, the contents of this file may be used under the terms of
+ * either of the GNU General Public License Version 2 or later (the "GPL"),
+ * or the GNU Lesser General Public License Version 2.1 or later (the "LGPL"),
+ * in which case the provisions of the GPL or the LGPL are applicable instead
+ * of those above. If you wish to allow use of your version of this file only
+ * under the terms of either the GPL or the LGPL, and not to allow others to
+ * use your version of this file under the terms of the CPL, indicate your
+ * decision by deleting the provisions above and replace them with the notice
+ * and other provisions required by the GPL or the LGPL. If you do not delete
+ * the provisions above, a recipient may use your version of this file under
+ * the terms of any one of the CPL, the GPL or the LGPL.
+ ***** END LICENSE BLOCK *****/
+package org.jruby.runtime.profile;
+
+
+import java.io.PrintStream;
+import java.util.Iterator;
+import java.util.Locale;
+
+import org.jruby.util.collections.IntHashMap;
+
+
+public class JsonProfilePrinter extends ProfilePrinter {
+ private static Locale JSON_LOCALE = Locale.ROOT;
+
+ public JsonProfilePrinter(ProfileData profileData) {
+ super(profileData);
+ }
+
+ JsonProfilePrinter(ProfileData profileData, Invocation topInvocation) {
+ super(profileData, topInvocation);
+ }
+
+ public void printProfile(PrintStream out) {
+ Invocation topInvocation = getTopInvocation();
+ IntHashMap<MethodData> methods = methodData(topInvocation);
+ String threadName = null;
+
+ if (getProfileData().getThreadContext().getThread() == null) {
+ threadName = Thread.currentThread().getName();
+ } else {
+ threadName = getProfileData().getThreadContext().getThread().getNativeThread().getName();
+ }
+
+ out.println("{");
+ out.printf("\t\"total_time\":%s,\n", nanosToSecondsString(topInvocation.getDuration()));
+ out.printf("\t\"thread_name\":\"%s\",\n", threadName);
+ out.println("\t\"methods\":[");
+
+ Iterator<MethodData> i = methods.values().iterator();
+ while (i.hasNext()) {
+ MethodData method = i.next();
+ out.print("\t\t");
+ out.print(methodToJson(method));
+ if (i.hasNext()) {
+ out.print(",");
+ }
+ out.println();
+ }
+
+ out.print("\t]\n}\n");
+ }
+
+ private String methodToJson(MethodData method) {
+ return toJsonObject(
+ "id", quote(method.serialNumber),
+ "name", quote(methodName(method.serialNumber)),
+ "total_calls", String.valueOf(method.totalCalls()),
+ "total_time", nanosToSecondsString(method.totalTime()),
+ "self_time", nanosToSecondsString(method.selfTime()),
+ "child_time", nanosToSecondsString(method.childTime()),
+ "parents", parentCallsToJson(method),
+ "children", childCallsToJson(method)
+ );
+ }
+
+ private String parentCallsToJson(MethodData method) {
+ if (method.serialNumber == 0) {
+ return toJsonArray(new String[] { });
+ } else {
+ int[] parentSerials = method.parents();
+ String[] parentCalls = new String[parentSerials.length];
+ for (int i = 0; i < parentSerials.length; i++) {
+ parentCalls[i] = callToJson(
+ parentSerials[i],
+ method.invocationsFromParent(parentSerials[i]).totalCalls(),
+ method.rootInvocationsFromParent(parentSerials[i])
+ );
+ }
+ return toJsonArray(parentCalls);
+ }
+ }
+
+ private String childCallsToJson(MethodData method) {
+ int[] childSerials = method.children();
+ String[] childCalls = new String[childSerials.length];
+ for (int i = 0; i < childSerials.length; i++) {
+ childCalls[i] = callToJson(
+ childSerials[i],
+ method.invocationsOfChild(childSerials[i]).totalCalls(),
+ method.rootInvocationsOfChild(childSerials[i])
+ );
+ }
+ return toJsonArray(childCalls);
+ }
+
+ private String callToJson(int serial, int calls, InvocationSet invocations) {
+ return toJsonObject(
+ "id", quote(serial),
+ "total_calls", String.valueOf(calls),
+ "total_time", nanosToSecondsString(invocations.totalTime()),
+ "self_time", nanosToSecondsString(invocations.selfTime()),
+ "child_time", nanosToSecondsString(invocations.childTime())
+ );
+ }
+
+ private String nanosToSecondsString(long nanos) {
+ return String.format(JSON_LOCALE, "%f", nanos/1.0e9);
+ }
+
+ private String quote(String str) {
+ return String.format("\"%s\"", str);
+ }
+
+ private String quote(int num) {
+ return String.format("\"%d\"", num);
+ }
+
+ private String quote(long num) {
+ return String.format("\"%d\"", num);
+ }
+
+ private String toJsonArray(String... values) {
+ StringBuffer buffer = new StringBuffer();
+ buffer.append("[");
+ for (String v : values) {
+ buffer.append(v);
+ if (v != values[values.length - 1]) {
+ buffer.append(",");
+ }
+ }
+ buffer.append("]");
+ return buffer.toString();
+ }
+
+ private String toJsonObject(String... keysAndValues) {
+ StringBuffer buffer = new StringBuffer();
+ buffer.append("{");
+ for (int i = 0; i < keysAndValues.length; i += 2) {
+ buffer.append(quote(keysAndValues[i]));
+ buffer.append(":");
+ buffer.append(keysAndValues[i + 1]);
+ if (i < keysAndValues.length - 3) {
+ buffer.append(",");
+ }
+ }
+ buffer.append("}");
+ return buffer.toString();
+ }
+}
View
3  src/org/jruby/runtime/profile/ProfilePrinter.java
@@ -65,6 +65,9 @@ else if (mode == ProfilingMode.GRAPH) {
else if (mode == ProfilingMode.HTML) {
printer = new HtmlProfilePrinter(profileData, topInvocation);
}
+ else if (mode == ProfilingMode.JSON) {
+ printer = new JsonProfilePrinter(profileData, topInvocation);
+ }
else {
printer = null;
}
View
3  src/org/jruby/util/cli/ArgumentProcessor.java
@@ -411,6 +411,9 @@ private void processArgument() {
} else if (argument.equals("--profile.html")) {
config.setProfilingMode(RubyInstanceConfig.ProfilingMode.HTML);
break FOR;
+ } else if (argument.equals("--profile.json")) {
+ config.setProfilingMode(RubyInstanceConfig.ProfilingMode.JSON);
+ break FOR;
} else if (argument.equals("--1.9")) {
config.setCompatVersion(CompatVersion.RUBY1_9);
break FOR;
Something went wrong with that request. Please try again.