Message Title

Florian Buchnet created an issue

Issue Type:	Bug
Affects Versions:	5.2.10
Assignee:	Unassigned
Created:	02/May/2017 04:57 AM
Environment:	Wildfly 10.1, Hibernate 5.2.10, Oracle 11
Labels:	hibernate performance
Priority:	Major
Reporter:	Florian Buchnet

I have several entities with a bidirectional @OneToMany-relation with @JoinTable. Functionality is working fine, besides the performance of inserting large amounts of datasets to the database. I found out that in this case Hibernate isn't using batch-processing for all entities. Hibernate using batch-processing for the parent-entities, but not for the childs. It inserts all parent-datasets to the database with batch-processing, but then it generates a child-dataset, then the associated mappingtable-dataset, then the next child-dataset, then the associated mappingtable-dataset and so on, all with single statements.

When i change the @OneToMany-Relation for test to a @ManyToMany-Relation then batch-processing is used for all datasets, first all parents, then all childs, then all mappings and the performance is increasing dramatically. Also on a unidirectional OneToMany-Relation batch-processing is working fine.

Easy example to reproduce:
Parent A:

 
                                                                package com.flobuc;

import javax.persistence.*;
import java.util.Collection;

@Entity
@Table(name = "A")
public class A {
    private String id;
    private String name;
    private Collection<B> bs;

    @Id
    @Column(name = "ID")
    public String getId() {
        return id;
    }

    public void setId(String id) {
        this.id = id;
    }

    @Basic
    @Column(name = "NAME")
    public String getName() {
        return name;
    }

    public void setName(String name) {
        this.name = name;
    }


    @OneToMany(cascade = CascadeType.ALL, mappedBy = "a")
    public Collection<B> getBs() {
        return bs;
    }

    public void setBs(Collection<B> bs) {
        this.bs = bs;
    }

    @Override
    public boolean equals(Object o) {
        if (this == o) return true;
        if (o == null || getClass() != o.getClass()) return false;

        A a = (A) o;

        if (id != null ? !id.equals(a.id) : a.id != null) return false;
        return name != null ? name.equals(a.name) : a.name == null;
    }

    @Override
    public int hashCode() {
        int result = id != null ? id.hashCode() : 0;
        result = 31 * result + (name != null ? name.hashCode() : 0);
        return result;
    }
}
 
                                                            

Child B:

 
                                                                package com.flobuc;

import javax.persistence.*;

@Entity
@Table(name = "B")
public class B {
    private String id;
    private String name;
    private A a;

    @Id
    @Column(name = "ID")
    public String getId() {
        return id;
    }

    public void setId(String id) {
        this.id = id;
    }

    @Basic
    @Column(name = "NAME")
    public String getName() {
        return name;
    }

    public void setName(String name) {
        this.name = name;
    }

    @ManyToOne
    @JoinTable(
            name="A2B",
            joinColumns = {@JoinColumn(name = "B_ID", referencedColumnName = "ID", nullable = false)},
            inverseJoinColumns={@JoinColumn(name = "A_ID", referencedColumnName = "ID", nullable = false)})
    public A getA() {
        return a;
    }

    public void setA(A a) {
        this.a = a;
    }

    @Override
    public boolean equals(Object o) {
        if (this == o) return true;
        if (o == null || getClass() != o.getClass()) return false;

        B b = (B) o;

        if (id != null ? !id.equals(b.id) : b.id != null) return false;
        return name != null ? name.equals(b.name) : b.name == null;
    }

    @Override
    public int hashCode() {
        int result = id != null ? id.hashCode() : 0;
        result = 31 * result + (name != null ? name.hashCode() : 0);
        return result;
    }
}
 
                                                            

Generate Entities and persist:

 
                                                                List<A> as = new ArrayList<>();

for (int i = 0; i < 100 ; i++) {

    A a = new A();
    a.setId("ID-A-" + i);
    a.setName("Name ID-" + i);

    a.setBs(new HashSet<>());

    for (int j = 0; j < 50 ; j++) {
        B b =new B();
        b.setId("ID-B-" + j + "ID-A-" + i);
        b.setName("Name ID-" + j + " Parent " + i);
        b.setA(a);
        a.getBs().add(b);
    }

    as.add(a);

}

for(A a : as){
    em.persist(a);
}
 
                                                            

persistence.xml:

 
                                                                <?xml version="1.0" encoding="UTF-8"?>
<persistence version="2.1" xmlns="http://xmlns.jcp.org/xml/ns/persistence"
             xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
             xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/persistence
                                 http://xmlns.jcp.org/xml/ns/persistence/persistence_2_1.xsd">

    <persistence-unit name="TimetablePU" transaction-type="JTA">

        <jta-data-source>java:/TimetableDS</jta-data-source>
        <class&gt;com.atron.atries.rx.asdm.dao.entity.netex.A</class&gt;
        <class&gt;com.atron.atries.rx.asdm.dao.entity.netex.B</class&gt;
        <exclude-unlisted-classes>true</exclude-unlisted-classes>
        <properties>
            <property name="hibernate.dialect" value="org.hibernate.dialect.Oracle10gDialect"/>
            <property name="hibernate.jdbc.batch_size" value="10"/>
            <property name="hibernate.order_inserts" value="true"/>
            <property name="hibernate.order_updates" value="true"/>
            <property name="hibernate.jdbc.batch_versioned_data" value="true"/>               
        </properties>

    </persistence-unit>

</persistence>
 
                                                            

Here is the log-file for inserting the entries on the one-side in table A with using batch:

 
                                                                2017-04-27 09:03:33,451 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Inserting entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-0]
2017-04-27 09:03:33,469 TRACE [org.hibernate.service.internal.AbstractServiceRegistryImpl] (default task-1) Initializing service [role=org.hibernate.engine.jdbc.batch.spi.BatchBuilder]
2017-04-27 09:03:33,471 TRACE [org.hibernate.service.internal.AbstractServiceRegistryImpl] (default task-1) Initializing service [role=org.hibernate.jmx.spi.JmxService]
2017-04-27 09:03:33,472 TRACE [org.hibernate.engine.jdbc.batch.internal.BatchBuilderImpl] (default task-1) Building batch [size=10]
2017-04-27 09:03:33,478 DEBUG [org.hibernate.SQL] (default task-1) insert into A (NAME, ID) values (?, ?)
2017-04-27 09:03:33,547 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl] (default task-1) Registering statement [org.jboss.jca.adapters.jdbc.jdk7.WrappedPreparedStatementJDK7@4f1b4848]
2017-04-27 09:03:33,548 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Dehydrating entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-0]
2017-04-27 09:03:33,551 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [1] as [VARCHAR] - [Name ID-0]
2017-04-27 09:03:33,551 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [2] as [VARCHAR] - [ID-A-0]
2017-04-27 09:03:33,552 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Inserting entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-1]
2017-04-27 09:03:33,552 DEBUG [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (default task-1) Reusing batch statement
2017-04-27 09:03:33,552 DEBUG [org.hibernate.SQL] (default task-1) insert into A (NAME, ID) values (?, ?)
2017-04-27 09:03:33,552 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Dehydrating entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-1]
2017-04-27 09:03:33,552 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [1] as [VARCHAR] - [Name ID-1]
2017-04-27 09:03:33,552 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [2] as [VARCHAR] - [ID-A-1]
2017-04-27 09:03:33,552 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Inserting entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-2]
2017-04-27 09:03:33,552 DEBUG [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (default task-1) Reusing batch statement
2017-04-27 09:03:33,552 DEBUG [org.hibernate.SQL] (default task-1) insert into A (NAME, ID) values (?, ?)
2017-04-27 09:03:33,552 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Dehydrating entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-2]
2017-04-27 09:03:33,553 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [1] as [VARCHAR] - [Name ID-2]
2017-04-27 09:03:33,553 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [2] as [VARCHAR] - [ID-A-2]
2017-04-27 09:03:33,553 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Inserting entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-3]
2017-04-27 09:03:33,553 DEBUG [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (default task-1) Reusing batch statement
2017-04-27 09:03:33,553 DEBUG [org.hibernate.SQL] (default task-1) insert into A (NAME, ID) values (?, ?)
2017-04-27 09:03:33,553 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Dehydrating entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-3]
2017-04-27 09:03:33,553 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [1] as [VARCHAR] - [Name ID-3]
2017-04-27 09:03:33,553 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [2] as [VARCHAR] - [ID-A-3]
2017-04-27 09:03:33,553 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Inserting entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-4]
2017-04-27 09:03:33,553 DEBUG [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (default task-1) Reusing batch statement
2017-04-27 09:03:33,553 DEBUG [org.hibernate.SQL] (default task-1) insert into A (NAME, ID) values (?, ?)
2017-04-27 09:03:33,553 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Dehydrating entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-4]
2017-04-27 09:03:33,553 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [1] as [VARCHAR] - [Name ID-4]
2017-04-27 09:03:33,553 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [2] as [VARCHAR] - [ID-A-4]
2017-04-27 09:03:33,553 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Inserting entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-5]
2017-04-27 09:03:33,553 DEBUG [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (default task-1) Reusing batch statement
2017-04-27 09:03:33,553 DEBUG [org.hibernate.SQL] (default task-1) insert into A (NAME, ID) values (?, ?)
2017-04-27 09:03:33,553 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Dehydrating entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-5]
2017-04-27 09:03:33,553 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [1] as [VARCHAR] - [Name ID-5]
2017-04-27 09:03:33,553 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [2] as [VARCHAR] - [ID-A-5]
2017-04-27 09:03:33,553 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Inserting entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-6]
2017-04-27 09:03:33,553 DEBUG [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (default task-1) Reusing batch statement
2017-04-27 09:03:33,553 DEBUG [org.hibernate.SQL] (default task-1) insert into A (NAME, ID) values (?, ?)
2017-04-27 09:03:33,553 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Dehydrating entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-6]
2017-04-27 09:03:33,554 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [1] as [VARCHAR] - [Name ID-6]
2017-04-27 09:03:33,554 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [2] as [VARCHAR] - [ID-A-6]
2017-04-27 09:03:33,554 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Inserting entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-7]
2017-04-27 09:03:33,554 DEBUG [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (default task-1) Reusing batch statement
2017-04-27 09:03:33,554 DEBUG [org.hibernate.SQL] (default task-1) insert into A (NAME, ID) values (?, ?)
2017-04-27 09:03:33,554 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Dehydrating entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-7]
2017-04-27 09:03:33,554 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [1] as [VARCHAR] - [Name ID-7]
2017-04-27 09:03:33,554 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [2] as [VARCHAR] - [ID-A-7]
2017-04-27 09:03:33,554 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Inserting entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-8]
2017-04-27 09:03:33,554 DEBUG [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (default task-1) Reusing batch statement
2017-04-27 09:03:33,554 DEBUG [org.hibernate.SQL] (default task-1) insert into A (NAME, ID) values (?, ?)
2017-04-27 09:03:33,554 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Dehydrating entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-8]
2017-04-27 09:03:33,554 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [1] as [VARCHAR] - [Name ID-8]
2017-04-27 09:03:33,554 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [2] as [VARCHAR] - [ID-A-8]
2017-04-27 09:03:33,554 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Inserting entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-9]
2017-04-27 09:03:33,554 DEBUG [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (default task-1) Reusing batch statement
2017-04-27 09:03:33,554 DEBUG [org.hibernate.SQL] (default task-1) insert into A (NAME, ID) values (?, ?)
2017-04-27 09:03:33,554 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Dehydrating entity: [com.atron.atries.rx.asdm.dao.entity.netex.A#ID-A-9]
2017-04-27 09:03:33,554 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [1] as [VARCHAR] - [Name ID-9]
2017-04-27 09:03:33,554 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [2] as [VARCHAR] - [ID-A-9]
2017-04-27 09:03:33,555 DEBUG [org.hibernate.engine.jdbc.batch.internal.BatchingBatch] (default task-1) Executing batch size: 10
2017-04-27 09:03:33,561 DEBUG [org.hibernate.jdbc.Expectations] (default task-1) Success of batch update unknown: 0
2017-04-27 09:03:33,561 DEBUG [org.hibernate.jdbc.Expectations] (default task-1) Success of batch update unknown: 1
2017-04-27 09:03:33,561 DEBUG [org.hibernate.jdbc.Expectations] (default task-1) Success of batch update unknown: 2
2017-04-27 09:03:33,561 DEBUG [org.hibernate.jdbc.Expectations] (default task-1) Success of batch update unknown: 3
2017-04-27 09:03:33,561 DEBUG [org.hibernate.jdbc.Expectations] (default task-1) Success of batch update unknown: 4
2017-04-27 09:03:33,561 DEBUG [org.hibernate.jdbc.Expectations] (default task-1) Success of batch update unknown: 5
2017-04-27 09:03:33,561 DEBUG [org.hibernate.jdbc.Expectations] (default task-1) Success of batch update unknown: 6
2017-04-27 09:03:33,561 DEBUG [org.hibernate.jdbc.Expectations] (default task-1) Success of batch update unknown: 7
2017-04-27 09:03:33,561 DEBUG [org.hibernate.jdbc.Expectations] (default task-1) Success of batch update unknown: 8
2017-04-27 09:03:33,561 DEBUG [org.hibernate.jdbc.Expectations] (default task-1) Success of batch update unknown: 9
 
                                                            

and here is the log-file-part for inserting the many-side entries in table B and in the mapping-table A2B without using batch:

 
                                                                2017-04-27 09:03:41,783 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Inserting entity: [com.atron.atries.rx.asdm.dao.entity.netex.B#ID-B-29ID-A-28]
2017-04-27 09:03:41,783 DEBUG [org.hibernate.SQL] (default task-1) insert into B (NAME, ID) values (?, ?)
2017-04-27 09:03:41,783 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl] (default task-1) Registering statement [org.jboss.jca.adapters.jdbc.jdk7.WrappedPreparedStatementJDK7@278944be]
2017-04-27 09:03:41,783 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Dehydrating entity: [com.atron.atries.rx.asdm.dao.entity.netex.B#ID-B-29ID-A-28]
2017-04-27 09:03:41,783 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [1] as [VARCHAR] - [Name ID-29 Parent 28]
2017-04-27 09:03:41,783 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [2] as [VARCHAR] - [ID-B-29ID-A-28]
2017-04-27 09:03:41,783 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Inserting entity: [com.atron.atries.rx.asdm.dao.entity.netex.B#ID-B-29ID-A-28]
2017-04-27 09:03:41,783 DEBUG [org.hibernate.engine.jdbc.batch.internal.BatchingBatch] (default task-1) Executing batch size: 1
2017-04-27 09:03:41,783 DEBUG [org.hibernate.jdbc.Expectations] (default task-1) Success of batch update unknown: 0
2017-04-27 09:03:41,783 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl] (default task-1) Releasing statement [org.jboss.jca.adapters.jdbc.jdk7.WrappedPreparedStatementJDK7@278944be]
2017-04-27 09:03:41,783 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl] (default task-1) Closing prepared statement [org.jboss.jca.adapters.jdbc.jdk7.WrappedPreparedStatementJDK7@278944be]
2017-04-27 09:03:41,783 TRACE [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] (default task-1) Starting after statement execution processing [AFTER_STATEMENT]
2017-04-27 09:03:41,783 DEBUG [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] (default task-1) Skipping aggressive release due to manual disabling
2017-04-27 09:03:41,783 DEBUG [org.hibernate.SQL] (default task-1) insert into A2B (A_ID, B_ID) values (?, ?)
2017-04-27 09:03:41,783 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl] (default task-1) Registering statement [org.jboss.jca.adapters.jdbc.jdk7.WrappedPreparedStatementJDK7@1ca56b4c]
2017-04-27 09:03:41,783 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default task-1) Dehydrating entity: [com.atron.atries.rx.asdm.dao.entity.netex.B#ID-B-29ID-A-28]
2017-04-27 09:03:41,783 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [1] as [VARCHAR] - [ID-A-28]
2017-04-27 09:03:41,783 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1) binding parameter [2] as [VARCHAR] - [ID-B-29ID-A-28]
2017-04-27 09:03:41,783 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl] (default task-1) Releasing statement [org.jboss.jca.adapters.jdbc.jdk7.WrappedPreparedStatementJDK7@1ca56b4c]
2017-04-27 09:03:41,783 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl] (default task-1) Closing prepared statement [org.jboss.jca.adapters.jdbc.jdk7.WrappedPreparedStatementJDK7@1ca56b4c]
2017-04-27 09:03:41,783 TRACE [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] (default task-1) Starting after statement execution processing [AFTER_STATEMENT]
 
                                                            

Add Comment

This message was sent by Atlassian JIRA