JSON format profile printer #270

Merged
merged 5 commits into from Sep 29, 2012

Projects

None yet

4 participants

@iconara
Contributor
iconara commented Aug 24, 2012

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
Contributor

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 Sep 29, 2012

1 check passed

default The Travis build passed
Details
@headius
Member
headius commented Sep 29, 2012

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

@headius
Member
headius commented Sep 29, 2012

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
Contributor
iconara commented Sep 29, 2012

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
Member
headius commented Sep 29, 2012

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
Contributor
iconara commented Sep 29, 2012

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

@iconara
Contributor
iconara commented Oct 1, 2012

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

@nirvdrum
Contributor
nirvdrum commented Jan 1, 2013

@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
Contributor
iconara commented Jan 1, 2013

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

@nirvdrum
Contributor
nirvdrum commented Feb 6, 2013

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

@iconara
Contributor
iconara commented Feb 6, 2013

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

@eregon eregon added a commit that referenced this pull request Jun 27, 2016
@eregon eregon Squashed 'spec/ruby/' changes from 842119c..9b80404
9b80404 Use the block-style for #fork to clarify which is child/parent
6105e6f Fix process leak in define_finalizer spec
0d16336 Set the thread-local variable on a fresh thread to avoid adding one to the main thread
6d6085b Add some specs for Fiber#resume and Fiber#transfer
d74074c Fix name of Thread#thread_variable? spec
d2646aa Clean up after some Fiber specs.
ea9ba0f A couple Thread, Fiber spec fixes.
3f3bfc9 Specs for Thread#thread_variable{s, _get, _set, _key?}.
7e0030d Added ObjectSpace.define_finalizer specs.
e36507d Improve coverage of Range#== and Range#eql? specs.
2b8f656 [Truffle] Complete implementation of RSTRING_PTR.
692a8c7 Add specs for Encoding.compatible?(String, Encoding).
7da8db1 Add specs for Encoding.compatible?'s special handling of empty strings.
7686226 Simplify scope changes in WeakRef#__send__ spec
2ad4c51 Remove useless GC.start
797a4ca Add a spec for `if $0 ==  __FILE__` with relative paths.
d4fe65c [Truffle] Implement rb_funcall and rb_proc_new.
517fba5 [Truffle] Pass all of Module C-extension specs.
27fdf70 Fix description in rb_define_global_function spec
cc2bbcc Specify what kind of NameError is acceptable for missing class variables
202d106 Merge pull request #270 from odaira/myContribution
9cdea79 Skip specs for getsockopt that are known to fail due to a bug in AIX
8190a7c Close dup'd fd in Readline#readline spec
1eddcf4 Fix spec trying to join a random process group
0e41add Merge pull request #269 from odaira/myContribution
2ded765 Avoid using the "daemon" group because it might not exist
4025994 Merge pull request #268 from rhenium/skip-openssl-random-pesudo_bytes
be27946 Skip OpenSSL::Random.pseudo_bytes if not defined
5c234e5 Revert "Fix of MRI Bug 12367 was backported to 2.3 and 2.2"
16c1d6a Fix of MRI Bug 12367 was backported to 2.3 and 2.2
391bc02 Fix guards for C-API constants
3ab19e5 Merge pull request #267 from nobu/integer-unification
e7d61e0 Remove `rb_cFixnum` and `rb_cBignum`
47d1d0f Merge 2 lines affecting the same variable in Process#setsid
033ee7d Merge pull request #266 from odaira/myContribution
c14030f AIX does not allow Process.getsid(pid) if pid is in a different session
6c15fa6 Merge pull request #265 from iliabylich/mark-unsupported-specs-for-opal-as-unsupported
4375899 Wrapped String#rindex specs containing regexp anchors with `not_supported_on :opal`.
fea9678 Merge pull request #263 from duerst/Unicode-case-mapping
0eef655 Update case mapping related in preparation for Unicode case mapping

git-subtree-dir: spec/ruby
git-subtree-split: 9b80404bef43b67d0f9a82ab3005ffcbc1be49cd
7727828
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment