0

Here is what I do: I have an entity class Item. Inside a loop, I want to update 10k items in the table. (In the loop, I set some fields in each item instance before updating it in the database.) First I find out time taken by the complete loop by setting timer at the start and ending the timer just after the loop. Then I find out time taken by execution of the entire block of statements in the loop in each iteration and sum up all such times. This is how my code looks:

public void method() {

EntityManager em = getEntityManager();
em.getTransaction().begin();

List<Item> itemsList = getItemsList();


int size = itemsList.size();                        //size = 10000 
ItemDAO itemDAO = new ItemDAO();                    //repository class instance for db operations

long totalTimeInsideLoop = 0;

Timer t1 = new Timer();                             //start timer for whole loop
for(int i=0; i<size; i++) {
    
    Timer t2 = new Timer();                         //start timer t2 for block statements
    
    Item item = itemsList.get(i);
    
    //set some fields in item to be updated
    item.setDescription("new desc");
    item.setType("new type").
    //...and set some more such basic fields
    
    itemDAO.update(item);
    
    //batching 500 updates
    if(i % 500 == 0) {
        em.flush();
        em.clear();
    }
    
    t2.end();                                           //end timer t2
    totalTimeInsideLoop += t2.getElapsedTimeInMillis();

}
t1.end();                                               //end timer t1

System.out.println("Time taken by complete loop in ms: " + t1.getElapsedTimeInMillis());
System.out.println("Time taken by the block in loop in ms: " + totalTimeInsideLoop);

em.flush();
em.getTransaction().commit();

}

Output:

Time taken by complete loop in ms: 12457
Time taken by the block in loop in ms: 6169

Why is it so? Does processing part of 'for' loop takes so much time? I also used for each loop, for each loop with map of items but in each case found that total time of the loop is 5-6 seconds more than time of execution of the statements inside the loop.

Note: When I removed batching (flush and clear statements), the output is like this:

Time taken by complete loop in ms: 36649
Time taken by the block in loop in ms: 31238

Again it takes 5 seconds more for the whole loop.

This is how my timer class looks like:

public class Timer {
    private long startTime;
    private long endTime;
    
    public Timer () {
        this.startTime = System.currentTimeMillis();
    }
    
    public void end() {
        this.endTime  = System.currentTimeMillis();
    }
    public long getElapsedTimeInMillis() {
        return (endTime - startTime);
    }
}
Reyaz
  • 1
  • 1
  • Please keep all these things here in mind: https://stackoverflow.com/questions/504103/how-do-i-write-a-correct-micro-benchmark-in-java – GhostCat Mar 10 '22 at 10:01
  • And for completeness: where is that `Timer` class coming from? When you run your code and completely to create call that 2nd timer in your inner loop, what happens? – GhostCat Mar 10 '22 at 10:02
  • I cannot believe the `for` loop itself takes so long - maybe you can test an almost empty loop (no 2nd Timer inside, but just incrementing a dummy variable - if the loop is empty, the JIT compiler may *remove* it) || I suspect the `Timer` class... or eventually GC invoked (freeing memory for a new `Timer`?) – user16320675 Mar 10 '22 at 10:18
  • Thanks @user16320675 yes this was the issue. With local variables instead of Timer instance, it works fine – Reyaz Mar 10 '22 at 13:24

1 Answers1

0

The root cause was due to GC being invoked to free memory for a new Timer instance, as mentioned by @user16320675.
When I used local variables to calculate the time inside the loop instead of the Timer instance, I did not find much difference between the two execution times.

Reyaz
  • 1
  • 1