2013-07-17 10:59:17,667 DEBUG [org.hibernate.search.indexes.impl.SharingBufferReaderProvider]: Opening IndexReader for directoryProvider com.setech.dw.inventory.domain.Item
2013-07-17 10:59:17,933 DEBUG [org.hibernate.search.reader.impl.MultiReaderFactory]: Closing MultiReader: CacheableMultiReader(ReadOnlyDirectoryReader(segments_2ef _2oj(3.6.2):C274802/2 _2ow(3.6.2):c1 _2ox(3.6.2):c1))
2013-07-17 10:59:17,934 DEBUG [org.hibernate.search.indexes.impl.SharingBufferReaderProvider]: Closing IndexReader: ReadOnlyDirectoryReader(segments_2ef _2oj(3.6.2):C274802/2 _2ow(3.6.2):c1 _2ox(3.6.2):c1)
2013-07-17 10:59:17,938 DEBUG [org.hibernate.SQL]: select <left out for brevity>
2013-07-17 10:59:17,968 DEBUG [org.hibernate.loader.Loader]: Result set row: 0
2013-07-17 10:59:17,968 DEBUG [org.hibernate.loader.Loader]: Result row: null, EntityKeycom.setech.dw.common.domain.Plant#6, EntityKeycom.setech.dw.common.domain.Customer#4, EntityKey[com.setech.dw.inventory.domain.Item#component[itemId,plantId]
Unknown macro: {plantId=6, itemId=48}
]
... multitudes of the above for each row
2013-07-17 10:59:18,029 DEBUG [org.hibernate.loader.Loader]: Result set row: 118
2013-07-17 10:59:18,029 DEBUG [org.hibernate.loader.Loader]: Result row: null, EntityKeycom.setech.dw.common.domain.Plant#6, EntityKeycom.setech.dw.common.domain.Customer#4, EntityKey[com.setech.dw.inventory.domain.Item#component[itemId,plantId]
Unknown macro: {plantId=6, itemId=1062}
]
2013-07-17 10:59:18,029 DEBUG [org.hibernate.loader.Loader]: Result set row: 119
2013-07-17 10:59:24,287 DEBUG [org.hibernate.loader.Loader]: Result row: null, EntityKeycom.setech.dw.common.domain.Plant#6, EntityKeycom.setech.dw.common.domain.Customer#4, EntityKey[com.setech.dw.inventory.domain.Item#component[itemId,plantId]
Unknown macro: {plantId=6, itemId=1063}
]
2013-07-17 10:59:24,288 DEBUG [org.hibernate.loader.Loader]: Result set row: 120
2013-07-17 10:59:24,288 DEBUG [org.hibernate.loader.Loader]: Result row: null, EntityKeycom.setech.dw.common.domain.Plant#6, EntityKeycom.setech.dw.common.domain.Customer#4, EntityKey[com.setech.dw.inventory.domain.Item#component[itemId,plantId]
Unknown macro: {plantId=6, itemId=1064}
]
2013-07-17 10:59:24,289 DEBUG [org.hibernate.loader.Loader]: Result set row: 121
... even more
2013-07-17 10:59:24,327 DEBUG [org.hibernate.engine.internal.TwoPhaseLoad]: Resolving associations for com.setech.dw.common.domain.Plant#6
2013-07-17 10:59:24,327 DEBUG [org.hibernate.engine.internal.TwoPhaseLoad]: Done materializing entity com.setech.dw.common.domain.Plant#6
2013-07-17 10:59:24,327 DEBUG [org.hibernate.engine.internal.TwoPhaseLoad]: Resolving associations for com.setech.dw.common.domain.Customer#4
2013-07-17 10:59:24,327 DEBUG [org.hibernate.engine.internal.TwoPhaseLoad]: Done materializing entity com.setech.dw.common.domain.Customer#4
2013-07-17 10:59:24,328 DEBUG [org.hibernate.engine.internal.TwoPhaseLoad]: Resolving associations for [com.setech.dw.inventory.domain.Item#component[itemId,plantId]
]
... more
2013-07-17 10:59:24,454 DEBUG [org.hibernate.engine.internal.TwoPhaseLoad]: Done materializing entity [com.setech.dw.inventory.domain.Item#component[itemId,plantId]
Unknown macro: {plantId=7, itemId=1349}
]
2013-07-17 10:59:24,457 DEBUG [org.hibernate.stat.internal.ConcurrentStatisticsImpl]: HHH000117: HQL: null, time: 6519ms, rows: 250
The biggest bulk of the time appears to be when the hibernate loader attempts to load row 120 of the result and there is a delay of nearly 6+ seconds.
