Improve default backtraces
--------------------------
Key: JRUBY-5504
URL: http://jira.codehaus.org/browse/JRUBY-5504
Project: JRuby
Issue Type: Improvement
Reporter: Charles Oliver Nutter
Assignee: Thomas E Enebo
Fix For: JRuby 1.7
I'm interested in improving the default JRuby backtrace. The current backtrace
is identical to MRI's, and newer traces like Rubinius's have shown there are
nicer ways to render the backtrace.
This bug will track ideas on how to improve the backtrace to be more useful and
readable for users.
To start, here's the backtrace as of JRuby 1.6.0.RC2:
{noformat}
~/projects/jruby ➔ jruby -e "1.times { catch(:x) {
File.open('build.xml') {|f| 1 / 0} } }"
org/jruby/RubyFixnum.java:490:in `op_div': divided by 0 (ZeroDivisionError)
from -e:1:in `__file__'
from org/jruby/RubyIO.java:1078:in `open'
from -e:1:in `__file__'
from org/jruby/RubyKernel.java:1191:in `rbCatch'
from -e:1:in `__file__'
from org/jruby/RubyFixnum.java:252:in `times'
from -e:1:in `(root)'
{noformat}
A few items of note:
# The full .java filename plus line number are present for known entry points
from Ruby into Java-based core classes.
# For core classes, the Java method name is used instead of the bound Ruby name
(rbCatch, op_div)
# The interesting bits - the file and line number - are scattered back and
forth over each line, and especially different for core class calls.
Here's the Rubinius trace (and a screenshot to show the color highlighting it
does when outputting to a TTY: http://i.min.us/ijfo16.png):
{noformat}
~/projects/jruby ➔ rbx -e "1.times { catch(:x) { File.open('build.xml')
{|f| 1 / 0} } }"
An exception occurred evaluating command line code
divided by 0 (ZeroDivisionError)
Backtrace:
Object#__script__ {} at -e:1
IO.open at kernel/common/io.rb:260
Object#__script__ {} at -e:1
Kernel(Object)#catch {} at kernel/common/throw_catch.rb:34
Rubinius::ThrownValue.register at kernel/common/throw_catch.rb:13
Kernel(Object)#catch at kernel/common/throw_catch.rb:33
Object#__script__ {} at -e:1
Integer(Fixnum)#times at kernel/common/integer.rb:138
Object#__script__ {} at -e:1
Kernel(Rubinius::Loader)#eval at kernel/common/eval.rb:112
Rubinius::Loader#evals at kernel/loader.rb:420
Rubinius::Loader#main at kernel/loader.rb:525
Rubinius::Loader.main at kernel/loader.rb:552
Object#__script__ at kernel/loader.rb:564
{noformat}
The key details here:
* Top line to indicate an exception occurred and where it happened (unsure what
other values there are besides "command line code"
* Exception message and type on the second line
* Blank line to offset backtrace, followed by "Backtrace:" header
Then the backtrace lines themselves:
* Color highlighted to emphasize user code but show internal code lines (Note
that C++ source lines are *not* shown...only .rb lines)
* Module or class the method came from (with included class for modules in
parens) starts the line
* Script body is shown as "__script__" (similar to JRuby's __file__), with {}
showing if it occurred in a block
* Centered after the class and method name
* file:line comes after centered "at"
The centering is obviously the most noticeable characteristic, though the color
is immediately apparent on terminals that support it. I believe they check
termcap to see if color is possible, which would be difficult for us to do
(would require native calls).
There are a few down sides:
* Very nonstandard...pretty, but everything's in a different place.
* More internal code shown than in a standard trace, which adds a visual noise.
* Color helps, but color sometimes looks bad on certain terminals (like the
really hard-to-read blue on OS X).
* Showing module *and* the class into which it was included is convenient
* (not shown) Method aliases are shown with alias name and original name
The same trace in JRuby, similar but omitting some difficult bits (there's also
color, slightly different configuration, not shown):
{noformat}
~/projects/jruby ➔ jruby -Xbacktrace.style=rubinius -e "1.times {
catch(:x) { File.open('build.xml') {|f| 1 / 0} } }"
An exception has occurred:
divided by 0
Backtrace:
org.jruby.RubyFixnum#op_div at org/jruby/RubyFixnum.java:490
ruby.__dash_e__#__file__ at -e:1
org.jruby.RubyIO#open at org/jruby/RubyIO.java:1078
ruby.__dash_e__#__file__ at -e:1
org.jruby.RubyKernel#rbCatch at org/jruby/RubyKernel.java:1191
ruby.__dash_e__#__file__ at -e:1
org.jruby.RubyFixnum#times at org/jruby/RubyFixnum.java:252
ruby.__dash_e__#(root) at -e:1
{noformat}
Note differences:
* The class in which a method was defined is not always available, since in
compiled code we build the backtrace based on compile-time information (see the
ruby.__dash_e__#__file__ lines, indicating the -e script compiled at command
line). When interpreted, this information is available, but it's very difficult
to show it at compiled code where we no longer track it (for perf reasons).
* Core class .java files are shown, but the output is less cumbersome due to
the centering
* Block-sourced lines are not shown, but could be (the information is available
in both interpreted and compiled native backtraces)
Here are a couple potential improvements that are acceptable for JRuby 1.6
final.
First, with the Ruby names in place of the core class Java names:
{noformat}
~/projects/jruby ➔ jruby -e "1.times { catch(:x) {
File.open('build.xml') {|f| 1 / 0} } }"
org/jruby/RubyFixnum.java:490:in `/': divided by 0 (ZeroDivisionError)
from -e:1:in `__file__'
from org/jruby/RubyIO.java:1078:in `open'
from -e:1:in `__file__'
from org/jruby/RubyKernel.java:1191:in `catch'
from -e:1:in `__file__'
from org/jruby/RubyFixnum.java:252:in `times'
from -e:1:in `(root)'
{noformat}
Since the line numbers are given, the fact that we've lost the real Java method
name isn't a big deal. Note that this also only affects core class methods
written in Java.
A second version, providing both the Ruby name and the Java name in parens
after it:
{noformat}
~/projects/jruby ➔ jruby -e "1.times { catch(:x) {
File.open('build.xml') {|f| 1 / 0} } }"
org/jruby/RubyFixnum.java:490:in `/ (op_div)': divided by 0 (ZeroDivisionError)
from -e:1:in `__file__'
from org/jruby/RubyIO.java:1078:in `open'
from -e:1:in `__file__'
from org/jruby/RubyKernel.java:1191:in `catch (rbCatch)'
from -e:1:in `__file__'
from org/jruby/RubyFixnum.java:252:in `times'
from -e:1:in `(root)'
{noformat}
The down side here is how much longer the core class lines are.
I'm going to do one of the above two modifications for 1.6 final.
Other possible improvements...
Most of the Rubinius improvements are possible, with the exception of showing
the module(class) (because it can't be known at load/compile time) and alias
names (we always show (and only track) real name, not aliased). The color and
centering improvements are possible, though color requires a bit more terminal
introspection than we have available through normal means.
* Remove the Java class entirely and use the Ruby class name for core classes
(this also shows Ruby method names):
{noformat}
~/projects/jruby ➔ jruby -e "1.times { catch(:x) {
File.open('build.xml') {|f| 1 / 0} } }"
Fixnum:490:in `/': divided by 0 (ZeroDivisionError)
from -e:1:in `__file__'
from IO:1078:in `open'
from -e:1:in `__file__'
from Kernel:1191:in `catch'
from -e:1:in `__file__'
from Fixnum:252:in `times'
from -e:1:in `(root)'
{noformat}
Advantages:
* No .java showing up in trace
* Shorter core class backtrace lines
Disadvantages:
* Uninitiated will not know "IO" means RubyIO.java, "Kernel" means
"RubyKernel.java", and so on
* Center the trace with method name followed by file:line:
{noformat}
divided by 0 (ZeroDivisionError)
`/' at org/jruby/RubyFixnum.java:490
`__file__' at -e:1
`open' at org/jruby/RubyIO.java:1078
`__file__' at -e:1
`catch' at org/jruby/RubyKernel.java:1191
`__file__' at -e:1
`times' at org/jruby/RubyFixnum.java:252
`(root)' at -e:1
{noformat}
Advantages:
* Centering
* Method name is first
Disadvantages:
* Line number aligns randomly
A variation: Centered with file:line first and method after (which is more
important to you?)
{noformat}
divided by 0 (ZeroDivisionError)
org/jruby/RubyFixnum.java:490 in `/'
-e:1 in `__file__'
org/jruby/RubyIO.java:1078 in `open'
-e:1 in `__file__'
org/jruby/RubyKernel.java:1191 in `catch'
-e:1 in `__file__'
org/jruby/RubyFixnum.java:252 in `times'
-e:1 in `(root)'
{noformat}
Another variation with centering also applied to the file:line:
{noformat}
divided by 0 (ZeroDivisionError)
org/jruby/RubyFixnum.java:490 in `/'
-e:1 in `__file__'
org/jruby/RubyIO.java:1078 in `open'
-e:1 in `__file__'
org/jruby/RubyKernel.java:1191 in `catch'
-e:1 in `__file__'
org/jruby/RubyFixnum.java:252 in `times'
-e:1 in `(root)'
{noformat}
Advantages:
* Centering x2 (but is it too much?)
* Line number easier to find
Other ideas?
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://jira.codehaus.org/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
To unsubscribe from this list, please visit:
http://xircles.codehaus.org/manage_email
