How to enable batch inserts with Hibernate and Spring Boot

Question

I want to insert a large number of entities into cross table. To do that, I want to enable hibernate's batch insert option, so that each insert will add not 1, but 20 or 50 rows at a time.

I'm trying to reproduce the results from hibernate's tutorial. I've created a test function that will try to insert 30 customers, just like in example:

//Batch inserting test entities //This code is inside transaction already, so I'm not creating a new one entityManager.flush(); for (int i = 0; i < 30; ++i) {     Customer customer = new Customer("Customer" + i, (i + 5) * 1000, "Position " + i);     entityManager.persist(customer);     if (i % 20 == 0) {         entityManager.flush();         entityManager.clear();     } } entityManager.flush(); entityManager.clear(); 

The Customer class has no generated id.

@Entity public class Customer {      @Id     private String id;     @Column     private String name;     @Column     private long salary;     @Column     private String position;      public Customer() {      }      public Customer(String name, long salary, String position) {         this.id = UUID.randomUUID().toString();         this.name = name;         this.salary = salary;         this.position = position;     }  } 

What I'm expecting to see is 2 insert statements, one for 20 records and one for 10 records. However, when I open postgres logs, I see 30 insert statements, each inserting only 1 row. I've double checked that it's possible to insert multiple rows using postgres.

I believe that the problem is caused by the hibernate.jdbc.batch_size 20 parameter, which I'm supposed to pass to hibernate. However, since I'm using spring boot, the only configuration file I have is application.properties. So I've tried inserting it there:

hibernate.jdbc.batch_size=20 hibernate.order_inserts=true hibernate.order_updates=true hibernate.jdbc.batch_versioned_data=true spring.jpa.hibernate.jdbc.batch_size=20 spring.jpa.hibernate.order_inserts=true spring.jpa.hibernate.order_updates=true spring.jpa.hibernate.jdbc.batch_versioned_data=true spring.jpa.properties.hibernate.jdbc.batch_size=20 spring.jpa.properties.hibernate.order_inserts=true spring.jpa.properties.hibernate.order_updates=true spring.jpa.properties.hibernate.jdbc.batch_versioned_data=true 

According to this answer, this should be enough, but I've also tried copying these parameters to the hibernate.properties file inside my jar and supplied the parameter via command line: -Dhibernate.jdbc.batch_size=20 as stated in this documentation.

None of this helps.
I also can't find a way to read batch size property in my code. It seems that most objects mentioned in hibernate's documentation doesn't exist in spring boot application.
How can I enable hibernate's batch insert inside spring boot application?

I've created a minimal working example which reproduces the issue: https://github.com/Alexey-/spring-boot-batch

---

After receiving the answer from Vlad Mihalcea I realized that yes, in fact batch statements are working, at least on hibernate and jdbc levels.

However, postgres logs themselves show very interesting behavior: they are almost identical for the case of batch inserts and normal inserts.

What I was initially expecting to see was that hibernate would be using statements like this:

test=# INSERT INTO customer (name, position, salary, id) values ('CustomerX', 'PositionX', '1000', 'idX'), ('CUSTOMERY', 'POSITIONY', '1000', 'idY'); 

Which would produce log records similar to this:

2015-12-15 11:43:33.238 MSK LOG:  statement: INSERT INTO customer (name, position, salary, id) values ('CustomerX', 'PositionX', '1000', 'idX'), ('CUSTOMERY', 'POSITIONY', '1000', 'idY'); 

However, that's not the case.
When batch insertion is enabled (p6spy shows that statements are, in fact, batched), postgres will produce logs similar to this:

2015-12-15 12:07:00.638 MSK LOG:  execute <unnamed>: BEGIN 2015-12-15 12:07:00.638 MSK LOG:  duration: 0.000 ms 2015-12-15 12:07:00.638 MSK LOG:  duration: 0.000 ms  parse <unnamed>: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:07:00.638 MSK LOG:  duration: 0.000 ms  bind <unnamed>: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:07:00.638 MSK DETAIL:  parameters: $1 = 'Customer0', $2 = 'Position 0', $3 = '0', $4 = '9c6a86fb-c991-4e98-aa65-fa736ef67dd7' 2015-12-15 12:07:00.638 MSK LOG:  execute <unnamed>: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:07:00.638 MSK DETAIL:  parameters: $1 = 'Customer0', $2 = 'Position 0', $3 = '0', $4 = '9c6a86fb-c991-4e98-aa65-fa736ef67dd7' 2015-12-15 12:07:00.639 MSK LOG:  duration: 1.000 ms 2015-12-15 12:07:00.648 MSK LOG:  duration: 0.000 ms  parse S_1: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:07:00.648 MSK LOG:  duration: 0.000 ms  bind S_1: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:07:00.648 MSK DETAIL:  parameters: $1 = 'Customer1', $2 = 'Position 1', $3 = '10', $4 = 'c8b2669c-044a-4a4d-acbd-31c3bcd9a783' 2015-12-15 12:07:00.648 MSK LOG:  execute S_1: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:07:00.648 MSK DETAIL:  parameters: $1 = 'Customer1', $2 = 'Position 1', $3 = '10', $4 = 'c8b2669c-044a-4a4d-acbd-31c3bcd9a783' 2015-12-15 12:07:00.648 MSK LOG:  duration: 0.000 ms 2015-12-15 12:07:00.648 MSK LOG:  duration: 0.000 ms  bind S_1: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:07:00.648 MSK DETAIL:  parameters: $1 = 'Customer2', $2 = 'Position 2', $3 = '20', $4 = '1c694f41-2ce7-4ee2-a0c0-f359690506f0' 2015-12-15 12:07:00.649 MSK LOG:  execute S_1: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:07:00.649 MSK DETAIL:  parameters: $1 = 'Customer2', $2 = 'Position 2', $3 = '20', $4 = '1c694f41-2ce7-4ee2-a0c0-f359690506f0' 2015-12-15 12:07:00.649 MSK LOG:  duration: 0.000 ms 2015-12-15 12:07:00.649 MSK LOG:  duration: 0.000 ms  bind S_1: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:07:00.649 MSK DETAIL:  parameters: $1 = 'Customer3', $2 = 'Position 3', $3 = '30', $4 = '1815947d-2604-48d4-a6be-43f6905130cf' 2015-12-15 12:07:00.649 MSK LOG:  execute S_1: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:07:00.649 MSK DETAIL:  parameters: $1 = 'Customer3', $2 = 'Position 3', $3 = '30', $4 = '1815947d-2604-48d4-a6be-43f6905130cf' 2015-12-15 12:07:00.649 MSK LOG:  duration: 0.000 ms 2015-12-15 12:07:00.649 MSK LOG:  duration: 0.000 ms  bind S_1: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:07:00.649 MSK DETAIL:  parameters: $1 = 'Customer4', $2 = 'Position 4', $3 = '40', $4 = 'cc521007-820f-4d58-8e1a-16a166aa91cf' 2015-12-15 12:07:00.649 MSK LOG:  execute S_1: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:07:00.649 MSK DETAIL:  parameters: $1 = 'Customer4', $2 = 'Position 4', $3 = '40', $4 = 'cc521007-820f-4d58-8e1a-16a166aa91cf' 2015-12-15 12:07:00.649 MSK LOG:  duration: 0.000 ms ... the rest of the logs is identical and do not provide any valuable information... 

And when batch statements are disabled (p6spy shows that no batching is performed), logs will looks like this:

2015-12-15 12:09:00.246 MSK LOG:  execute <unnamed>: BEGIN 2015-12-15 12:09:00.246 MSK LOG:  duration: 0.000 ms 2015-12-15 12:09:00.246 MSK LOG:  duration: 0.000 ms  parse <unnamed>: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:09:00.246 MSK LOG:  duration: 0.000 ms  bind <unnamed>: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:09:00.246 MSK DETAIL:  parameters: $1 = 'Customer0', $2 = 'Position 0', $3 = '0', $4 = '9e085ad0-437f-4d7d-afaa-e342e031cbee' 2015-12-15 12:09:00.246 MSK LOG:  execute <unnamed>: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:09:00.246 MSK DETAIL:  parameters: $1 = 'Customer0', $2 = 'Position 0', $3 = '0', $4 = '9e085ad0-437f-4d7d-afaa-e342e031cbee' 2015-12-15 12:09:00.246 MSK LOG:  duration: 0.000 ms 2015-12-15 12:09:00.248 MSK LOG:  duration: 0.000 ms  parse <unnamed>: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:09:00.248 MSK LOG:  duration: 0.000 ms  bind <unnamed>: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:09:00.248 MSK DETAIL:  parameters: $1 = 'Customer1', $2 = 'Position 1', $3 = '10', $4 = 'f29cfa40-7d24-49a6-ae5d-2a2021932d80' 2015-12-15 12:09:00.248 MSK LOG:  execute <unnamed>: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:09:00.248 MSK DETAIL:  parameters: $1 = 'Customer1', $2 = 'Position 1', $3 = '10', $4 = 'f29cfa40-7d24-49a6-ae5d-2a2021932d80' 2015-12-15 12:09:00.249 MSK LOG:  duration: 1.000 ms 2015-12-15 12:09:00.250 MSK LOG:  duration: 0.000 ms  parse <unnamed>: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:09:00.250 MSK LOG:  duration: 0.000 ms  bind <unnamed>: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:09:00.250 MSK DETAIL:  parameters: $1 = 'Customer2', $2 = 'Position 2', $3 = '20', $4 = '067dd6d4-5060-467f-b533-75994ecbaedc' 2015-12-15 12:09:00.250 MSK LOG:  execute <unnamed>: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:09:00.250 MSK DETAIL:  parameters: $1 = 'Customer2', $2 = 'Position 2', $3 = '20', $4 = '067dd6d4-5060-467f-b533-75994ecbaedc' 2015-12-15 12:09:00.250 MSK LOG:  duration: 0.000 ms 2015-12-15 12:09:00.250 MSK LOG:  duration: 0.000 ms  parse <unnamed>: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:09:00.250 MSK LOG:  duration: 0.000 ms  bind <unnamed>: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:09:00.251 MSK DETAIL:  parameters: $1 = 'Customer3', $2 = 'Position 3', $3 = '30', $4 = '7df32327-f2f5-4011-848d-55aafb3f09fa' 2015-12-15 12:09:00.251 MSK LOG:  execute <unnamed>: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:09:00.251 MSK DETAIL:  parameters: $1 = 'Customer3', $2 = 'Position 3', $3 = '30', $4 = '7df32327-f2f5-4011-848d-55aafb3f09fa' 2015-12-15 12:09:00.251 MSK LOG:  duration: 0.000 ms 2015-12-15 12:09:00.251 MSK LOG:  duration: 0.000 ms  parse S_1: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:09:00.251 MSK LOG:  duration: 0.000 ms  bind S_1: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:09:00.251 MSK DETAIL:  parameters: $1 = 'Customer4', $2 = 'Position 4', $3 = '40', $4 = '1e55ab6a-8780-4c8f-8af2-2886d954f819' 2015-12-15 12:09:00.251 MSK LOG:  execute S_1: insert into customer (name, position, salary, id) values ($1, $2, $3, $4) 2015-12-15 12:09:00.251 MSK DETAIL:  parameters: $1 = 'Customer4', $2 = 'Position 4', $3 = '40', $4 = '1e55ab6a-8780-4c8f-8af2-2886d954f819' 2015-12-15 12:09:00.251 MSK LOG:  duration: 0.000 ms ... the rest of the logs is identical and do not provide any valuable information... 

So, the only difference between the two is when batch is disabled, postgres will take tiny bit more time to realize that it should reuse prepared statements.

So I decided to run performance tests to confirm this.
I tried inserting 30.000 records into empty database.
With batching disabled, it took 334ms.
With batching enabled, it took 4650ms!

So then I removed all calls to entityManager.flush (leaving only entityManager.clear) and the time dropped to 320ms. I don't know why hibernate's tutorial advises using flush. I guess that's just a mistake.

So I guess the bottom line is this: the batching is working, but it doesn't provide any real benefits (at least for postgres). Furthermore, using it improperly (as in tutorial) can lead to a terrible, terrible results. Use at your own risk and always measure real performance increase.

Answer 1

There is nothing wrong with your code and it's working properly.

I debugged it and then I installed p6spy and it's working. This is how you can test it too:

1. In build.gradle add this dependency:

   compile 'p6spy:p6spy:2.1.4' 

2. Modify the connection properties like this:

   database.driver=com.p6spy.engine.spy.P6SpyDriver database.url=jdbc:p6spy:postgresql://localhost:5432/ 

3. Add spy.properties in the resources folder. You can download it from here.

And then you will see the batched statements:

2015-12-14 19:38:03.655  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114683655|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer0', 'Position 0', 5000, '9f92ac01-8156-41f1-9bdb-36ff622a99cc') 2015-12-14 19:38:03.658  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114683658|2|statement|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer0', 'Position 0', 5000, '9f92ac01-8156-41f1-9bdb-36ff622a99cc') 2015-12-14 19:38:04.212  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684212|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer1', 'Position 1', 6000, 'e3a1dc5a-2183-4fb0-aa9a-4fb8cace23a3') 2015-12-14 19:38:04.213  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684213|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer2', 'Position 2', 7000, '8824f5be-afe5-4a6a-ab8a-8f266db5973f') 2015-12-14 19:38:04.213  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684213|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer3', 'Position 3', 8000, '249304b3-19c5-4376-b5dc-2da685c1db64') 2015-12-14 19:38:04.213  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684213|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer4', 'Position 4', 9000, '2bf15945-94c3-45f8-b0d1-e2fedbdcbaca') 2015-12-14 19:38:04.214  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684214|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer5', 'Position 5', 10000, '85b2b999-5d84-4181-9c71-1a83b4d20b86') 2015-12-14 19:38:04.214  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684214|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer6', 'Position 6', 11000, '8ed6289e-3d04-4ba5-9285-9bce202c8dae') 2015-12-14 19:38:04.215  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684215|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer7', 'Position 7', 12000, '2fc489a8-c6c4-4984-808d-2da9a2e8ad4a') 2015-12-14 19:38:04.215  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684215|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer8', 'Position 8', 13000, '897cd341-b65b-4521-87e6-f4fb78b09bfd') 2015-12-14 19:38:04.215  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684215|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer9', 'Position 9', 14000, 'fa59d5a7-2570-43f9-ba46-595b8fcefa35') 2015-12-14 19:38:04.216  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684216|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer10', 'Position 10', 15000, '0b5b38d1-d644-4ea0-a3f0-9aa025463b8a') 2015-12-14 19:38:04.216  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684216|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer11', 'Position 11', 16000, 'afbb349f-cf28-4cfb-b5b8-73b4df6fa4b1') 2015-12-14 19:38:04.216  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684216|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer12', 'Position 12', 17000, 'd6719dc4-1dfd-433f-a8ae-4c931f461e78') 2015-12-14 19:38:04.216  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684216|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer13', 'Position 13', 18000, 'ca277f3c-d51e-493d-a4f7-a945879bd7d0') 2015-12-14 19:38:04.217  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684217|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer14', 'Position 14', 19000, '07014145-332b-4b4c-b320-9412443c45b6') 2015-12-14 19:38:04.217  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684217|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer15', 'Position 15', 20000, '8ffde083-420f-418d-b624-b059b9e28f3b') 2015-12-14 19:38:04.217  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684217|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer16', 'Position 16', 21000, '6ac39900-69db-408a-bda1-4d2706da49ba') 2015-12-14 19:38:04.217  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684217|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer17', 'Position 17', 22000, '45f6db1b-18cd-4986-8f46-ce8f02d9588d') 2015-12-14 19:38:04.217  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684217|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer18', 'Position 18', 23000, 'b4312298-a818-4b7a-9cff-7923328de4dc') 2015-12-14 19:38:04.218  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684218|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer19', 'Position 19', 24000, 'efe7e3d2-da11-40ce-9fee-6f77726499db') 2015-12-14 19:38:04.218  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684218|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer20', 'Position 20', 25000, 'd51484c3-36e2-4737-b5c9-135709ad1d30') 2015-12-14 19:38:04.808  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684808|2|statement|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer20', 'Position 20', 25000, 'd51484c3-36e2-4737-b5c9-135709ad1d30') 2015-12-14 19:38:04.811  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684811|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer21', 'Position 21', 26000, '8c7e0e43-f89f-4000-8367-3406974102f4') 2015-12-14 19:38:04.811  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684811|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer22', 'Position 22', 27000, 'ab757793-1c45-4861-aff8-aa5cea3c8bd5') 2015-12-14 19:38:04.812  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684812|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer23', 'Position 23', 28000, 'edf18735-cc27-437b-9a28-156f57b51343') 2015-12-14 19:38:04.812  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684812|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer24', 'Position 24', 29000, 'c882f053-2e9a-405f-bb94-3ba83303aefe') 2015-12-14 19:38:04.812  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684812|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer25', 'Position 25', 30000, 'd6af1feb-5842-4b40-816d-8e2aaa2ce9b3') 2015-12-14 19:38:04.812  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684812|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer26', 'Position 26', 31000, '48f6a4cb-5671-4b73-bb51-3e37964fa136') 2015-12-14 19:38:04.813  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684812|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer27', 'Position 27', 32000, '6ac59ed6-2a0f-4dbb-a6d7-7231a9c9d2cc') 2015-12-14 19:38:04.813  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684813|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer28', 'Position 28', 33000, '57565a6a-4e44-4fe0-86bd-837a9687487d') 2015-12-14 19:38:04.813  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684813|0|batch|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer29', 'Position 29', 34000, 'f3c2dbdd-5d54-4bf3-86d2-327c60ee5cc0') 2015-12-14 19:38:04.814  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684814|1|statement|connection 7|insert into customer (name, position, salary, id) values (?, ?, ?, ?)|insert into customer (name, position, salary, id) values ('Customer29', 'Position 29', 34000, 'f3c2dbdd-5d54-4bf3-86d2-327c60ee5cc0') 2015-12-14 19:38:04.817  INFO 14116 --- [io-18080-exec-3] p6spy  : 1450114684817|2|commit|connection 7|| 

The third column is batch indicating that the statement were executed in a JDBC batch.

The column right before the one mentioning batch indicates the amount of milliseconds it took to execute the statement. The ones with 0 are for when the statement is added to the batch.

The ones containing statement in the 3rd column (therefore having a 1 or a 2 in the 2nd column) are for when the batch was executed, which corresponds to the 20th and the 30th iteration.