June 5th 2011 10:58 pm
Java stacktraces straw man
It’s a sad fact of life that many developers spend a good deal of time staring at stack traces.
My personal favorite situation is when you get to:
Exception in thread "main" java.lang.NullPointerException
at com.goeswhere.dmnp.linenos.B.foo(B.java:13)
..and, line 13 is:
System.out.println(first.substring(1) + second.toUpperCase() + third.toLowerCase());
Basically, the end of any happiness.
LineNos can fix this:
$ java -Xbootclasspath/p:linenos.jar -javaagent:linenos.jar=com/goeswhere com.goeswhere.dmnp.linenos.B
Exception in thread "main" java.lang.NullPointerException
at com.goeswhere.dmnp.linenos.B.foo(B.java:13), attempting to invoke toUpperCase #4
at com.goeswhere.dmnp.linenos.B.run(B.java:9)
at com.goeswhere.dmnp.linenos.B.main(B.java:5), attempting to invoke run #2
This is implemented entirely as a Java Agent; it requires no VM modifications and is portable anywhere that supports instrumenters transforming classes (i.e. everywhere that matters).
It works by adding extra line numbers for each call on a line. Currently it adds call-number*1000 to the line number, so that it’s debuggable and easier to do in two phases, but this makes it much less efficient.
i.e., assuming Java allowed labels for line-numbers, it does:
13:
8013: System.out.println(
1013: [secret StringBuilder construction (used to implement String concatenation)]
2013: first.substring(1)
3013: +
4013: second.toUpperCase()
5013: +
6013: third.toLowerCase()
7013: [secret StringBuilder#toString()]);
Thus, the real stacktrace looks like:
Exception in thread "main" java.lang.NullPointerException
at com.goeswhere.dmnp.linenos.B.foo(B.java:4013)
at com.goeswhere.dmnp.linenos.B.run(B.java:9)
...
It additionally overrides StackTraceElement#toString() to decompile the named class and report the invocation that’s on that line, i.e. lookup line 4013 in the above bytecode, and report that it’s an invocation of toUpperCase, thus giving the intended result.
It has no run-time performance penalty beyond the extra time to load classes, and the increase in the size of line-number table (actually, I have no idea how this affects performance, but I can’t imagine it’s much). Printing a stacktrace is slower, however (although, it probably wouldn’t be much slower in a real implementation). Also, it’s a straw-man, so leaks memory, but this isn’t an important part of the implementation.
A much better implementation would be to store the [Class<>, line-number] -> hint mapping instead of the whole file and doing decompilation; or to replace the entire line-number table with a bytecode number table (i.e. 1->1, 2->2, 3->..), and do it all at print-time. Patches welcome.
In summary: Dear Oracle, please make the JVM do this by default. Lots of Love, Faux.
10 Comments »
Martin on 06 Jun 2011 at 11:55 am #
What license are you releasing this code under?
Faux on 06 Jun 2011 at 12:35 pm #
Martin: There’s a LICENSE in the root of the repo and in the root pom; it’s BSD (i.e. do what you want).
Foo on 06 Jun 2011 at 1:03 pm #
It seems to me that stating the method call is insufficient. What if the line has several invocations of that call? You really should also print out *where* on the line the problem occurred.
Pragma on 06 Jun 2011 at 2:05 pm #
For what it’s worth, I’ve seen real source files that exceed 1000 lines; granted, it was all C, but there’s no reason why that can’t happen in Java. With this technique of encoding line number information, calls on lines 1000+ will simply not encode correctly. I humbly recommend the following scheme for encoding your line numbers instead, to avoid issues with large source files:
lineno = (real_line_number * 1000) + call_number_in_this_line;
This way, your example above look like so:
13:
13008: System.out.println(
13001: [secret StringBuilder construction (used to implement String concatenation)]
13002: first.substring(1)
13003: +
13004: second.toUpperCase()
13005: +
13006: third.toLowerCase()
13007: [secret StringBuilder#toString()]);
… which will support 999 function calls per line, in files well in excess of 1000 lines of code.
Faux on 06 Jun 2011 at 2:17 pm #
Foo: The #4 on the end of the stack trace is which call on the line it is; you can work back from this to the actual position in the source (with names), but that’s decompilation; what I’m doing (despite using the term “decompilation”) is actually disassembly, which is much, much easier. (Note how System.out.println() is #8, not #1 as you’d expect, and that the plusses take up function numbers etc.).
Pragma: The line number table is stored as a unsigned short, i.e. a maximum value of 2^16-1 == 65535. I picked to have up to 1000 lines and up to 64 calls on a line (as opposed to your proposed up to 1000 calls/line and 64 lines). There are plenty of better ways to allocate numbers; either linearly as I suggested (and store an additional line-number table); or, set the high-bit and increment for each call, as rz0 suggested on reddit. Personally, I’d go with my method, but I may be biased.
Abinesh on 07 Jun 2011 at 6:36 pm #
How does the library behave when you have a().b().c().d().e()? Not an ideal situation we want to be in, but just curious as to how it responds.
Simon on 07 Jun 2011 at 9:42 pm #
Pragma – if you’ve never seen a Java source file over 1000 lines, you must deal with a much nicer code base than I do. We’ve got dozens of them, some well over 5000, and a few close to 10000. We know they’re bad – they’re a result of pre-IDE bad practices from ten years ago – but we’re stuck with them, gradually improving the situation…
Serzhas on 08 Jun 2011 at 9:57 am #
Hello all.
Sounds like nice library for developers!
However, I’m having troubles starting it along with JRebel. My application just fails to initialize Spring context.
What am I doing wrong? Any suggestions?
Thanks.
P.S. My Tomcat arguments list contains this:
-Xbootclasspath/p:”C:\Dev\apache-tomcat-6.0.29\lib\linenos-1.0.jar” -javaagent:”C:\Dev\apache-tomcat-6.0.29\lib\linenos-1.0.jar”
Serzhas on 08 Jun 2011 at 9:59 am #
Just tried to start it without JRebel with same result:
2011-06-08 12.58.40 org.apache.catalina.core.StandardContext listenerStart
SEVERE: Exception sending context initialized event to listener instance of class org.springframework.web.context.ContextLoaderListener
2011-06-08 12.58.40 org.apache.catalina.core.StandardContext start
SEVERE: Error listenerStart
2011-06-08 12.58.40 org.apache.catalina.core.StandardContext start
SEVERE: Context [/epolice-portlets] startup failed due to previous errors
D. Garcia on 01 Jul 2011 at 8:05 pm #
Another solution to this problem is simply just don’t make many things on the same line (method calls). It reduces the complexity and augments the legibility and reusability.
If the intention is to build a String with a few values like in the example, use a template engine like StringTemplate.
I’ve got cleaner and nicer code since I follow this pattern.