JPA batch inserts does not improve performance

Question

I would like to improve the performance of my postgresql inserts with JPA batch inserts.

I'm using :

• spring-boot-starter-data-jpa 2.1.3.RELEASE
• postgresql 42.2.5 (jdbc driver).
• Database is PostgreSQL 9.6.2

I have managed to activate JPA's batch inserts, but performance has not improved at all.

• I use @GeneratedValue(strategy = GenerationType.SEQUENCE) in my entities

• I use reWriteBatchedInserts=true in my jdbc connexion string

• I set the following properties :

spring.jpa.properties.hibernate.jdbc.batch_size=100
spring.jpa.properties.hibernate.order_inserts=true
spring.jpa.properties.hibernate.generate_statistics=true

• I use the saveAll(collection) method
• I tried to flush and clean my entityManager after each batch
• I tried with a batch size of 100 and 1000, flushing for each batch, with no noticeable change.

I can see in the logs that hibernate does use batch inserts but am unsure if my database does (I'm trying to fetch the logs, folder permission is pending).

@Service
@Configuration
@Transactional
public class SecteurGeographiqueServiceImpl implements SecteurGeographiqueService {

    private static final Logger logger = LoggerFactory.getLogger(SecteurGeographiqueServiceImpl.class);

@Value("${spring.jpa.properties.hibernate.jdbc.batch_size}")
private int batchSize;

@PersistenceContext
private EntityManager entityManager;

@Autowired
private SecteurGeographiqueRepository secteurGeographiqueRepository;

    @Override
    public List<SecteurGeographique> saveAllSecteurGeographiquesISOs(List<SecteurGeographique> listSecteurGeographiques) {
    logger.warn("BATCH SIZE : " + this.batchSize);
    final List<SecteurGeographique> tempList = new ArrayList<>();
    final List<SecteurGeographique> savedList = new ArrayList<>();
    for (int i = 0; i < listSecteurGeographiques.size(); i++) {
        if ((i % this.batchSize) == 0) {
            savedList.addAll(this.secteurGeographiqueRepository.saveAll(tempList));
            tempList.clear();
            this.entityManager.flush();
            this.entityManager.clear();
        }
        tempList.add(listSecteurGeographiques.get(i));
    }
    savedList.addAll(this.secteurGeographiqueRepository.saveAll(tempList));
    tempList.clear();
    this.entityManager.flush();
    this.entityManager.clear();
    return savedList;
    }

}

...

@Entity
public class SecteurGeographique {

    private static final long serialVersionUID = 1L;

    @Id
    @GeneratedValue(strategy = GenerationType.SEQUENCE)
    @Column(name = "id")
    public Long id;
...

My repository implementation is :

org.springframework.data.jpa.repository.JpaRepository<SecteurGeographique, Long>

application.properties (connection part) :

spring.datasource.url=jdbc:postgresql://xx.xx.xx.xx:5432/bddname?reWriteBatchedInserts=true
spring.jpa.properties.hibernate.default_schema=schema
spring.datasource.username=xxxx
spring.datasource.password=xxxx
spring.datasource.driverClassName=org.postgresql.Driver
spring.jpa.properties.hibernate.dialect=org.hibernate.dialect.PostgreSQLDialect
spring.jpa.properties.hibernate.jdbc.lob.non_contextual_creation=true
spring.jpa.properties.hibernate.jdbc.batch_size=100
spring.jpa.properties.hibernate.order_inserts=true
spring.jpa.properties.hibernate.generate_statistics=true

And in the logs after my 16073 entities are inserted (this test does not include flushing) :

13:31:40.882 [restartedMain] INFO  o.h.e.i.StatisticalLoggingSessionEventListener - Session Metrics {
    15721506 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    121091067 nanoseconds spent preparing 16074 JDBC statements;
    240144821872 nanoseconds spent executing 16073 JDBC statements;
    3778202166 nanoseconds spent executing 161 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    4012929596 nanoseconds spent executing 1 flushes (flushing a total of 16073 entities and 0 collections);
    0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
}

Note that this is just one table, with no constraint / foreign key. Just flat basic data in a table, nothing fancy.

From the logs ot does look like there is a problem :

240144821872 nanoseconds spent executing <b>16073 JDBC statements</b>;
3778202166 nanoseconds spent executing 161 JDBC batches;

Shouldn't it be "executing 161 JDBC statements" if everything is in the batches ?

Tests with flushes, and batch sizes 100 then 1000 :

15:32:17.612 [restartedMain] WARN  f.g.j.a.r.s.i.SecteurGeographiqueServiceImpl - BATCH SIZE : 100
15:36:46.206 [restartedMain] INFO  o.h.e.i.StatisticalLoggingSessionEventListener - Session Metrics {
    15416324 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    105369002 nanoseconds spent preparing 16234 JDBC statements;
    262388696401 nanoseconds spent executing 16073 JDBC statements;
    3669253410 nanoseconds spent executing 161 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    3956493726 nanoseconds spent executing 161 flushes (flushing a total of 16073 entities and 0 collections);
    0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
}

15:43:54.155 [restartedMain] WARN  f.g.j.a.r.s.i.SecteurGeographiqueServiceImpl - BATCH SIZE : 1000
15:48:22.335 [restartedMain] INFO  o.h.e.i.StatisticalLoggingSessionEventListener - Session Metrics {
    15676227 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    111370586 nanoseconds spent preparing 16090 JDBC statements;
    265089247563 nanoseconds spent executing 16073 JDBC statements;
    599946208 nanoseconds spent executing 17 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    866452023 nanoseconds spent executing 17 flushes (flushing a total of 16073 entities and 0 collections);
    0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
}

Each time I get a 4min 30sec execution time. It feels enormous for batch inserts. What am I missing / misinterpreting ?

Answer 1

After trying a batch size of 1000 with a postgresql server on localhost (https://gareth.flowers/postgresql-portable/ v10.1.1), the execution runs under 3 seconds. So it seems the code or configuration is not to blame here.

Unfortunately I cannot investigate why it was taking so much time on the remote postgresql (hosted on an AWS), but I can only conclude this was a network or database issue.

As of today I cannot access postgresql remote logs, but if you have any advice on what to look for on the postgresql instance, I'm all ears.

Logs with batching (1000) and flush+clean :

16:20:52.360 [restartedMain] WARN  f.g.j.a.r.s.i.SecteurGeographiqueServiceImpl - BATCH SIZE : 1000
16:20:54.844 [restartedMain] INFO  o.h.e.i.StatisticalLoggingSessionEventListener - Session Metrics {
    523125 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    44649191 nanoseconds spent preparing 16090 JDBC statements;
    1311557995 nanoseconds spent executing 16073 JDBC statements;
    204225325 nanoseconds spent executing 17 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    381230968 nanoseconds spent executing 17 flushes (flushing a total of 16073 entities and 0 collections);
    0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
}

Logs WITHOUT batching, flush or clean :

16:57:34.426 [restartedMain] INFO  o.h.e.i.StatisticalLoggingSessionEventListener - Session Metrics {
    725069 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    55763008 nanoseconds spent preparing 32146 JDBC statements;
    2816525053 nanoseconds spent executing 32146 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    1796451447 nanoseconds spent executing 1 flushes (flushing a total of 16073 entities and 0 collections);
    0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
}

This comparison shows a 46% gain in the overall JDBC statements execution time.