How to follow the origin of a value in Java?

Question

I have a variable that very rarely gets an incorrect value. Since the system is quite complex I'm having trouble tracing all the code paths that value goes through - there are multiple threads involved, it can be saved and then loaded from a DB and so on. I'm going to try to use a code graph generator to see if I can spot the problem by looking at the ways the setter can be called, by may be there's some other technique. Perhaps wrapping the value with a class that traces the places and changes it goes through? I'm not sure the question is clear enough, but I'd appreciate input from somebody who encountered such a situation.

[Edit] The problem is not easily reproducible and I can't catch it in a debugger. I'm looking for a static analysis or logging technique to help track down the issue.

[Edit 2] Just to make things clearer, the value I'm talking about is a timestamp represented as the number of milliseconds from the Unix epoch (01/01/1970) in a 64-bit long variable. At some unknown point the top 32 bits of the value are truncated generating completely incorrect (and unrecoverable) timestamps.

[Edit 3] OK, thanks to some of your suggestions and to a couple of hours of pouring through the code, I found the culprit. The millisecond-based timestamp was converted into a second-based timestamp by dividing it by 1000 and stored in an int variable. At a later point in code, the second-based timestamp (an int) was multiplied by 1000 and stored into a new long variable. Since both 1000 and the second-based timestamps were int values, the result of the multiplication was truncated before being converted to long. This was a subtle one, thanks to everyone who helped.

Answer 1

I agree - if the value is only changed via a setter (no matter what the orgin) - and it better be - then the best way is to modify the setter to do the tracking for you (print stack trace at every setting, possibly only when the value set is a specific one if that cuts down on the clatter)

Answer 2

1) Supposing that foo is the name of your variable, you could add something like this to the setter method:

try {
  throw new Exception();
}
catch (Exception e) {
  System.out.println("foo == " + foo.toString());
  e.printStackTrace();
}

How well this will work depends on how frequently the setter is being called. If it's being called thousands of times over the run of your program, you might have trouble finding the bad value in all the stack traces. (I've used this before to troubleshoot a problem like yours. It worked for me.)

2) If you can run your app in a debugger and you can identify programatically bad values for your variable, then you could set a breakpoint in the setter conditional on whatever it is that makes the value bad. But this requires that you can write a test for badness, which maybe you can't do.

3) Since you said (in a subsequent edit) that the problem is the high 32 bits being zeroed, you can specifically test for that before printing your stack trace. That should cut down the amount of debugging output enough to be manageable.

Answer 3

Multithreaded programming is jsut hard, but there are IDE tools to help. If you have intellij IDEA, you can use the analyze dataflow feature to work out where things gets changed. If won't show you a live flow (its a static analysis tool), but it can give you a great start.

Alternatively, you can use some Aspects and just print out the value of the variable everywhere, but the resulting debugging info will be too overwhelming to be that meaningful.

The solution is to avoid state shared between threads. Use immutable objects, and program functionally.

Answer 4

In your question, you speak of a "variable" that has an incorrect value, and suggest that you could try "wrapping the value with a class". Perhaps I'm reading too much into your choice of words, but would like to see a bit more about the design.

Is the value in question a primitive? Is it a field of a large, complex object that is shared between threads? If it is a field of some object, is that object a DTO or does it implement domain-specific behavior?

In general, I'd agree with the previous comments re instrumenting the object of which the "variable" is a field, but more information about the nature and usage of this variable would help guide more precise suggestions.

Answer 5

If you are using a setter and only a setter to set your value you can add these lines in order to track the thread and stack trace:

public void setTimestamp(long value) {
  if(log.idDebugEnabled) {
    log.debug("Setting the value to " + value + ". Old value is " + this.timestamp);
    log.debug("Thread is " + Thread.currentThread().getName());
    log.debug("Stacktrace is", new Throwable()); // we could also iterate on Thread.currentThread().getStackTrace()
  }
  // check for bad value
  if(value & 0xffffffff00000000L == 0L) {
    log.warn("Danger Will Robinson", new IlegalValueException());
  }
  this.timestamp = value;
}

Also, go over the class that contains the field, and make sure that every reference to it is done via the setter (even in private/protected methods)

Edit

Perhaps FindBugs can help in terms of static analysis, I'll try to find the exact rule later.

Answer 6

Based on your description, I don't know if that means it's not feasible to actual debug the app in real time, but if it is, depending on your IDE there's a bunch of debugging options available.

I know that with Eclipse, you can set conditional breakpoints in the setter method for example. You can specify to suspend only when the value gets set to a specific value, and you can also filter by thread, in case you want to focus on a specific thread.

Answer 7

I will rather keep a breakpoint inside the setter. Eclipse allows you to do that.

There are some IDE which allows you to halt ( wait for execution of next instruction ) the program, if the value of variable is changed.

Answer 8

The fact that 32 bits of the long get changed, rather than the whole value, suggests strongly that this is a threading problem (two threads update the variable at the same time). Since java does not guarantee atomic access to a long value, if two threads update it at the same time, it could end up with half the bits set one way and half the other. This means that the best way to approach the issue is from a threading point of view. Odds are that there is nothing setting the variable in a way that a static analysis tool will show you is an incorrect value, but rather the syncronization and locking strategy around this variable needs to be examined for potential holes.

As a quick fix, you could wrap that value in an AtomicLong.

Answer 9

Two things:

First, to me, it smells as though some caller is treating their timestamp in an integer context, losing your high 32 bits. It may be, as Yishai surmised, threading-related, but I'd look first at the operations being performed. However, naturally, you need to assure that your value is being updated "atomically" - whether with an AtomicLong, as he suggested, or with some other mechanism.

That speculation aside, given that what you're losing is the high 32 bits, and you know it's milliseconds since the epoch, your setter can enforce validity: if the supplied value is less than the timestamp at program start, it's wrong, so reject it, and of course, print a stack trace.

Answer 10

IMO the best way to debug this type of problem is using a field modification breakpoint. (Especially if you're using reflection extensively)

I'm not sure how to do this in eclipse, but in intellij you can just right click on the field and do an "add breakpoint".