Hibernate Community • View topic

View unanswered posts | View active topics

Board index » Hibernate & Java Persistence » Hibernate Users

All times are UTC - 5 hours [ DST ]

Slow commit times

Page 1 of 1

[ 10 posts ]

Previous topic | Next topic

Author

Message

IanWorthington

Post subject: Slow commit times

Posted: Tue Dec 29, 2015 9:01 am

Newbie

Joined: Tue Dec 29, 2015 8:38 am
Posts: 6

I'm testing a Hibernate/JPA application and finding it has very poor commit times.

The application consists of two simple classes:

Code:

@Entity
@Table
public class RouteCabinFares {
    @Id @GeneratedValue
    private Long id;   
    private String originCity;
    private String destinationCity;
    private String cabin;
    private String siteCountry;
    private SearchType paymentType;
        
    @ElementCollection
    @CollectionTable    
    private List<PriceData> fareList = new ArrayList<>(); 

Code:

@Embeddable
public class PriceData {
   @Transient
   final private static  Logger log = LoggerFactory.getLogger(PriceData.class);
   
   @Transient
   final private static DateTimeFormatter inputFmt  = DateTimeFormatter.ofPattern("yyyy-MM-dd'T'HH:mm");
   @Transient
   final private static DateTimeFormatter outputFmt = DateTimeFormatter.ofPattern("yyyy-MM-dd");
   
   
   private String stringPrice;
   private int intPrice;
   private LocalDate departureDate;
   private LocalDate returnDate;
   private ZonedDateTime foundDateTimeUtc;

PriceData is harvested and added to the database using the following code:

Code:

                EntityManager entityManager = entityManagerFactory.createEntityManager();
           EntityTransaction transaction = entityManager.getTransaction();
           transaction.begin();                     
           
           try {
            @SuppressWarnings("unchecked")
            List<RouteCabinFares> existingRcfFaresList = (List<RouteCabinFares>) entityManager.createQuery("select rcf from RouteCabinFares rcf")
                                                                         .getResultList();
            
            log.info( "{}() {} RCFs found in database", 
                  Thread.currentThread().getStackTrace()[1].getMethodName(), 
                  existingRcfFaresList.size() );
            
                        
            RouteCabinFares existingRcfFare = (RouteCabinFares) entityManager.createQuery("select rcf from RouteCabinFares rcf where lower(rcf.originCity) = :originCity and lower(rcf.destinationCity) = :destinationCity and lower(rcf.cabin) = :cabin and lower(rcf.siteCountry) = :siteCountry and rcf.paymentType = :paymentType")      // put in @NamedQuery
                                                      .setParameter("originCity",      originCity.toLowerCase()) // TODO lower() does not solve accent problem!!
                                                      .setParameter("destinationCity", destinationCity.toLowerCase())
                                                      .setParameter("cabin",           cabin.toLowerCase())
                                                      .setParameter("siteCountry",     siteCountry.toLowerCase())
                                                      .setParameter("paymentType",     paymentType)
                                                      .setMaxResults(1)
                                                      .getSingleResult();                                                      
            // No results here causes NoResultException
                          
            log.info( "{}() Match found in database: {}", 
                  Thread.currentThread().getStackTrace()[1].getMethodName(), 
                  existingRcfFare.toString() );
            
            faresInDb = existingRcfFare.getFareList().size();
            newFares  = rcFares.getFareList().size();
            
            log.info( "{}() {} fares already in db, adding {} new fares...", 
                  Thread.currentThread().getStackTrace()[1].getMethodName(), 
                  faresInDb,
                  newFares
                  );            
         
            existingRcfFare.getFareList()
                        .addAll(rcFares.getFareList());               
           }         
         catch (NoResultException | SQLGrammarException exc) {
            log.info( "{}() No matching RCF data in database, will be added", 
                  Thread.currentThread().getStackTrace()[1].getMethodName() );   
            
            faresInDb = 0;
            newFares  = rcFares.getFareList().size();
            
            entityManager.persist(rcFares);
         }             
           
           log.info( "{}() Starting commit...", 
               Thread.currentThread().getStackTrace()[1].getMethodName() );
           
           transaction.commit();           
           
           log.info( "{}() Commit complete, starting close...", 
               Thread.currentThread().getStackTrace()[1].getMethodName() );
           entityManager.close();
           
           log.info( "{}() Close complete", 
               Thread.currentThread().getStackTrace()[1].getMethodName() );

ie retrieve the relevant RouteCabinFares record, add in the data to the PriceData collection, and commit.

I'm finding though that commit times are proportional to the total number of records in the collection, not to the number of records I'm adding. This can degrade rapidly causing commit times of several minutes (I'm seeing ~1 mSec/record).

Am I right in thinking that even though the original collection data is being loaded lazily it still has to be checked at commit to see if it's dirty, and that's its this process that is causing the long commit times?

If so, is there any other solution other than changing the entity record to have a collection per database load rather than all the fare data together?

Ian

Top

vlad

Post subject: Re: Slow commit times

Posted: Tue Dec 29, 2015 9:24 am

Hibernate Team

Joined: Thu Sep 11, 2014 2:50 am
Posts: 1628
Location: Romania

That's actually right. The dirty checking mechanism verifies every managed entity during flush time, which happens before a commit:

You need to fetch less data of you don't really need to modify it. The problem is here:

Code:

existingRcfFare.getFareList().addAll(rcFares.getFareList());

If you have 10k or 100k children, then you have to fetch them all only to persist the new entries.
You can optimize this by turning the PriceData into a stand-alone entity and adding a @ManyToOne association back to its parent RouteCabinFares entity.

You don't have to use the collection to save those new entities, so you can remove it altogether and use a query whenever you need to fetch the children records.
This way, you don't have to fetch the collection to add/remove PriceData entities, and if the number of children is large, you can better paginate the results with a query rather than a mapping.

Top

IanWorthington

Post subject: Re: Slow commit times

Posted: Tue Dec 29, 2015 1:37 pm

Newbie

Joined: Tue Dec 29, 2015 8:38 am
Posts: 6

Thanks for your most rapid response. I was hoping to avoid the rats nest of cascade options and management that treating a value type as an entity entails but you're right, that would seem to be the better solution in this case.

I'm curious though as to why dirty-checking of unreferenced lazily-loaded objects should be so slow at seemingly about 1 msec each. Is hibernate really fetching them all? Does that make sense?

Top

IanWorthington

Post subject: Re: Slow commit times

Posted: Thu Jan 07, 2016 2:07 am

Newbie

Joined: Tue Dec 29, 2015 8:38 am
Posts: 6

Thanks for your advice.

I've updated the classes to

Code:

@Entity
@Table
public class RouteCabinFares {
    @Id @GeneratedValue
    private Long id;   
    private String originCity;
    private String destinationCity;
    private String cabin;
    private String siteCountry;
    private SearchType paymentType;
          
    @OneToMany(mappedBy = "routeCabinFares", cascade = CascadeType.ALL, orphanRemoval=true)
    private List<PriceData> fareList = new ArrayList<>();     
        
    protected RouteCabinFares(){} // required by hibernate
 
    public RouteCabinFares( String originCity, String destinationCity, String cabin, String siteCountry, SearchType paymentType )  {
       this.originCity = originCity;
       this.destinationCity = destinationCity;
       this.cabin   = cabin;
       this.siteCountry = siteCountry; 
       this.paymentType = paymentType;
       //this.fareList = fareList;
    }
    
   public RouteCabinFares setFareList(List<PriceData> fareList) {
      this.fareList = fareList; 
      
      return this;
   }
   
   public RouteCabinFares addFare( PriceData fare ) {
      fare.setRouteCabinFares(this); 
      fareList.add(fare);
      
      return this;
   }
   
   public RouteCabinFares addFareList( List<PriceData> fareList ) {
      for (PriceData fare : fareList) {
         addFare(fare);         
      }
      
      return this;
   }   

and

Code:

@Entity
@Table
public class PriceData {
  @Id @GeneratedValue
  private Long id;
    
   @Transient
   final private static  Logger log = LoggerFactory.getLogger(PriceData.class);
   
   @Transient
   final private static DateTimeFormatter inputFmt  = DateTimeFormatter.ofPattern("yyyy-MM-dd'T'HH:mm");
   @Transient
   final private static DateTimeFormatter outputFmt = DateTimeFormatter.ofPattern("yyyy-MM-dd");
   
   @ManyToOne
   @JoinColumn(nullable = false)
   private RouteCabinFares routeCabinFares;
   
   private String stringPrice;
   private int intPrice;
   private LocalDate departureDate;
   private LocalDate returnDate;
   private ZonedDateTime foundDateTimeUtc;
   
   @Transient
   private int quantile = Integer.MIN_VALUE;
   @Transient
   private int percentageMoreExpensive;
   
   protected PriceData() {} // required for hibernate
   
   public PriceData( String stringPrice,
                   int intPrice,
                   String departureDate,
                   String returnDate, 
                   ZonedDateTime foundDateTimeUtc
                   ) {      
      this.stringPrice = stringPrice;
      this.intPrice = intPrice;
      this.departureDate = LocalDate.parse(departureDate, inputFmt);
      this.returnDate = LocalDate.parse(returnDate, inputFmt);   
      this.foundDateTimeUtc = foundDateTimeUtc;
      this.routeCabinFares = null;
   }

respectively, and the mainline is relatively unchanged as:

Code:

           // Start unit of work
           EntityManager entityManager = entityManagerFactory.createEntityManager();
           EntityTransaction transaction = entityManager.getTransaction();
           transaction.begin();                     
           
           try {
            @SuppressWarnings("unchecked")
            List<RouteCabinFares> existingRcfFaresList = (List<RouteCabinFares>) entityManager.createQuery("select rcf from RouteCabinFares rcf")
                                                                             .getResultList();
            
            log.info( "{}() {} RCFs found in database", 
                  Thread.currentThread().getStackTrace()[1].getMethodName(), 
                  existingRcfFaresList.size() );
            
                        
            RouteCabinFares existingRcfFare = (RouteCabinFares) entityManager.createQuery("select rcf from RouteCabinFares rcf where lower(rcf.originCity) = :originCity and lower(rcf.destinationCity) = :destinationCity and lower(rcf.cabin) = :cabin and lower(rcf.siteCountry) = :siteCountry and rcf.paymentType = :paymentType")      // TODO put in @NamedQuery
                                                      .setParameter("originCity",      originCity.toLowerCase()) // TODO lower() does not solve accent problem!!
                                                      .setParameter("destinationCity", destinationCity.toLowerCase())
                                                      .setParameter("cabin",           cabin.toLowerCase())
                                                      .setParameter("siteCountry",     siteCountry.toLowerCase())
                                                      .setParameter("paymentType",     paymentType)
                                                      .setMaxResults(1)
                                                      .getSingleResult();
                                                      //.getResultList();
            // No results here causes NoResultException
                          
            log.info( "{}() Match found in database: {}", 
                  Thread.currentThread().getStackTrace()[1].getMethodName(), 
                  existingRcfFare.toString() );
            
            faresInDb = existingRcfFare.getFareList().size();
            newFares  = fareList.size();
            
            log.info( "{}() {} fares already in db, adding {} new fares...", 
                  Thread.currentThread().getStackTrace()[1].getMethodName(), 
                  faresInDb,
                  newFares
                  );
            
            startTime = System.nanoTime();
   
            existingRcfFare.addFareList(fareList);                             
            
            addTimeUs = (System.nanoTime() - startTime) / 1000;
           }         
         catch (NoResultException | SQLGrammarException exc) {   
            log.info( "{}() No matching RCF data in database, will be added", 
                  Thread.currentThread().getStackTrace()[1].getMethodName() );   
            
            faresInDb = 0;
            newFares  = fareList.size();
            
            rcFares.addFareList(fareList);   
            
            entityManager.persist(rcFares);
         }             
           
           // End unit of work
           log.info( "{}() Starting commit...", 
               Thread.currentThread().getStackTrace()[1].getMethodName() );
           
           startTime = System.nanoTime();
           
           transaction.commit();
           
           commitTimeMs = (System.nanoTime() - startTime) / 1000000;
           
           
           log.info( "{}() Commit complete, starting close...", 
               Thread.currentThread().getStackTrace()[1].getMethodName() );
           entityManager.close();
           
           log.info( "{}() Close complete", 
               Thread.currentThread().getStackTrace()[1].getMethodName() );
           
           
         log.info( "{}() Existing fares in db: {}; New fares added: {}; Collection add in {} uSecs; Commit in {} mSecs", 
               Thread.currentThread().getStackTrace()[1].getMethodName(), 
               faresInDb,
                 newFares,
                 addTimeUs,
                 commitTimeMs );
      
      }   

This retains the collection and reduces the commit time to 4.7 ~7.1 seconds (median ~5.4 s) for adding a fareList of 3600 items, regardless of the total number of existing fares linked to the master RouteCabinFares class.

I have the following doubts though:

o Whilst 5~6 seconds is acceptable for my application 1.5 ms/record feels slow to me. Is this normal?
o Why don't I get the same dirty checking delay linking as a ManyToOne entity as I did when I was linking a value type?

Ian

Top

vlad

Post subject: Re: Slow commit times

Posted: Thu Jan 07, 2016 4:04 am

Hibernate Team

Joined: Thu Sep 11, 2014 2:50 am
Posts: 1628
Location: Romania

You can optimize it further by enabling batch inserts.

Top

IanWorthington

Post subject: Re: Slow commit times

Posted: Fri Jan 08, 2016 1:21 am

Newbie

Joined: Tue Dec 29, 2015 8:38 am
Posts: 6

I've added

Code:

But it seems to have made little difference?

Turning on

Code:

<property name="hibernate.show_sql" value="true"/>
<property name="hibernate.format_sql" value="true"/>
<property name="use_sql_comments" value="true"/

gives me the following output with no signs that any batching is taking place:

Code:

00:13:07.028 [34mINFO [0;39m [[36mbiz.ianw.lanchecker.Main[0;39m] - main() 10759 fares already in db, adding 10 new fares...
00:13:07.028 [34mINFO [0;39m [[36mbiz.ianw.lanchecker.Main[0;39m] - main() Starting commit...
Hibernate: 
    select
        next_val as id_val 
    from
        hibernate_sequence for update
            
Hibernate: 
    update
        hibernate_sequence 
    set
        next_val= ? 
    where
        next_val=?
Hibernate: 
    select
        next_val as id_val 
    from
        hibernate_sequence for update
            
Hibernate: 
    update
        hibernate_sequence 
    set
        next_val= ? 
    where
        next_val=?
Hibernate: 
    select
        next_val as id_val 
    from
        hibernate_sequence for update
            
Hibernate: 
    update
        hibernate_sequence 
    set
        next_val= ? 
    where
        next_val=?
Hibernate: 
    select
        next_val as id_val 
    from
        hibernate_sequence for update
            
Hibernate: 
    update
        hibernate_sequence 
    set
        next_val= ? 
    where
        next_val=?
Hibernate: 
    select
        next_val as id_val 
    from
        hibernate_sequence for update
            
Hibernate: 
    update
        hibernate_sequence 
    set
        next_val= ? 
    where
        next_val=?
Hibernate: 
    select
        next_val as id_val 
    from
        hibernate_sequence for update
            
Hibernate: 
    update
        hibernate_sequence 
    set
        next_val= ? 
    where
        next_val=?
Hibernate: 
    select
        next_val as id_val 
    from
        hibernate_sequence for update
            
Hibernate: 
    update
        hibernate_sequence 
    set
        next_val= ? 
    where
        next_val=?
Hibernate: 
    select
        next_val as id_val 
    from
        hibernate_sequence for update
            
Hibernate: 
    update
        hibernate_sequence 
    set
        next_val= ? 
    where
        next_val=?
Hibernate: 
    select
        next_val as id_val 
    from
        hibernate_sequence for update
            
Hibernate: 
    update
        hibernate_sequence 
    set
        next_val= ? 
    where
        next_val=?
Hibernate: 
    select
        next_val as id_val 
    from
        hibernate_sequence for update
            
Hibernate: 
    update
        hibernate_sequence 
    set
        next_val= ? 
    where
        next_val=?
Hibernate: 
    insert 
    into
        PriceData
        (departureDate, foundDateTimeUtc, intPrice, returnDate, routeCabinFares_id, stringPrice, id) 
    values
        (?, ?, ?, ?, ?, ?, ?)
Hibernate: 
    insert 
    into
        PriceData
        (departureDate, foundDateTimeUtc, intPrice, returnDate, routeCabinFares_id, stringPrice, id) 
    values
        (?, ?, ?, ?, ?, ?, ?)
Hibernate: 
    insert 
    into
        PriceData
        (departureDate, foundDateTimeUtc, intPrice, returnDate, routeCabinFares_id, stringPrice, id) 
    values
        (?, ?, ?, ?, ?, ?, ?)
Hibernate: 
    insert 
    into
        PriceData
        (departureDate, foundDateTimeUtc, intPrice, returnDate, routeCabinFares_id, stringPrice, id) 
    values
        (?, ?, ?, ?, ?, ?, ?)
Hibernate: 
    insert 
    into
        PriceData
        (departureDate, foundDateTimeUtc, intPrice, returnDate, routeCabinFares_id, stringPrice, id) 
    values
        (?, ?, ?, ?, ?, ?, ?)
Hibernate: 
    insert 
    into
        PriceData
        (departureDate, foundDateTimeUtc, intPrice, returnDate, routeCabinFares_id, stringPrice, id) 
    values
        (?, ?, ?, ?, ?, ?, ?)
Hibernate: 
    insert 
    into
        PriceData
        (departureDate, foundDateTimeUtc, intPrice, returnDate, routeCabinFares_id, stringPrice, id) 
    values
        (?, ?, ?, ?, ?, ?, ?)
Hibernate: 
    insert 
    into
        PriceData
        (departureDate, foundDateTimeUtc, intPrice, returnDate, routeCabinFares_id, stringPrice, id) 
    values
        (?, ?, ?, ?, ?, ?, ?)
Hibernate: 
    insert 
    into
        PriceData
        (departureDate, foundDateTimeUtc, intPrice, returnDate, routeCabinFares_id, stringPrice, id) 
    values
        (?, ?, ?, ?, ?, ?, ?)
Hibernate: 
    insert 
    into
        PriceData
        (departureDate, foundDateTimeUtc, intPrice, returnDate, routeCabinFares_id, stringPrice, id) 
    values
        (?, ?, ?, ?, ?, ?, ?)
00:13:07.262 [34mINFO [0;39m [[36mbiz.ianw.lanchecker.Main[0;39m] - main() Commit complete, starting close...
00:13:07.269 [34mINFO [0;39m [[36mbiz.ianw.lanchecker.Main[0;39m] - main() Close complete
00:13:07.270 [34mINFO [0;39m [[36mbiz.ianw.lanchecker.Main[0;39m] - main() Existing fares in db: 10759; New fares added: 10; Collection add in 91 uSecs; Commit in 233 mSecs

Top

vlad

Post subject: Re: Slow commit times

Posted: Fri Jan 08, 2016 1:28 am

Hibernate Team

Joined: Thu Sep 11, 2014 2:50 am
Posts: 1628
Location: Romania

I use p6spy or datasource-proxy to visualize the batching outcome. You can also debug it and see if the batching is there or the Hibernate SQL output is misleading.
I see you use table generator which should allow JDBC batching.

Top

IanWorthington

Post subject: Re: Slow commit times

Posted: Mon Jan 11, 2016 12:38 am

Newbie

Joined: Tue Dec 29, 2015 8:38 am
Posts: 6

mihalcea_vlad wrote:

Thanks for that pointer, that was very useful.

Yes, the batching does seem to be taking place:

Code:

2016-01-10 23:18:29.531-0500 INFO  [biz.ianw.lanchecker.Main] - main() 0 fares already in db, adding 3582 new fares...
2016-01-10 23:18:29.533-0500 INFO  [biz.ianw.lanchecker.Main] - main() Starting commit...
2016-01-10 23:18:29.554-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:1, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["select next_val as id_val from hibernate_sequence for update"], Params:[()]
2016-01-10 23:18:29.557-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:2, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["update hibernate_sequence set next_val= ? where next_val=?"], Params:[(1=2,2=1)]
...
2016-01-10 23:18:57.202-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:0, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["select next_val as id_val from hibernate_sequence for update"], Params:[()]
2016-01-10 23:18:57.202-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:0, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["update hibernate_sequence set next_val= ? where next_val=?"], Params:[(1=3583,2=3582)]
2016-01-10 23:18:58.190-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:658, Success:True, Type:Prepared, Batch:True, QuerySize:1, [b]BatchSize:3582[/b], Query:["insert into PriceData (departureDate, foundDateTimeUtc, intPrice, returnDate, routeCabinFares_id, stringPrice, id) values (?, ?, ?, ?, ?, ?, ?)"], Params:[(1=[B@71df3f5b,2=[B@21b842cf,3=3565,4=[B@4555272a,5=1,6=US$3,565.30,7=1),(1=[B@6d80624,2=[B@ef5c443,3=3565,4=[B@6d385168,5=1,6=US$3,565.30,7=2),(1=[B@1384792,2=[B@471788b7,3=3565,4=[B@67609bca,5=1,6=US$3,565.30,7=3),(1=[B@487c355f,2=[B@bbbff15,3=3565,4=[B@70929ce5,5=1,6=US$3,565.30,7=4),...
2016-01-10 23:19:00.768-0500 INFO  [biz.ianw.lanchecker.Main] - main() Commit complete, starting close...
2016-01-10 23:19:00.776-0500 INFO  [biz.ianw.lanchecker.Main] - main() Close complete
2016-01-10 23:19:00.776-0500 INFO  [biz.ianw.lanchecker.Main] - main() Existing fares in db: 0; New fares added: 3582; Collection add in 1942 uSecs; Commit in 31233 mSecs

The timings are, presumably, greatly affected by the presence of the proxy, but they suggest that at least half of my commit time is being taken up by the select/update pairs to generate the id for the PriceData entries.

If I change to:

Code:

public class PriceData {
    @TableGenerator(
            name="pdGen", 
            allocationSize=1000)
    
    @Id 
    @GeneratedValue(strategy=GenerationType.TABLE, generator="pdGen")
    private Long id;

this seems to substantially reduce the commit time:

Code:

 
2016-01-11 01:16:37.971-0500 INFO  [biz.ianw.lanchecker.Main] - main() No matching RCF data in database, will be added
2016-01-11 01:16:37.993-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:0, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["select next_val as id_val from hibernate_sequence for update"], Params:[()]
2016-01-11 01:16:37.995-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:2, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["update hibernate_sequence set next_val= ? where next_val=?"], Params:[(1=2,2=1)]
2016-01-11 01:16:38.041-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:2, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["select tbl.next_val from hibernate_sequences tbl where tbl.sequence_name=? for update"], Params:[(1=PriceData)]
2016-01-11 01:16:38.042-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:1, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["insert into hibernate_sequences (sequence_name, next_val)  values (?,?)"], Params:[(1=PriceData,2=1)]
2016-01-11 01:16:38.043-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:1, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["update hibernate_sequences set next_val=?  where next_val=? and sequence_name=?"], Params:[(1=1001,2=1,3=PriceData)]
2016-01-11 01:16:38.049-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:1, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["select tbl.next_val from hibernate_sequences tbl where tbl.sequence_name=? for update"], Params:[(1=PriceData)]
2016-01-11 01:16:38.050-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:1, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["update hibernate_sequences set next_val=?  where next_val=? and sequence_name=?"], Params:[(1=2001,2=1001,3=PriceData)]
2016-01-11 01:16:38.233-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:0, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["select tbl.next_val from hibernate_sequences tbl where tbl.sequence_name=? for update"], Params:[(1=PriceData)]
2016-01-11 01:16:38.234-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:0, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["update hibernate_sequences set next_val=?  where next_val=? and sequence_name=?"], Params:[(1=3001,2=2001,3=PriceData)]
2016-01-11 01:16:38.317-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:0, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["select tbl.next_val from hibernate_sequences tbl where tbl.sequence_name=? for update"], Params:[(1=PriceData)]
2016-01-11 01:16:38.319-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:1, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["update hibernate_sequences set next_val=?  where next_val=? and sequence_name=?"], Params:[(1=4001,2=3001,3=PriceData)]
2016-01-11 01:16:38.401-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:0, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["select tbl.next_val from hibernate_sequences tbl where tbl.sequence_name=? for update"], Params:[(1=PriceData)]
2016-01-11 01:16:38.402-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:1, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["update hibernate_sequences set next_val=?  where next_val=? and sequence_name=?"], Params:[(1=5001,2=4001,3=PriceData)]
2016-01-11 01:16:38.440-0500 INFO  [biz.ianw.lanchecker.Main] - main() Starting commit...
2016-01-11 01:16:38.544-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:2, Success:True, Type:Prepared, Batch:True, QuerySize:1, BatchSize:1, Query:["insert into RouteCabinFares (cabin, destinationCity, originCity, paymentType, siteCountry, id) values (?, ?, ?, ?, ?, ?)"], Params:[(1=Premium Business,2=miami,3=lima,4=0,5=pe,6=1)]
2016-01-11 01:16:39.619-0500 INFO  [net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener] - Name:, Time:827, Success:True, Type:Prepared, Batch:True, QuerySize:1, BatchSize:3581, Query:["insert into PriceData (departureDate, foundDateTimeUtc, intPrice, returnDate, routeCabinFares_id, stringPrice, id) values (?, ?, ?, ?, ?, ?, ?)"], Params:[(1=[B@2691df5e,2=[B@748c63cc,3=8363,4=[B@11f11e95,5=1,6=US$8,362.98,7=1),(1=[B@2d123bb1,2=[B@5517a62,3=3565,4=[B@1254eb07,5=1,6=US$3,565.30,7=2),...,(1=[B@4aeb7ea5,2=[B@56b0059c,3=3530,4=[B@160ffb29,5=1,6=US$3,529.70,7=3580),(1=[B@7a44ad98,2=[B@6bcbea23,3=3530,4=[B@3d018e23,5=1,6=US$3,529.70,7=3581)]
2016-01-11 01:16:39.791-0500 INFO  [biz.ianw.lanchecker.Main] - main() Commit complete, starting close...

Top

vlad

Post subject: Re: Slow commit times

Posted: Mon Jan 11, 2016 5:36 am

Hibernate Team

Joined: Thu Sep 11, 2014 2:50 am
Posts: 1628
Location: Romania

The table generator has an overhead due to the SELECT FOR UPDATE locking semantics.
If you're using Oracle, PostgreSQL or SQL Server 2012, you can use a sequence.

If you're using MySQL, you can opt for IDENTITY, but then Hibernate will not be able to batch entities.
You might want to test to see if the IDENTITY generator still delivers better response times even if batching is disabled.

Top

IanWorthington

Post subject: Re: Slow commit times

Posted: Mon Jan 11, 2016 4:28 pm

Newbie

Joined: Tue Dec 29, 2015 8:38 am
Posts: 6

mihalcea_vlad wrote:

I've been running some tests overnight and it seems that using the table generator with an allocationSize=1000 (along with the batch size of 5000) has reduced the total commit time to around 1.2 ~1.3 seconds for 3600 items, ie around 350 uSecs per item. That seems a much more reasonable number, and is acceptable to me. I'm guess that we're probably entering the zone of diminishing returns from now on?

Many thanks for your help, much appreciated.

Ian

Top

Page 1 of 1

[ 10 posts ]

Board index » Hibernate & Java Persistence » Hibernate Users

All times are UTC - 5 hours [ DST ]

You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum