Недавно мы переместили наше программное обеспечение с Hibernate 3 на Hibernate 5. При выполнении длительной операции файл журнала базы данных SQL Server 2014 быстро растет, пока не заканчивается свободное место на диске. Процесс читает 3200 записей из базы данных за одну операцию, а затем перебирает эти записи и читает другую запись, эти два набора записей затем используются для создания двух новых записей - таким образом, 6400 записей. Эта операция с версией, использующей Hibernate 3, не влияет на размер файла журнала на всех , но с использованием Hibernate 5 (с использованием той же виртуальной машины для их запуска). В старой версии эта операция обычно занимает около 5 минут. В новой версии это занимает около 15, а затем терпит неудачу.
Это небольшое подмножество журнала для Hibernate 3: -
02-Jul-2018 15:51:52,756 DEBUG - SQL - select this_.ID as ID33_0_, this_.Content as Content33_0_ from tbl_edoc_content this_ where this_.ID=?
02-Jul-2018 15:51:52,756 DEBUG - AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
02-Jul-2018 15:51:52,756 DEBUG - Loader - result row: EntityKey[uk.co.stasys.edoc.sectioning.Content#1]
02-Jul-2018 15:51:52,756 DEBUG - AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
02-Jul-2018 15:51:52,756 DEBUG - AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
02-Jul-2018 15:51:52,756 DEBUG - TwoPhaseLoad - resolving associations for [uk.co.stasys.edoc.sectioning.Content#1]
02-Jul-2018 15:51:52,756 DEBUG - TwoPhaseLoad - done materializing entity [uk.co.stasys.edoc.sectioning.Content#1]
02-Jul-2018 15:51:52,756 DEBUG - StatefulPersistenceContext - initializing non-lazy collections
02-Jul-2018 15:51:52,788 DEBUG - AbstractSaveEventListener - executing identity-insert immediately
02-Jul-2018 15:51:52,788 DEBUG - AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
02-Jul-2018 15:51:52,788 DEBUG - SQL - insert into tbl_edoc_content (Content) values (?)
02-Jul-2018 15:51:52,788 DEBUG - IdentifierGeneratorHelper - Natively generated identity: 29
02-Jul-2018 15:51:52,788 DEBUG - AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
02-Jul-2018 15:51:52,788 DEBUG - AbstractSaveEventListener - executing identity-insert immediately
02-Jul-2018 15:51:52,788 DEBUG - AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
02-Jul-2018 15:51:52,788 DEBUG - SQL - insert into tbl_edoc_section (DocumentID, Type, Depth, SectionNumber, Title, NextID, PreviousID, ContentID, Tag, unnumbered, indentDepth, BulletStyle, classification, userNumbered) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
02-Jul-2018 15:51:52,788 DEBUG - IdentifierGeneratorHelper - Natively generated identity: 26
02-Jul-2018 15:51:52,788 DEBUG - AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
02-Jul-2018 15:51:52,803 DEBUG - AbstractFlushingEventListener - processing flush-time cascades
02-Jul-2018 15:51:52,803 DEBUG - AbstractFlushingEventListener - dirty checking collections
02-Jul-2018 15:51:52,803 DEBUG - AbstractFlushingEventListener - Flushed: 0 insertions, 1 updates, 0 deletions to 20 objects
02-Jul-2018 15:51:52,803 DEBUG - AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
02-Jul-2018 15:51:52,803 DEBUG - Printer - listing entities:
Это то же подмножество журнала для Hibernate 5: -
02-Jul-2018 18:31:20,021 DEBUG - SQL - select content0_.ID as ID1_92_, content0_.Content as Content2_92_ from tbl_edoc_content content0_ where content0_.ID=1
02-Jul-2018 18:31:20,021 DEBUG - Loader - Result set row: 0
02-Jul-2018 18:31:20,021 DEBUG - Loader - Result row: EntityKey[uk.co.stasys.edoc.sectioning.Content#1]
02-Jul-2018 18:31:20,021 DEBUG - TwoPhaseLoad - Resolving associations for [uk.co.stasys.edoc.sectioning.Content#1]
02-Jul-2018 18:31:20,021 DEBUG - TwoPhaseLoad - Done materializing entity [uk.co.stasys.edoc.sectioning.Content#1]
02-Jul-2018 18:31:20,021 DEBUG - ActionQueue - Executing identity-insert immediately
02-Jul-2018 18:31:20,021 DEBUG - SQL - insert into tbl_edoc_content (Content) values (?)
02-Jul-2018 18:31:20,037 DEBUG - IdentifierGeneratorHelper - Natively generated identity: 29
02-Jul-2018 18:31:20,037 DEBUG - ResourceRegistryStandardImpl - HHH000387: ResultSet's statement was not registered
02-Jul-2018 18:31:20,037 DEBUG - ActionQueue - Executing identity-insert immediately
02-Jul-2018 18:31:20,037 DEBUG - SQL - insert into tbl_edoc_section (DocumentID, Type, Depth, SectionNumber, Title, NextID, PreviousID, ContentID, Tag, unnumbered, indentDepth, BulletStyle, classification, userNumbered) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
02-Jul-2018 18:31:20,053 DEBUG - IdentifierGeneratorHelper - Natively generated identity: 26
02-Jul-2018 18:31:20,053 DEBUG - ResourceRegistryStandardImpl - HHH000387: ResultSet's statement was not registered
02-Jul-2018 18:31:20,053 DEBUG - CriteriaQueryImpl - Rendered criteria query -> select generatedAlias0 from Note as generatedAlias0 where ( generatedAlias0.documentId=3 ) and ( generatedAlias0.sectionId=1 ) order by generatedAlias0.position asc
02-Jul-2018 18:31:20,053 DEBUG - QueryTranslatorImpl - parse() - HQL: select generatedAlias0 from uk.co.stasys.edoc.comm.notes.Note as generatedAlias0 where ( generatedAlias0.documentId=3 ) and ( generatedAlias0.sectionId=1 ) order by generatedAlias0.position asc
02-Jul-2018 18:31:20,053 DEBUG - ErrorCounter - throwQueryException() : no errors
02-Jul-2018 18:31:20,053 DEBUG - QueryTranslatorImpl - --- HQL AST ---
\-[QUERY] Node: 'query'
+-[SELECT_FROM] Node: 'SELECT_FROM'
| +-[FROM] Node: 'from'
| | \-[RANGE] Node: 'RANGE'
| | +-[DOT] Node: '.'
| | | +-[DOT] Node: '.'
| | | | +-[DOT] Node: '.'
| | | | | +-[DOT] Node: '.'
| | | | | | +-[DOT] Node: '.'
| | | | | | | +-[DOT] Node: '.'
| | | | | | | | +-[IDENT] Node: 'uk'
| | | | | | | | \-[IDENT] Node: 'co'
| | | | | | | \-[IDENT] Node: 'stasys'
| | | | | | \-[IDENT] Node: 'edoc'
| | | | | \-[IDENT] Node: 'comm'
| | | | \-[IDENT] Node: 'notes'
| | | \-[IDENT] Node: 'Note'
| | \-[ALIAS] Node: 'generatedAlias0'
| \-[SELECT] Node: 'select'
| \-[IDENT] Node: 'generatedAlias0'
+-[WHERE] Node: 'where'
| \-[AND] Node: 'and'
| +-[EQ] Node: '='
| | +-[DOT] Node: '.'
| | | +-[IDENT] Node: 'generatedAlias0'
| | | \-[IDENT] Node: 'documentId'
| | \-[NUM_INT] Node: '3'
| \-[EQ] Node: '='
| +-[DOT] Node: '.'
| | +-[IDENT] Node: 'generatedAlias0'
| | \-[IDENT] Node: 'sectionId'
| \-[NUM_INT] Node: '1'
\-[ORDER] Node: 'order'
+-[DOT] Node: '.'
| +-[IDENT] Node: 'generatedAlias0'
| \-[IDENT] Node: 'position'
\-[ASCENDING] Node: 'asc'
02-Jul-2018 18:31:20,053 DEBUG - HqlSqlBaseWalker - select << begin [level=1, statement=select]
02-Jul-2018 18:31:20,053 DEBUG - FromElement - FromClause{level=1} : uk.co.stasys.edoc.comm.notes.Note (generatedAlias0) -> note0_
02-Jul-2018 18:31:20,053 DEBUG - FromReferenceNode - Resolved : generatedAlias0 -> note0_.NoteId
02-Jul-2018 18:31:20,053 DEBUG - FromReferenceNode - Resolved : generatedAlias0 -> note0_.NoteId
02-Jul-2018 18:31:20,053 DEBUG - DotNode - getDataType() : documentId -> org.hibernate.type.IntegerType@27cf3151
02-Jul-2018 18:31:20,053 DEBUG - FromReferenceNode - Resolved : generatedAlias0.documentId -> note0_.DocumentId
02-Jul-2018 18:31:20,053 DEBUG - FromReferenceNode - Resolved : generatedAlias0 -> note0_.NoteId
02-Jul-2018 18:31:20,053 DEBUG - DotNode - getDataType() : sectionId -> org.hibernate.type.IntegerType@27cf3151
02-Jul-2018 18:31:20,053 DEBUG - FromReferenceNode - Resolved : generatedAlias0.sectionId -> note0_.SectionId
02-Jul-2018 18:31:20,053 DEBUG - FromReferenceNode - Resolved : generatedAlias0 -> note0_.NoteId
02-Jul-2018 18:31:20,053 DEBUG - DotNode - getDataType() : position -> org.hibernate.type.IntegerType@27cf3151
02-Jul-2018 18:31:20,053 DEBUG - FromReferenceNode - Resolved : generatedAlias0.position -> note0_.Pos
02-Jul-2018 18:31:20,053 DEBUG - HqlSqlBaseWalker - select : finishing up [level=1, statement=select]
02-Jul-2018 18:31:20,053 DEBUG - HqlSqlWalker - processQuery() : ( SELECT ( {select clause} note0_.NoteId ) ( FromClause{level=1} tbl_edoc_notes note0_ ) ( where ( and ( = ( note0_.DocumentId note0_.NoteId documentId ) 3 ) ( = ( note0_.SectionId note0_.NoteId sectionId ) 1 ) ) ) ( order ( note0_.Pos note0_.NoteId position ) asc ) )
02-Jul-2018 18:31:20,053 DEBUG - JoinProcessor - Using FROM fragment [tbl_edoc_notes note0_]
02-Jul-2018 18:31:20,053 DEBUG - HqlSqlBaseWalker - select >> end [level=1, statement=select]
02-Jul-2018 18:31:20,053 DEBUG - QueryTranslatorImpl - --- SQL AST ---
\-[SELECT] QueryNode: 'SELECT' querySpaces (tbl_edoc_notes)
+-[SELECT_CLAUSE] SelectClause: '{select clause}'
| +-[ALIAS_REF] IdentNode: 'note0_.NoteId as NoteId1_110_' {alias=generatedAlias0, className=uk.co.stasys.edoc.comm.notes.Note, tableAlias=note0_}
| \-[SQL_TOKEN] SqlFragment: 'note0_.Version as Version2_110_, note0_.DocumentId as Document3_110_, note0_.SectionId as SectionI4_110_, note0_.Pos as Pos5_110_, note0_.Deleted as Deleted6_110_, note0_.Content as Content7_110_'
+-[FROM] FromClause: 'from' FromClause{level=1, fromElementCounter=1, fromElements=1, fromElementByClassAlias=[generatedAlias0], fromElementByTableAlias=[note0_], fromElementsByPath=[], collectionJoinFromElementsByPath=[], impliedElements=[]}
| \-[FROM_FRAGMENT] FromElement: 'tbl_edoc_notes note0_' FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=generatedAlias0,role=null,tableName=tbl_edoc_notes,tableAlias=note0_,origin=null,columns={,className=uk.co.stasys.edoc.comm.notes.Note}}
+-[WHERE] SqlNode: 'where'
| \-[AND] SqlNode: 'and'
| +-[EQ] BinaryLogicOperatorNode: '='
| | +-[DOT] DotNode: 'note0_.DocumentId' {propertyName=documentId,dereferenceType=PRIMITIVE,getPropertyPath=documentId,path=generatedAlias0.documentId,tableAlias=note0_,className=uk.co.stasys.edoc.comm.notes.Note,classAlias=generatedAlias0}
| | | +-[ALIAS_REF] IdentNode: 'note0_.NoteId' {alias=generatedAlias0, className=uk.co.stasys.edoc.comm.notes.Note, tableAlias=note0_}
| | | \-[IDENT] IdentNode: 'documentId' {originalText=documentId}
| | \-[NUM_INT] LiteralNode: '3'
| \-[EQ] BinaryLogicOperatorNode: '='
| +-[DOT] DotNode: 'note0_.SectionId' {propertyName=sectionId,dereferenceType=PRIMITIVE,getPropertyPath=sectionId,path=generatedAlias0.sectionId,tableAlias=note0_,className=uk.co.stasys.edoc.comm.notes.Note,classAlias=generatedAlias0}
| | +-[ALIAS_REF] IdentNode: 'note0_.NoteId' {alias=generatedAlias0, className=uk.co.stasys.edoc.comm.notes.Note, tableAlias=note0_}
| | \-[IDENT] IdentNode: 'sectionId' {originalText=sectionId}
| \-[NUM_INT] LiteralNode: '1'
\-[ORDER] OrderByClause: 'order'
+-[DOT] DotNode: 'note0_.Pos' {propertyName=position,dereferenceType=PRIMITIVE,getPropertyPath=position,path=generatedAlias0.position,tableAlias=note0_,className=uk.co.stasys.edoc.comm.notes.Note,classAlias=generatedAlias0}
| +-[ALIAS_REF] IdentNode: 'note0_.NoteId' {alias=generatedAlias0, className=uk.co.stasys.edoc.comm.notes.Note, tableAlias=note0_}
| \-[IDENT] IdentNode: 'position' {originalText=position}
\-[ASCENDING] SqlNode: 'asc'
02-Jul-2018 18:31:20,053 DEBUG - ErrorCounter - throwQueryException() : no errors
02-Jul-2018 18:31:20,053 DEBUG - QueryTranslatorImpl - HQL: select generatedAlias0 from uk.co.stasys.edoc.comm.notes.Note as generatedAlias0 where ( generatedAlias0.documentId=3 ) and ( generatedAlias0.sectionId=1 ) order by generatedAlias0.position asc
02-Jul-2018 18:31:20,053 DEBUG - QueryTranslatorImpl - SQL: select note0_.NoteId as NoteId1_110_, note0_.Version as Version2_110_, note0_.DocumentId as Document3_110_, note0_.SectionId as SectionI4_110_, note0_.Pos as Pos5_110_, note0_.Deleted as Deleted6_110_, note0_.Content as Content7_110_ from tbl_edoc_notes note0_ where note0_.DocumentId=3 and note0_.SectionId=1 order by note0_.Pos asc
02-Jul-2018 18:31:20,053 DEBUG - ErrorCounter - throwQueryException() : no errors
02-Jul-2018 18:31:20,053 DEBUG - AbstractFlushingEventListener - Processing flush-time cascades
02-Jul-2018 18:31:20,053 DEBUG - AbstractFlushingEventListener - Dirty checking collections
02-Jul-2018 18:31:20,053 DEBUG - AbstractFlushingEventListener - Flushed: 0 insertions, 3 updates, 0 deletions to 20 objects
02-Jul-2018 18:31:20,053 DEBUG - AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
02-Jul-2018 18:31:20,053 DEBUG - EntityPrinter - Listing entities:
Я не знаю, какие различия мне нужно искать.