Column numbers in stack trace - enhancement request

[Sasi]

I filed the following enhancement request to Sun. Would like to hear
opinion about how useful implementing this feature would be.

Synopsis: Need column numbers in stack traces
Description:
A DESCRIPTION OF THE REQUEST :
Stack traces contain only line numbers and in certain cases line number
alone is not sufficient for figuring out where exactly an exception
occurred. Consider the following line of code.

value = getItem().getRelatedItem().getName().getValue();

If the above line throws a NullPointerException, we have no clue
whether it is the getItem, getRelatedItem or the getName that is
returning a null value. So providing just the line number is not
sufficiently helpful in narrowing down the problem. If the stack trace
also contains the column number where the null was encountered, it will
be really helpful.

Though the above code could be rewritten to several lines so that we
can clearly identify which method returned null, there are tons of such
existing code and changing them all will be an unreasonably complex
task.

 

[Robert Klemme]

I filed the following enhancement request to Sun. Would like to hear
opinion about how useful implementing this feature would be.

Synopsis: Need column numbers in stack traces
Description:
A DESCRIPTION OF THE REQUEST :
Stack traces contain only line numbers and in certain cases line number
alone is not sufficient for figuring out where exactly an exception
occurred. Consider the following line of code.

value = getItem().getRelatedItem().getName().getValue();

If the above line throws a NullPointerException, we have no clue
whether it is the getItem, getRelatedItem or the getName that is
returning a null value. So providing just the line number is not
sufficiently helpful in narrowing down the problem. If the stack trace
also contains the column number where the null was encountered, it will
be really helpful.

Though the above code could be rewritten to several lines so that we
can clearly identify which method returned null, there are tons of such
existing code and changing them all will be an unreasonably complex
task.

You can as well debug your app.

robert

 

[Thomas Kellerer]

value = getItem().getRelatedItem().getName().getValue();

If the above line throws a NullPointerException, we have no clue
whether it is the getItem, getRelatedItem or the getName that is
returning a null value.

That's precisely the reason why I avoid those constructs and store the
intermediate results in a local variable. And it eases debugging as
well, as I can look at each result.

Thomas

 

[Sasi]

When I encounter these kinds of issues during development, I wouldn't
even need a line number to debug the problem. Unfortunately, not all
bugs are so nice. Some decide to show up only in production deployment
and are not reproducible in the dev environment. In those cases, it
will be very helpful to know which exact method faltered so that you
can work the logic backwards and figure out what could have gone wrong.

 

[Chris Uppal]

I filed the following enhancement request to Sun. Would like to hear
opinion about how useful implementing this feature would be.

I don't think it's worthwhile myself. It would require changes (upwardly
compatible, but still changes) to the classfile format. It would require
non-trivial changes to javc to generate the new maps. On the other hand, it
wouldn't give a lot of benefit to most people (who either don't write long
chained sends on one line, or who do use debuggers). I'm not saying that it
would be of no benefit[*], but it seems to me that the costs /of change/
outweigh the benefits.

Note that the costs would not only be born by Sun, but by everyone who writes
compilers or classfile-aware software (which includes me) -- so any time spent
by, say, the Eclipse team keeping up with the (not entirely trivial) changes,
would be time taken from improving Eclipse in other ways.

-- chris

[*] Indeed, it would probably have been better if the debugging information had
always included character offsets. But it didn't :-(

 

[Patricia Shanahan]

I filed the following enhancement request to Sun. Would like to hear
opinion about how useful implementing this feature would be.

Synopsis: Need column numbers in stack traces
Description:
A DESCRIPTION OF THE REQUEST :
Stack traces contain only line numbers and in certain cases line number
alone is not sufficient for figuring out where exactly an exception
occurred. Consider the following line of code.

value = getItem().getRelatedItem().getName().getValue();

The general column number idea would be quite expensive, but there may
be a cheaper solution that would help this particular problem.

How about including in NullPointerException the compile time type of the
subexpression that was null? If getItem() and getRelatedItem() have the
same return type, it would not distinguish between them, but it would
distinguish between the two Item methods, and each of the other two methods.

That said, I tend to avoid chains like that anyway, because I like to
use local variable names as documentation.

Patricia

 

[Chris Uppal]

How about including in NullPointerException the compile time type of the
subexpression that was null?

That's a nice idea, and has the advantage that it requires only limited
modifications (i.e. all within Sun's codebase). Actually NullPointerException
is used rather a lot, and it might be awkward to make /all/ the desirable
changes (e.g. in non-platform code which checks for and throws NPEs), but even
getting a large fraction of the sources to include the desired target class
would help substantially (not only when chained sends are used).

Personally, I think the Sun collection of Throwables suffer from information
underload. Very few of the standard exceptions include sufficient diagnostic
information (e.g. what class was expected and what was found in a
ClassCastException, what index was expected in a ArrayIndexException, and so
on).

Even worse, from my point of view (though I admit it doesn't obviously effect
most people), is that too many runtime exceptions don't contain enough
information to re-start the precise operation. For instance, by the time a
NoSuchMethodError is trapped, the parameters to the method call have been
irretrievably discarded which makes creating worthwhile implementations of
worthwhile languages on a JVM unnecessarily difficult, and also rules out
useful kinds of adaptive software structures.

-- chris

 

[Sasi]

How about including in NullPointerException the compile time type of the
In addition, if the trace contains what method call was attempted on
the null variable, it might help differentiate many of the cases where
the return types of two methods in the same line are identical. JRE
should be able to provide the method name, shouldn't it?

Also, these data will help quite a bit even if the classes were built
without line number information. For those cases, in all but small
methods, it is pretty much impossible to figure out where a
NullPointerException could have occurred.

Of course, none of this is a must if a problem reported by production
users can be reproduced in the dev environment. It will be very easy to
attach the debugger to figure out the bug. But, I get bug reports quite
often that are not reproducible in the dev environment and stack trace
from the logs is all I have to figure out how to reproduce the problem.

I won't be writing any more code with multiple method calls in the same
line. At the same time, I have never seen any warning against this
practice in the Java books I've read or even Sun's Java coding
conventions. Are there any such warnings in some java book or coding
standard?

 

[Lew]

java.util.logging
org.apache.log4j

- Lew

 

[Chris Uppal]

In addition, if the trace contains what method call was attempted on
the null variable, it might help differentiate many of the cases where
the return types of two methods in the same line are identical. JRE
should be able to provide the method name, shouldn't it?

The JMV could certainly record what the failed operation had been (it doesn't
have to be a method call, it could be a field access or an index into an array
for instance). But remember that NPEs can be thrown explicitly too -- that
doesn't mean that the information couldn't be recorded when it was generated by
the JVM, but that wouldn't always be the case.

I won't be writing any more code with multiple method calls in the same
line. At the same time, I have never seen any warning against this
practice in the Java books I've read or even Sun's Java coding
conventions. Are there any such warnings in some java book or coding
standard?

I've never seen a warning against it on those grounds. One partial reason
might be that it's only recently (since 1.5 as I recall) that Sun's compilers
have routinely included line number information in .class files at all (it has
always been available as an option, but was not the default) and without that
you don't get line number information in stack traces.

-- chris

 

[Sasi]

I've never seen a warning against it on those grounds. One partial reason

might be that it's only recently (since 1.5 as I recall) that Sun's compilers
have routinely included line number information in .class files at all (it has
always been available as an option, but was not the default) and without that
you don't get line number information in stack traces.

I didn't know that Sun had made including line numbers as default in
1.5. I am assuming that Sun made this change because they have figured
out that the performance penalty incurred by including the line numbers
in the .class files is negligible in most cases due to JIT. Is that
correct?

 

[Sasi]

How about including in NullPointerException the compile time type of the

java.util.logging
org.apache.log4j

Lew,

Could you explain how java.util.logging or Log4J can help here? I went
through their docs a little bit, but I couldn't find a way to figure
out how they can help in the problem we are discussing.

Sasi

 

[Lew]

java.util.logging

Lew,

Could you explain how java.util.logging or Log4J can help here? I went
through their docs a little bit, but I couldn't find a way to figure
out how they can help in the problem we are discussing.

Sure! You raised several needs, such as

if the trace contains what method call was attempted on
the null variable, it might help differentiate many of the cases where
the return types of two methods in the same line are identical. JRE
should be able to provide the method name, shouldn't it?

The logging packages give the programmer explicit control over this behavior
and others that you described. You need to write an exception handler anyway,
so you including a call to
logger.error( stringContainingAllSortsOfInformation );
in it.

In the log message you can include any useful information available, which at
the point of capture can be pretty darn fine grained.

catch ( NullPointerException exc )
{
String msg = "Variable foo was null in method( foo ). "
+ exc.getMessage();
logger.error( msg );
return FAILURE;
}

The logging mechanism itself will timestamp the entries, provide class and
thread context, and do other useful stuff under the hood.

Including have negligible impact on performance when the logging level is set
high enough.

This does mean writing a whole mess o' catch blocks and if blocks with message
string construction and log calls, but you know what? You have to do that
anyway to achieve "algebraic closure" (metaphorically) of program behavior.

Aspect-oriented programming (AOP) promises at least some relief from the
drudgery involved.

- Lew

 

[Chris Uppal]

I didn't know that Sun had made including line numbers as default in
1.5. I am assuming that Sun made this change because they have figured
out that the performance penalty incurred by including the line numbers
in the .class files is negligible in most cases due to JIT. Is that
correct?

I imagine so (I don't work for Sun so I can't know for sure). The only
significant overhead is that it makes the classfiles a little larger, but it
allows better error reporting in stack traces, which (IMO) is a good bargain.

-- chris