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

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 2

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 3

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 4

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.