Reproducer for HHH-19211 #480
Open
Hibernate Jenkins CI / Jenkins
failed
May 26, 2025 in 37s
Test: error in 'sh' step
Test / Shell Script
Error in sh step, with arguments mvn -B verify.
script returned exit code 1
Build log
Build log truncated.
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
select
id
from
MainEntity
where
id=? for update
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
10278556 nanoseconds spent acquiring 1 JDBC connections;
527900 nanoseconds spent releasing 1 JDBC connections;
5649087 nanoseconds spent preparing 5 JDBC statements;
8124740 nanoseconds spent executing 5 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;
2596693 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
3662 nanoseconds spent executing 1 pre-partial-flushes;
2666 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
479787 nanoseconds spent acquiring 1 JDBC connections;
97605 nanoseconds spent releasing 1 JDBC connections;
1120208 nanoseconds spent preparing 5 JDBC statements;
15433520 nanoseconds spent executing 5 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;
6881123 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
7213 nanoseconds spent executing 1 pre-partial-flushes;
3953 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
select
id
from
MainEntity
where
id=? for update
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
22295686 nanoseconds spent acquiring 1 JDBC connections;
86804 nanoseconds spent releasing 1 JDBC connections;
4176526 nanoseconds spent preparing 5 JDBC statements;
97693770 nanoseconds spent executing 5 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;
6267947 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
10040 nanoseconds spent executing 1 pre-partial-flushes;
4297 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
select
id
from
MainEntity
where
id=? for update
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
1555744 nanoseconds spent acquiring 1 JDBC connections;
79205 nanoseconds spent releasing 1 JDBC connections;
1059174 nanoseconds spent preparing 5 JDBC statements;
19139718 nanoseconds spent executing 5 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;
6758672 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
8562 nanoseconds spent executing 1 pre-partial-flushes;
5383 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
6194360 nanoseconds spent acquiring 1 JDBC connections;
101551 nanoseconds spent releasing 1 JDBC connections;
3245886 nanoseconds spent preparing 5 JDBC statements;
8276450 nanoseconds spent executing 5 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;
4232915 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
7288 nanoseconds spent executing 1 pre-partial-flushes;
4302 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
select
id
from
MainEntity
where
id=? for update
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
17415710 nanoseconds spent acquiring 1 JDBC connections;
76111 nanoseconds spent releasing 1 JDBC connections;
11903545 nanoseconds spent preparing 5 JDBC statements;
122311893 nanoseconds spent executing 5 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;
5040254 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
189298 nanoseconds spent executing 1 pre-partial-flushes;
13297 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
select
id
from
MainEntity
where
id=? for update
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
Hibernate:
select
id
from
MainEntity
where
id=? for update
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
17908908 nanoseconds spent acquiring 1 JDBC connections;
84456 nanoseconds spent releasing 1 JDBC connections;
18073815 nanoseconds spent preparing 5 JDBC statements;
136911912 nanoseconds spent executing 5 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;
6289057 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
2691 nanoseconds spent executing 1 pre-partial-flushes;
4768 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
3564564 nanoseconds spent acquiring 1 JDBC connections;
70138 nanoseconds spent releasing 1 JDBC connections;
12514866 nanoseconds spent preparing 5 JDBC statements;
155088416 nanoseconds spent executing 5 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;
4246786 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
2339 nanoseconds spent executing 1 pre-partial-flushes;
4340 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
id
from
MainEntity
where
id=? for update
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
18361857 nanoseconds spent acquiring 1 JDBC connections;
89924 nanoseconds spent releasing 1 JDBC connections;
11198319 nanoseconds spent preparing 5 JDBC statements;
145176980 nanoseconds spent executing 5 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;
4233837 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
3342 nanoseconds spent executing 1 pre-partial-flushes;
4823 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
8728277 nanoseconds spent acquiring 1 JDBC connections;
107656 nanoseconds spent releasing 1 JDBC connections;
1038563 nanoseconds spent preparing 5 JDBC statements;
28838994 nanoseconds spent executing 5 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;
2114792 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
7415 nanoseconds spent executing 1 pre-partial-flushes;
3642 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
Hibernate:
select
id
from
MainEntity
where
id=? for update
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
1217955 nanoseconds spent acquiring 1 JDBC connections;
75032 nanoseconds spent releasing 1 JDBC connections;
16358354 nanoseconds spent preparing 5 JDBC statements;
158313322 nanoseconds spent executing 5 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;
6130613 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
4642 nanoseconds spent executing 1 pre-partial-flushes;
4112 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
743843 nanoseconds spent acquiring 1 JDBC connections;
112573 nanoseconds spent releasing 1 JDBC connections;
2221172 nanoseconds spent preparing 5 JDBC statements;
12798100 nanoseconds spent executing 5 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;
1848174 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
7008 nanoseconds spent executing 1 pre-partial-flushes;
3862 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
select
id
from
MainEntity
where
id=? for update
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
Hibernate:
select
id
from
MainEntity
where
id=? for update
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
6814472 nanoseconds spent acquiring 1 JDBC connections;
81463 nanoseconds spent releasing 1 JDBC connections;
12865909 nanoseconds spent preparing 5 JDBC statements;
175683324 nanoseconds spent executing 5 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;
4163718 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
2516 nanoseconds spent executing 1 pre-partial-flushes;
4127 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
9785528 nanoseconds spent acquiring 1 JDBC connections;
100083 nanoseconds spent releasing 1 JDBC connections;
1029431 nanoseconds spent preparing 5 JDBC statements;
141297550 nanoseconds spent executing 5 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;
4635472 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
7883 nanoseconds spent executing 1 pre-partial-flushes;
27677 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
1954728 nanoseconds spent acquiring 1 JDBC connections;
67670 nanoseconds spent releasing 1 JDBC connections;
11659041 nanoseconds spent preparing 5 JDBC statements;
191428815 nanoseconds spent executing 5 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;
3983745 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
8065 nanoseconds spent executing 1 pre-partial-flushes;
3076 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
5093524 nanoseconds spent acquiring 1 JDBC connections;
77841 nanoseconds spent releasing 1 JDBC connections;
1013351 nanoseconds spent preparing 5 JDBC statements;
53657639 nanoseconds spent executing 5 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;
2045227 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
7483 nanoseconds spent executing 1 pre-partial-flushes;
3699 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
Hibernate:
select
id
from
MainEntity
where
id=? for update
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
2843114 nanoseconds spent acquiring 1 JDBC connections;
70603 nanoseconds spent releasing 1 JDBC connections;
1082590 nanoseconds spent preparing 5 JDBC statements;
69489476 nanoseconds spent executing 5 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;
5354453 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
7140 nanoseconds spent executing 1 pre-partial-flushes;
4142 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
16400175 nanoseconds spent acquiring 1 JDBC connections;
64833 nanoseconds spent releasing 1 JDBC connections;
3927493 nanoseconds spent preparing 5 JDBC statements;
23643639 nanoseconds spent executing 5 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;
4724449 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
6526 nanoseconds spent executing 1 pre-partial-flushes;
5769 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
428374 nanoseconds spent acquiring 1 JDBC connections;
74578 nanoseconds spent releasing 1 JDBC connections;
1007229 nanoseconds spent preparing 5 JDBC statements;
10332479 nanoseconds spent executing 5 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;
4927908 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
6396 nanoseconds spent executing 1 pre-partial-flushes;
3929 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
id
from
MainEntity
where
id=? for update
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
18947424 nanoseconds spent acquiring 1 JDBC connections;
79685 nanoseconds spent releasing 1 JDBC connections;
3593799 nanoseconds spent preparing 5 JDBC statements;
49070089 nanoseconds spent executing 5 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;
4574912 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
6805 nanoseconds spent executing 1 pre-partial-flushes;
3855 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
861207 nanoseconds spent acquiring 1 JDBC connections;
88215 nanoseconds spent releasing 1 JDBC connections;
19496790 nanoseconds spent preparing 5 JDBC statements;
236191657 nanoseconds spent executing 5 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;
7381159 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
2705 nanoseconds spent executing 1 pre-partial-flushes;
3989 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
id
from
MainEntity
where
id=? for update
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
13378911 nanoseconds spent acquiring 1 JDBC connections;
78011 nanoseconds spent releasing 1 JDBC connections;
14487355 nanoseconds spent preparing 5 JDBC statements;
245035219 nanoseconds spent executing 5 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;
1923470 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
7274 nanoseconds spent executing 1 pre-partial-flushes;
4059 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
2558147 nanoseconds spent acquiring 1 JDBC connections;
67845 nanoseconds spent releasing 1 JDBC connections;
6687869 nanoseconds spent preparing 5 JDBC statements;
904478 nanoseconds spent executing 5 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;
2324793 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
6991 nanoseconds spent executing 1 pre-partial-flushes;
3678 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
Hibernate:
select
id
from
MainEntity
where
id=? for update
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
5121512 nanoseconds spent acquiring 1 JDBC connections;
74847 nanoseconds spent releasing 1 JDBC connections;
16187122 nanoseconds spent preparing 5 JDBC statements;
256696968 nanoseconds spent executing 5 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;
3308978 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
2569 nanoseconds spent executing 1 pre-partial-flushes;
5547 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
20239036 nanoseconds spent acquiring 1 JDBC connections;
85579 nanoseconds spent releasing 1 JDBC connections;
12723454 nanoseconds spent preparing 5 JDBC statements;
261933062 nanoseconds spent executing 5 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;
2513216 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
10481 nanoseconds spent executing 1 pre-partial-flushes;
3933 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
3388235 nanoseconds spent acquiring 1 JDBC connections;
72201 nanoseconds spent releasing 1 JDBC connections;
8275263 nanoseconds spent preparing 5 JDBC statements;
265130024 nanoseconds spent executing 5 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;
4665063 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
5779 nanoseconds spent executing 1 pre-partial-flushes;
3269 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
id
from
MainEntity
where
id=? for update
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
10832271 nanoseconds spent acquiring 1 JDBC connections;
76529 nanoseconds spent releasing 1 JDBC connections;
839988 nanoseconds spent preparing 5 JDBC statements;
13490517 nanoseconds spent executing 5 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;
6784749 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
6199 nanoseconds spent executing 1 pre-partial-flushes;
4327 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
14277358 nanoseconds spent acquiring 1 JDBC connections;
71764 nanoseconds spent releasing 1 JDBC connections;
13940798 nanoseconds spent preparing 5 JDBC statements;
280650738 nanoseconds spent executing 5 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;
2106668 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
6252 nanoseconds spent executing 1 pre-partial-flushes;
4364 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
Hibernate:
select
id
from
MainEntity
where
id=? for update
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
7364876 nanoseconds spent acquiring 1 JDBC connections;
60579 nanoseconds spent releasing 1 JDBC connections;
14559706 nanoseconds spent preparing 5 JDBC statements;
287097377 nanoseconds spent executing 5 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;
5182678 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
2612 nanoseconds spent executing 1 pre-partial-flushes;
3639 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
1723499 nanoseconds spent acquiring 1 JDBC connections;
62092 nanoseconds spent releasing 1 JDBC connections;
1001078 nanoseconds spent preparing 5 JDBC statements;
297176422 nanoseconds spent executing 5 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;
1942033 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
8537 nanoseconds spent executing 1 pre-partial-flushes;
5184 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
15850638 nanoseconds spent acquiring 1 JDBC connections;
59599 nanoseconds spent releasing 1 JDBC connections;
963555 nanoseconds spent preparing 5 JDBC statements;
67433428 nanoseconds spent executing 5 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;
1703039 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
6908 nanoseconds spent executing 1 pre-partial-flushes;
6276 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
select
id
from
MainEntity
where
id=? for update
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
2025-05-26 14:39:20 WARN DeferredResultSetAccess:111 - HHH000444: Encountered request for locking however dialect reports that database prefers locking be done in a separate select (follow-on locking); results will be locked after initial query executes
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
19553335 nanoseconds spent acquiring 1 JDBC connections;
68776 nanoseconds spent releasing 1 JDBC connections;
2002506 nanoseconds spent preparing 5 JDBC statements;
25479909 nanoseconds spent executing 5 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;
3441183 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
6743 nanoseconds spent executing 1 pre-partial-flushes;
4215 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
join
RelatedEntity re1_0
on me1_0.id=re1_0.main_id
where
me1_0.id=?
Hibernate:
select
id
from
MainEntity
where
id=? for update
Hibernate:
select
id
from
MainEntity
where
id=? for update
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
21249557 nanoseconds spent acquiring 1 JDBC connections;
79233 nanoseconds spent releasing 1 JDBC connections;
4572164 nanoseconds spent preparing 5 JDBC statements;
191061831 nanoseconds spent executing 5 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;
4972365 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
6928 nanoseconds spent executing 1 pre-partial-flushes;
3885 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
2025-05-26 14:39:20 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
6138438 nanoseconds spent acquiring 1 JDBC connections;
73503 nanoseconds spent releasing 1 JDBC connections;
906047 nanoseconds spent preparing 5 JDBC statements;
11578004 nanoseconds spent executing 5 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;
2688342 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
6808 nanoseconds spent executing 1 pre-partial-flushes;
3850 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
2025-05-26 14:39:21 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
20037531 nanoseconds spent acquiring 1 JDBC connections;
69387 nanoseconds spent releasing 1 JDBC connections;
912478 nanoseconds spent preparing 5 JDBC statements;
6593100 nanoseconds spent executing 5 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;
1658899 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
6850 nanoseconds spent executing 1 pre-partial-flushes;
3961 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
2025-05-26 14:39:21 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
11857809 nanoseconds spent acquiring 1 JDBC connections;
66631 nanoseconds spent releasing 1 JDBC connections;
854760 nanoseconds spent preparing 5 JDBC statements;
33777659 nanoseconds spent executing 5 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;
1713986 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
6287 nanoseconds spent executing 1 pre-partial-flushes;
3741 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
2025-05-26 14:39:21 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
395141 nanoseconds spent acquiring 1 JDBC connections;
94152 nanoseconds spent releasing 1 JDBC connections;
16167803 nanoseconds spent preparing 5 JDBC statements;
337156380 nanoseconds spent executing 5 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;
1816799 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
3185 nanoseconds spent executing 1 pre-partial-flushes;
6088 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
2025-05-26 14:39:21 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
5585252 nanoseconds spent acquiring 1 JDBC connections;
71994 nanoseconds spent releasing 1 JDBC connections;
12595130 nanoseconds spent preparing 5 JDBC statements;
335178929 nanoseconds spent executing 5 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;
2584969 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
2763 nanoseconds spent executing 1 pre-partial-flushes;
4332 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
re1_0.main_id,
re1_0.id,
re1_0.relatedCounter
from
RelatedEntity re1_0
where
re1_0.main_id=?
Hibernate:
update
MainEntity
set
mainCounter=?
where
id=?
Hibernate:
update
RelatedEntity
set
main_id=?,
relatedCounter=?
where
id=?
2025-05-26 14:39:21 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
1597179 nanoseconds spent acquiring 1 JDBC connections;
64310 nanoseconds spent releasing 1 JDBC connections;
831386 nanoseconds spent preparing 5 JDBC statements;
23149438 nanoseconds spent executing 5 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;
2313088 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
5641 nanoseconds spent executing 1 pre-partial-flushes;
3520 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
2025-05-26 14:39:21 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
17380828 nanoseconds spent acquiring 1 JDBC connections;
61966 nanoseconds spent releasing 1 JDBC connections;
938791 nanoseconds spent preparing 5 JDBC statements;
173482753 nanoseconds spent executing 5 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;
1673672 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 2 collections);
7551 nanoseconds spent executing 1 pre-partial-flushes;
4425 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}
Hibernate:
select
me1_0.id,
me1_0.mainCounter
from
MainEntity me1_0
where
me1_0.id=?
Hibernate:
drop table if exists MainEntity cascade
2025-05-26 14:39:21 INFO access:52 - HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess@75bf9e67] for (non-JTA) DDL execution was not in auto-commit mode; the Connection 'local transaction' will be committed and the Connection will be set into auto-commit mode.
Hibernate:
drop table if exists RelatedEntity cascade
Hibernate:
drop sequence if exists MainEntity_SEQ
Hibernate:
drop sequence if exists RelatedEntity_SEQ
2025-05-26 14:39:21 ERROR pooling:483 - Connection leak detected: there are 1 unclosed connections upon shutting down pool jdbc:h2:mem:db1;DB_CLOSE_DELAY=-1
2025-05-26 14:39:21 ERROR pooling:311 - Connection leak detected: there are 1 unclosed connections
[ERROR] Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 4.011 s <<< FAILURE! -- in org.hibernate.bugs.JPAUnitTestCase
[ERROR] org.hibernate.bugs.JPAUnitTestCase.hhh19211Test -- Time elapsed: 4.007 s <<< FAILURE!
org.opentest4j.AssertionFailedError: expected: <50> but was: <6>
at org.junit.jupiter.api.AssertionFailureBuilder.build(AssertionFailureBuilder.java:151)
at org.junit.jupiter.api.AssertionFailureBuilder.buildAndThrow(AssertionFailureBuilder.java:132)
at org.junit.jupiter.api.AssertEquals.failNotEqual(AssertEquals.java:197)
at org.junit.jupiter.api.AssertEquals.assertEquals(AssertEquals.java:150)
at org.junit.jupiter.api.AssertEquals.assertEquals(AssertEquals.java:145)
at org.junit.jupiter.api.Assertions.assertEquals(Assertions.java:531)
at org.hibernate.bugs.JPAUnitTestCase.hhh19211Test(JPAUnitTestCase.java:89)
at java.base/java.lang.reflect.Method.invoke(Method.java:569)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
[INFO] Running org.hibernate.bugs.ORMStandaloneTestCase
2025-05-26 14:39:21 WARN CachingRegionFactory:48 - org.hibernate.testing.cache.CachingRegionFactory should be only used for testing.
2025-05-26 14:39:21 INFO RegionFactoryInitiator:53 - HHH000025: Second-level cache region factory [org.hibernate.testing.cache.CachingRegionFactory]
2025-05-26 14:39:21 WARN pooling:86 - HHH10001002: Using built-in connection pool (not intended for production use)
2025-05-26 14:39:21 WARN deprecation:153 - HHH90000025: H2Dialect does not need to be specified explicitly using 'hibernate.dialect' (remove the property setting and it will be selected by default)
2025-05-26 14:39:21 INFO pooling:163 - HHH10001005: Database info:
Database JDBC URL [jdbc:h2:mem:db1;DB_CLOSE_DELAY=-1]
Database driver: org.h2.Driver
Database version: 2.3.232
Autocommit mode: false
Isolation level: undefined/unknown
Minimum pool size: 1
Maximum pool size: 5
2025-05-26 14:39:21 INFO JtaPlatformInitiator:56 - HHH000490: Using JTA platform [org.hibernate.engine.transaction.jta.platform.internal.WildFlyStandAloneJtaPlatform]
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.071 s -- in org.hibernate.bugs.ORMStandaloneTestCase
[INFO] Running org.hibernate.bugs.ORMUnitTestCase
2025-05-26 14:39:21 WARN CachingRegionFactory:48 - org.hibernate.testing.cache.CachingRegionFactory should be only used for testing.
2025-05-26 14:39:21 INFO RegionFactoryInitiator:53 - HHH000025: Second-level cache region factory [org.hibernate.testing.cache.CachingRegionFactory]
2025-05-26 14:39:21 WARN deprecation:153 - HHH90000025: H2Dialect does not need to be specified explicitly using 'hibernate.dialect' (remove the property setting and it will be selected by default)
2025-05-26 14:39:21 INFO pooling:163 - HHH10001005: Database info:
Database JDBC URL [jdbc:h2:mem:db1;DB_CLOSE_DELAY=-1]
Database driver: org.h2.Driver
Database version: 2.3.232
Autocommit mode: false
Isolation level: undefined/unknown
Minimum pool size: 1
Maximum pool size: 5
2025-05-26 14:39:21 INFO JtaPlatformInitiator:56 - HHH000490: Using JTA platform [org.hibernate.engine.transaction.jta.platform.internal.WildFlyStandAloneJtaPlatform]
2025-05-26 14:39:21 INFO StatisticalLoggingSessionEventListener:280 - Session Metrics {
0 nanoseconds spent acquiring 0 JDBC connections;
0 nanoseconds spent releasing 0 JDBC connections;
0 nanoseconds spent preparing 0 JDBC statements;
0 nanoseconds spent executing 0 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;
0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
0 nanoseconds spent executing 0 pre-partial-flushes;
0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
}
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.046 s -- in org.hibernate.bugs.ORMUnitTestCase
[INFO]
[INFO] Results:
[INFO]
[ERROR] Failures:
[ERROR] JPAUnitTestCase.hhh19211Test:89 expected: <50> but was: <6>
[INFO]
[ERROR] Tests run: 4, Failures: 1, Errors: 0, Skipped: 0
[INFO]
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary:
[INFO]
[INFO] Hibernate ORM 5 Test Case Template 1.0.0.Final ..... SUCCESS [ 4.238 s]
[INFO] Hibernate ORM 6 Test Case Template 1.0.0.Final ..... FAILURE [ 6.711 s]
[INFO] Hibernate Envers 5 Test Case Template 1.0.0.Final .. SKIPPED
[INFO] Hibernate Envers 6 Test Case Template 1.0.0.Final .. SKIPPED
[INFO] Hibernate Search 5 with Elasticsearch 5 Test Case Template 1.0.0.Final SKIPPED
[INFO] Hibernate Search 5 with Lucene Test Case Template 1.0.0.Final SKIPPED
[INFO] Hibernate Search 6 with Hibernate ORM and Elasticsearch Test Case Template 1.0.0.Final SKIPPED
[INFO] Hibernate Search 6 with Hibernate ORM and Lucene Test Case Template 1.0.0.Final SKIPPED
[INFO] Hibernate Search 7 with Hibernate ORM and Elasticsearch Test Case Template 1.0.0.Final SKIPPED
[INFO] Hibernate Search 7 with Hibernate ORM and Lucene Test Case Template 1.0.0.Final SKIPPED
[INFO] Hibernate Validator 6 Test Case Template 1.0.0.Final SKIPPED
[INFO] Hibernate Validator 8 Test Case Template 1.0.0.Final SKIPPED
[INFO] Hibernate Validator 9 Test Case Template 1.0.0.Final SKIPPED
[INFO] Hibernate Reactive 2 Test Case Template 1.0.0.Final SKIPPED
[INFO] Hibernate Test Case Templates - Aggregator POM 1.0-SNAPSHOT SKIPPED
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 11.125 s
[INFO] Finished at: 2025-05-26T14:39:21Z
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:3.2.5:test (default-test) on project test-case-template-hibernate-orm-6: There are test failures.
[ERROR]
[ERROR] Please refer to /mnt/workdir/jenkins/workspace/rnate-test-case-templates_PR-480/orm/hibernate-orm-6/target/surefire-reports for the individual test results.
[ERROR] Please refer to dump files (if any exist) [date].dump, [date]-jvmRun[N].dump and [date].dumpstream.
[ERROR] -> [Help 1]
[ERROR]
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR]
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoFailureException
[ERROR]
[ERROR] After correcting the problems, you can resume the build with the command
[ERROR] mvn <args> -rf :test-case-template-hibernate-orm-6
Details
- Declarative: Checkout SCM (7.4 sec)
- Declarative: Tool Install (1.3 sec)
- Build (16 sec)
- Test (13 sec)
Error: script returned exit code 1
- Declarative: Tool Install (1.3 sec)
Loading