1

I am running some JUnit tests on a single thread and they are failing in a non-deterministic way. I had one person tell me that the optimizing JVM (Oracle Hotspot 64-Bit 17.1-b03) is executing the instructions out of order for speed. I have trouble believing that the java spec would allow that, but I can't find the specific reference.

Wikipedia states that a single thread must enforce within-thread as-if-serial so I shouldn't have to worry about execution order differing from what I wrote. http://en.wikipedia.org/wiki/Java_Memory_Model#The_memory_model

Example code:

@Test
public void testPersistence() throws Exception
{
    // Setup
    final long preTestTimeStamp = System.currentTimeMillis();

    // Test
    persistenceMethod();

    // Validate
    final long postTestTimeStamp = System.currentTimeMillis();
    final long updateTimeStamp = -- load the timestamp from the database -- ;
    assertTrue("Updated time should be after the pretest time", updateTimeStamp >= preTestTimeStamp);
    assertTrue("Updated time should be before the posttest time", updateTimeStamp <= postTestTimeStamp);
}

void persistenceMethod()
{
    ...
    final long updateTime = System.currentTimeMillis();
    ...
    -- persist updateTime to the database --
    ...
}

When this test code is run it has completely non-deterministic behavior, sometimes it passes, sometimes if fails on the first assert, and sometimes it fails on the second assert. The values are always within a millisecond or two of each other so it isn't that the persistence is just failing completely. Adding a Thread.sleep(2); between each statement does decrease the number of times the test fails, but doesn't eliminate the failures completely.

Is it possible that this is the fault of the JVM or is it more likely that the database (MsSql) is doing some sort of rounding of the stored data?

Adam R.
  • 71
  • 7
  • Have you tried comparing the updateTimeStamp read from the database with the updateTime you store in the database in persistenceMethod? Also, what's the data type of the timestamp column in the database and how do you store it? – JB Nizet Jul 11 '11 at 20:42
  • a single (same) thread will always see the operation as if they were serial. You problem is the precision of the database stamp and `System.currenTimeMillis()` you are looking in totally wrong direction. – bestsss Jul 11 '11 at 21:11
  • The data type in the database is the M$ Sql DATATIME implementation. I do not know how to get the raw value back in the Sql Server Management Studio. – Adam R. Jul 11 '11 at 22:04

3 Answers3

1

The possibility that the JVM is executing statements out of order is so remote that I think you can pretty much dismiss it. If the JVM had a bug like that, it would be showing up in a lot of places besides this one program of yours.

It is true that currentTimeMillis is not guaranteed to actually be accurate to the millisecond. But the possibility that the clock would run backwards is almost as remote as the possibility that the JVM is executing statements out of order.

I've written many, many programs that test how long it takes a function I'm interested in to execute by taking the currentTimeMillis before it starts, executing the function, getting currentTimeMillis when it's done, and subtracting to find an elapsed time. I have never had such a program give me a negative time.

Some possibilities that occur to me:

  1. There's an error in your code to save the timestamp to the database or to read it back. You don't show that code, so we have no way to know if there's a bug there.

  2. Rounding. I don't have a MySQL instance handy, so I'm not sure what the precision of a timestamp is. If it's not as precise as a millisecond, then this would readily explain your problem. For example, say it's only accurate to the second. You get pre time=01:00:00.1, update time=01:00:00.2, post time=01:00:00.4. But update time gets saved as 01:00:00 because that's the limit of precision, so when you read it back update time < re time. Likewise suppose the times are 01:00:00.4, 01:00:00.6, 01:00:00.7. Update time gets rounded to 01:00:01. So update time > post time.

  3. Time zones. Default time zone is an attribute of a connection. If when you write the time you are set to, say, Eastern Time, but when you read it back you are on Pacific Time, then the order of the times will not be what you expected.

Instead of just looking at the relationships, why don't you print the values of all three timestamps? I'd print them as int's and also as Gregorian dates. Oh, and I'd print update time before saving and again after reading it back. Maybe something would become apparent.

If, for example, you see that the update time as read back always end with one or more zeros even when the time as saved had non-zero digits, that would indicate that your times are being truncated or rounded. If the time has read back differs from the time as written by an exact multiple of 1 hour, that might be a time zone problem. If post time is less than pre time, that either indicates a serious problem with your system clock or, more likely, a program bug that's mixing up the times. Etc.

Jay
  • 26,876
  • 10
  • 61
  • 112
  • I did print the value of all three timestamps (after retrieval from persistence) and output them as longs, and they were within milliseconds of each other. If I output the timestamp in the persistence method it slows down the test enough that the failures stop occurring. As the persisted data is only a millisecond off (and sometimes passes) from the other timestamps the precision of the database isn't the issue unless there is some rounding on the last digit. – Adam R. Jul 11 '11 at 22:28
  • 2
    Looks like rounding, case 2. The SQL Server DATETIME type (per OP's comment) is coarser than 1 millisecond, according to the "accuracy" section here. http://msdn.microsoft.com/en-us/library/ms187819.aspx. If the times coming back from the db always end in 0, 3, or 7, that confirms this is your culprit. The doco says use DATETIME2 instead. – Andrew Janke Jul 12 '11 at 06:59
  • The Microsoft rounding is exactly the problem! Thank you very much for finding that for me. – Adam R. Jul 12 '11 at 13:27
0

Should be easy enough to determine whether mySql (0r your persistence code) is doing something. Have your persistenceMethod() return the value it persisted and compare with what you read. They surely should match.

I wonder whether it's the trustworthiness of currentTimeMillis() that's in question:

Returns the current time in milliseconds. Note that while the unit of time of the return value is a millisecond, the granularity of the value depends on the underlying operating system and may be larger. For example, many operating systems measure time in units of tens of milliseconds.

Given that you are doing a >= test, I can't quite see how that might manifest, but it makes me wonder exactly what times you are getting.

djna
  • 54,992
  • 14
  • 74
  • 117
  • I'd really. really, really hope that any timing method a modern OS provides would ensure that the time is non-decreasing (except for overflows obviously). NTP handles this by slowing down the time to synchronize. – Voo Jul 11 '11 at 21:29
  • Yes, I'd be pretty amazed if it does decrease, but we're in a bit of a Sherlock here, we keep eliminating the impossible, and whatever is left, no matter how unlikely ... – djna Jul 12 '11 at 07:27
0

That is really strange. Java will certainly not rearrange statements and execute them in a different order if those statements might have side effects which affect subsequent statements.

I think this error happens because System.currentTimeMillis is not as precise as you think. The API documentation of that method says:

Returns the current time in milliseconds. Note that while the unit of time of the return value is a millisecond, the granularity of the value depends on the underlying operating system and may be larger. For example, many operating systems measure time in units of tens of milliseconds.

It sounds strange, but time might even seem to be going backwards in some cases, so the value that currentTimeMillis returns at one moment can be lower than what it returned an instant earlier. See this question: Will System.currentTimeMillis always return a value >= previous calls?

Community
  • 1
  • 1
Jesper
  • 202,709
  • 46
  • 318
  • 350