Database insertion is taking zero seconds to insert

Question

I am trying to measure the performance of Database Insert. So for that I have written a StopWatch class which will reset the counter before executeUpdate method and calculate the time after executeUpdate method is done.

And I am trying to see how much time each thread is taking, so I am keeping those numbers in a ConcurrentHashMap.

Below is my main class-

public static void main(String[] args) {

        final int noOfThreads = 4;
        final int noOfTasks = 100;

        final AtomicInteger id = new AtomicInteger(1);

        ExecutorService service = Executors.newFixedThreadPool(noOfThreads);

        for (int i = 0; i < noOfTasks * noOfThreads; i++) {
            service.submit(new Task(id));
        }
        while (!service.isTerminated()) {

        }

           //printing the histogram
          System.out.println(Task.histogram);

    }

Below is the class that implements Runnable in which I am trying to measure each thread performance in inserting to database meaning how much time each thread is taking to insert to database-

class Task implements Runnable {

    private final AtomicInteger id;
    private StopWatch totalExecTimer = new StopWatch(Task.class.getSimpleName() + ".totalExec");
    public static ConcurrentHashMap<Long, AtomicLong> histogram = new ConcurrentHashMap<Long, AtomicLong>();

    public Task(AtomicInteger id) {
        this.id = id;
    }


    @Override
    public void run() {

        dbConnection = getDBConnection();

        preparedStatement = dbConnection.prepareStatement(Constants.INSERT_ORACLE_SQL);

        //other preparedStatement

        totalExecTimer.resetLap();

        preparedStatement.executeUpdate();

        totalExecTimer.accumulateLap();

        final AtomicLong before = histogram.putIfAbsent(totalExecTimer.getCumulativeTime() / 1000, new AtomicLong(1L));
        if (before != null) {
            before.incrementAndGet();
        }
    }
}

Below is the StopWatch class

/**
 * A simple stop watch.
 */
protected static class StopWatch {
    private final String name;
    private long lapStart;
    private long cumulativeTime;

    public StopWatch(String _name) {
        name = _name;
    }

    /**
     * Resets lap start time.
     */
    public void resetLap() {
        lapStart = System.currentTimeMillis();
    }

    /**
     * Accumulates the lap time and return the current lap time.
     * 
     * @return the current lap time.
     */
    public long accumulateLap() {
        long lapTime = System.currentTimeMillis() - lapStart;
        cumulativeTime += lapTime;
        return lapTime;
    }

    /**
     * Gets the current cumulative lap time.
     * 
     * @return
     */
    public long getCumulativeTime() {
        return cumulativeTime;
    }

    public String getName() {
        return name;
    }

    @Override
    public String toString() {
        StringBuilder sb = new StringBuilder();
        sb.append(name);
        sb.append("=");
        sb.append((cumulativeTime / 1000));
        sb.append("s");
        return sb.toString();
    }
}

After running the above program, I can see 400 rows got inserted. And when it is printing the histogram, I am only seeing like this-

{0=400}

which means 400 calls came back in 0 seconds? It's not possible for sure.

I am just trying to see how much time each thread is taking to insert the record and then store those numbers in a Map and print that map from the main thread.

I think the problem I am assuming it's happening because of thread safety here and that is the reason whenever it is doing resetlap zero is getting set to Map I guess.

If yes how can I avoid this problem? And also it is required to pass histogram map from the main thread to constructor of Task? As I need to print that Map after all the threads are finished to see what numbers are there.

Update:- If I remove divide by 1000 thing to store the number as milliseconds then I am able to see some numbers apart from zero. So that looks good.

But One thing more I found out is that numbers are not consistent, If I sum up each threads time, I will get some number for that. And I also I am printing how much time in which whole program is finishing as well. SO I compare these two numbers they are different by big margin

Answer 1

As an additional note, System.currentTimeMillis() is pseudo time and has a level of innacuracy. Using System.nanoTime() is a more accurate approach

long start = System.nanoTime();

long end = System.nanoTime();

long timeInSeconds = TimeUnit.NANOSECONDS.convert(end-start, TimeUnit.SECONDS);

Answer 2

To avoid concurrency issues with your stopwatch you're probably better off creating a new one as a local variable within the run method of your Runnable. That way each thread has it's own stopwatch.

As for the timing you're seeing, I would absolutely hope that a simple record insert would happen in well under a second. Seeing 400 inserts that all happen in less than a second each doesn't surprise me at all. You may get better results by using the millisecond value from your stopwatch as your HashMap key.

Update

For the stopwatch concurrency problem I'm suggesting something like this:

class Task implements Runnable {

    private final AtomicInteger id;
    // Remove the stopwatch from here
    //private StopWatch totalExecTimer = new StopWatch(Task.class.getSimpleName() + ".totalExec");
    public static ConcurrentHashMap<Long, AtomicLong> histogram = new ConcurrentHashMap<Long, AtomicLong>();

    public Task(AtomicInteger id) {
        this.id = id;
    }


    @Override
    public void run() {

        // And add it here
        StopWatch totalExecTimer = new StopWatch(Task.class.getSimpleName() + ".totalExec");

        dbConnection = getDBConnection();

In this way each thread, indeed each Task, gets its own copy, and you don't have to worry about concurrency. Making the StopWatch thread-safe as-is is probably more trouble than it's worth.

Update 2

Having said that then the approach you mentioned in your comment would probably give better results, as there's less overhead in the timing mechanism.

To answer your question about the difference in cumulative thread time and the toal running time of the program I would glibbly say, "What did you expect?".

There are two issues here. One is that you're not measuring the total running time of each thread, just the bit where you're doing the DB insert.

The other is that measuring the running time of the whole application does not take into account any overlap in the execution times of the threads. Even if you were measuring the total time of each task, and assuming you're running on a multi-core machine, I would expect the cumulative time to be more than the elapse time of program execution. That's the benefit of parallel programming.

Answer 3

For a number of reasons, currentTimeMillis is apt to not "refresh" its value on every call. You should use nanoTime for high-resolution measurements.

And your code is throwing away fractions of a second. Your toString method should use sb.append((cumulativeTime / 1000.0)); so that you get fractional seconds.

But the overhead of your timing mechanism is substantial, and if you ever do measure something a big chunk of the time will just be the timing overhead. It's much better to measure a number of operations rather than just one.