Trying to measure how much time an insert takes in a database

Question

I have a Multithreaded program which will insert into one of my table and that program I am running like this-

java -jar CannedTest.jar 100 10000

which means:

• Number of threads is 100
• Number of tasks is 10000

So each thread will insert 10000 records in my table. So that means total count (100 * 10000) in the table should be 1,000,000 after program is finished executing.

I am trying to measure how much time an insert is taking into my table as a part of our LnP testing. I am storing all these numbers in a ConcurrentHashMap like how much time an insert into database is taking like below.

long start = System.nanoTime();

callableStatement[pos].executeUpdate(); // flush the records.

long end = System.nanoTime() - start;

final AtomicLong before = insertHistogram.putIfAbsent(end / 1000000L, new AtomicLong(1L));
if (before != null) {
    before.incrementAndGet();
}

When all the threads are finished executing all the tasks, then I try to print out the numbers from the ConcurrentHashMap insertHistogram by sorting it on Key which is Milliseconds and I get the result like below-

Milliseconds           Number
0                      2335
1                      62488
2                      60286
3                      54967
4                      52374
5                      93034
6                      123083
7                      179355
8                      118686
9                      87126
10                     42305
..                      ..
..                      ..
..                      ..

And also, from the same ConcurrentHashMap insertHistogram I tried to make a Histogram like below.

17:46:06,112  INFO LoadTest:195 - Insert Histogram List:
17:46:06,112  INFO LoadTest:212 - 64823 came back between 1 and 2 ms
17:46:06,112  INFO LoadTest:212 - 115253 came back between 3 and 4 ms
17:46:06,112  INFO LoadTest:212 - 447846 came back between 5 and 8 ms
17:46:06,112  INFO LoadTest:212 - 330533 came back between 9 and 16 ms
17:46:06,112  INFO LoadTest:212 - 29188 came back between 17 and 32 ms
17:46:06,112  INFO LoadTest:212 - 6548 came back between 33 and 64 ms
17:46:06,112  INFO LoadTest:212 - 3821 came back between 65 and 128 ms
17:46:06,113  INFO LoadTest:212 - 1988 came back greater than 128 ms

NOTE:- The database in which I am trying to insert records, it's in Memory Only mode currently.

Problem Statement:-

Take a look at this number in my above result which prints out by sorting it on the key-

0 2335

I am not sure how it is possible that 2335 calls was inserted in 0 milliseconds? And also I am using System.nanotime while measuring the insert.

Below is the code which will print out the above logs-

private static void logHistogramInfo() {

    int[] definition = { 0, 2, 4, 8, 16, 32, 64, 128 };
    long[] buckets = new long[definition.length];

    System.out.println("Milliseconds           Number");
    SortedSet<Long> keys = new TreeSet<Long>(Task.insertHistogram.keySet());
    for (long key : keys) { 
       AtomicLong value = Task.insertHistogram.get(key);
       System.out.println(key+ "                      " + value);
    }

    LOG.info("Insert Histogram List: ");
    for (Long time : Task.insertHistogram.keySet()) {
        for (int i = definition.length - 1; i >= 0; i--) {
            if (time >= definition[i]) {
                buckets[i] += Task.insertHistogram.get(time).get();
                break;
            }
        }
    }
    for (int i = 0; i < definition.length; i++) {
        String period = "";
        if (i == definition.length - 1) {
            period = "greater than " + definition[i] + " ms";
        } else {
            period = "between " + (definition[i] + 1) + " and " + definition[i + 1] + " ms";
        }
        LOG.info(buckets[i] + " came back " + period);
    }

}

I am not sure why 0 milliseconds is getting shown when I try to print the values from the Map directly by sorting it on the key.

But the same 0 milliseconds doesn't get shown when I try to make the histogram in the same logHistogramInfo method.

Is there anything wrong I am doing in my calculation process in my above method?