Dear All,
We are experiencing a performance issue with DSpace 6.2. Some of our
collections will time out/take several minutes to load. They are not big
collections, one of them only have 20 items, but each item contains 100+
bitstreams (one PDF in Original bundle and 100+ of JP2 files in customized
MASTER bundle which are hidden from end users). The postgresql left so many
"idle in transaction" processes that will slow down the overall site. The
tomcat begin to take most of the CPU time too.
We used to use 16G of memory for tomcat under v5.x, and the performance has
been ok. Now, even I increased to 64G(half of our server memory) under 6.2,
the performance didn't improve.
We are using Tomcat 8.0.13, Java 1.8, Redhat Linux 6.7, and XMLUI. We have
about 80+ communities, 280+ collections, 60,000+ items and 490,000
bitstreams.
To determine the cause of the slowness, I duplicate the same collection
with two copies. In one collection, I removed all MASTER files and leave
PDF only. The other collection, I zipped all MASTER files as one zip file
and uploaded with PDF. It turns out they all have no performance issues.
Seems like the number of bitstreams will affect the performance.
After turning on the debugging, I got following information. It is too big
to upload the whole log so I just put hibernate stat here.
======
The collection has 100+ bitstreams in it
======
2018-02-07 00:43:17,724 DEBUG
org.hibernate.stat.internal.ConcurrentStatisticsImpl @ HHH000117: HQL:
null, time: 1ms, rows: 1
2018-02-07 00:43:17,882 INFO
org.hibernate.engine.internal.StatisticalLoggingSessionEventListener
@ Session Metrics {
237746 nanoseconds spent acquiring 1 JDBC connections;
0 nanoseconds spent releasing 0 JDBC connections;
552698751 nanoseconds spent preparing 48017 JDBC statements;
12590561333 nanoseconds spent executing 48017 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
929992 nanoseconds spent performing 52 L2C puts;
188492 nanoseconds spent performing 10 L2C hits;
1935100 nanoseconds spent performing 42 L2C misses;
133422494 nanoseconds spent executing 2 flushes (flushing a total of
43868 entities and 58348 collections);
562373235433 nanoseconds spent executing 20136 partial-flushes
(flushing a total of 235915143 entities and 235915143 collections)
}
2018-02-07 00:43:17,884 INFO
org.hibernate.engine.internal.StatisticalLoggingSessionEventListener
@ 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 partial-flushes (flushing a total of 0
entities and 0 collections)
}
=====
The collection has PDF only
=====
2018-02-17 20:30:27,534 INFO
org.hibernate.engine.internal.StatisticalLoggingSessionEventListener
@ Session Metrics {
341778 nanoseconds spent acquiring 1 JDBC connections;
0 nanoseconds spent releasing 0 JDBC connections;
15974134 nanoseconds spent preparing 1189 JDBC statements;
271327429 nanoseconds spent executing 1189 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
717412 nanoseconds spent performing 45 L2C puts;
3906724 nanoseconds spent performing 247 L2C hits;
2081066 nanoseconds spent performing 855 L2C misses;
6829028 nanoseconds spent executing 2 flushes (flushing a total of 3916
entities and 5072 collections);
578786157 nanoseconds spent executing 261 partial-flushes (flushing a
total of 345641 entities and 345641 collections)
}
2018-02-17 20:30:27,535 DEBUG org.hibernate.SQL @
/* load org.dspace.eperson.EPerson */ select
eperson0_.uuid as uuid1_12_0_,
eperson0_.can_log_in as can_log_1_13_0_,
eperson0_.digest_algorithm as digest_a2_13_0_,
eperson0_.email as email3_13_0_,
eperson0_.last_active as last_act4_13_0_,
eperson0_.eperson_id as eperson_5_13_0_,
eperson0_.netid as netid6_13_0_,
eperson0_.password as password7_13_0_,
eperson0_.require_certificate as require_8_13_0_,
eperson0_.salt as salt9_13_0_,
eperson0_.self_registered as self_re10_13_0_
from
public.eperson eperson0_
inner join
public.dspaceobject eperson0_1_
on eperson0_.uuid=eperson0_1_.uuid
where
eperson0_.uuid=?
2018-02-17 20:30:27,535 TRACE org.hibernate.type.descriptor.sql.BasicBinder
@ binding parameter [1] as [OTHER] - b9f6c429-3567-4800-b55c-940deb3d8fce
2018-02-17 20:30:27,536 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found [true] as column
[can_log_1_13_0_]
2018-02-17 20:30:27,536 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found [SHA-512] as
column [digest_a2_13_0_]
2018-02-17 20:30:27,536 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found
[[email protected]] as column [email3_13_0_]
2018-02-17 20:30:27,536 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found [2018-02-17
19:07:13.416] as column [last_act4_13_0_]
2018-02-17 20:30:27,536 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found [405] as column
[eperson_5_13_0_]
2018-02-17 20:30:27,536 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found [yj4] as column
[netid6_13_0_]
2018-02-17 20:30:27,536 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found
[a556eeb9a5ea7541612573acf443367031ee943ecd1298c1739798ec88f75642c9bae7ebde0a44101a4a184d511c40ce5112955b74ded00b93108df01941271f]
as column [password7_13_0_]
2018-02-17 20:30:27,536 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found [false] as column
[require_8_13_0_]
2018-02-17 20:30:27,536 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found
[7fbf53e68087a11fff06c2600bbedab1] as column [salt9_13_0_]
2018-02-17 20:30:27,536 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found [true] as column
[self_re10_13_0_]
2018-02-17 20:30:27,536 TRACE org.hibernate.type.CollectionType @ Created
collection wrapper:
[org.dspace.content.DSpaceObject.handles#b9f6c429-3567-4800-b55c-940deb3d8fce]
2018-02-17 20:30:27,536 TRACE org.hibernate.type.CollectionType @ Created
collection wrapper:
[org.dspace.content.DSpaceObject.metadata#b9f6c429-3567-4800-b55c-940deb3d8fce]
2018-02-17 20:30:27,536 TRACE org.hibernate.type.CollectionType @ Created
collection wrapper:
[org.dspace.content.DSpaceObject.resourcePolicies#b9f6c429-3567-4800-b55c-940deb3d8fce]
2018-02-17 20:30:27,536 TRACE org.hibernate.type.CollectionType @ Created
collection wrapper:
[org.dspace.eperson.EPerson.groups#b9f6c429-3567-4800-b55c-940deb3d8fce]
2018-02-17 20:30:27,536 INFO
org.hibernate.engine.internal.StatisticalLoggingSessionEventListener
@ Session Metrics {
120941 nanoseconds spent acquiring 1 JDBC connections;
0 nanoseconds spent releasing 0 JDBC connections;
19210 nanoseconds spent preparing 1 JDBC statements;
190340 nanoseconds spent executing 1 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 partial-flushes (flushing a total of 0
entities and 0 collections)
=====
The collection has PDF and ZIPPED MASTER
=====
2018-02-17 20:31:25,062 INFO
org.hibernate.engine.internal.StatisticalLoggingSessionEventListener
@ Session Metrics {
168784 nanoseconds spent acquiring 1 JDBC connections;
0 nanoseconds spent releasing 0 JDBC connections;
12220421 nanoseconds spent preparing 1276 JDBC statements;
282597546 nanoseconds spent executing 1276 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
237448 nanoseconds spent performing 32 L2C puts;
4220734 nanoseconds spent performing 300 L2C hits;
2013993 nanoseconds spent performing 1008 L2C misses;
7370699 nanoseconds spent executing 2 flushes (flushing a total of 4078
entities and 5434 collections);
708646098 nanoseconds spent executing 301 partial-flushes (flushing a
total of 419170 entities and 419170 collections)
}
2018-02-17 20:31:25,063 DEBUG org.hibernate.SQL @
/* load org.dspace.eperson.EPerson */ select
eperson0_.uuid as uuid1_12_0_,
eperson0_.can_log_in as can_log_1_13_0_,
eperson0_.digest_algorithm as digest_a2_13_0_,
eperson0_.email as email3_13_0_,
eperson0_.last_active as last_act4_13_0_,
eperson0_.eperson_id as eperson_5_13_0_,
eperson0_.netid as netid6_13_0_,
eperson0_.password as password7_13_0_,
eperson0_.require_certificate as require_8_13_0_,
eperson0_.salt as salt9_13_0_,
eperson0_.self_registered as self_re10_13_0_
from
public.eperson eperson0_
inner join
public.dspaceobject eperson0_1_
on eperson0_.uuid=eperson0_1_.uuid
where
eperson0_.uuid=?
2018-02-17 20:31:25,063 TRACE org.hibernate.type.descriptor.sql.BasicBinder
@ binding parameter [1] as [OTHER] - b9f6c429-3567-4800-b55c-940deb3d8fce
2018-02-17 20:31:25,063 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found [true] as column
[can_log_1_13_0_]
2018-02-17 20:31:25,063 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found [SHA-512] as
column [digest_a2_13_0_]
2018-02-17 20:31:25,063 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found
[[email protected]] as column [email3_13_0_]
2018-02-17 20:31:25,063 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found [2018-02-17
19:07:13.416] as column [last_act4_13_0_]
2018-02-17 20:31:25,063 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found [405] as column
[eperson_5_13_0_]
2018-02-17 20:31:25,063 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found [yj4] as column
[netid6_13_0_]
2018-02-17 20:31:25,063 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found
[a556eeb9a5ea7541612573acf443367031ee943ecd1298c1739798ec88f75642c9bae7ebde0a44101a4a184d511c40ce5112955b74ded00b93108df01941271f]
as column [password7_13_0_]
2018-02-17 20:31:25,063 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found [false] as column
[require_8_13_0_]
2018-02-17 20:31:25,063 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found
[7fbf53e68087a11fff06c2600bbedab1] as column [salt9_13_0_]
2018-02-17 20:31:25,063 TRACE
org.hibernate.type.descriptor.sql.BasicExtractor @ Found [true] as column
[self_re10_13_0_]
2018-02-17 20:31:25,063 TRACE org.hibernate.type.CollectionType @ Created
collection wrapper:
[org.dspace.content.DSpaceObject.handles#b9f6c429-3567-4800-b55c-940deb3d8fce]
2018-02-17 20:31:25,063 TRACE org.hibernate.type.CollectionType @ Created
collection wrapper:
[org.dspace.content.DSpaceObject.metadata#b9f6c429-3567-4800-b55c-940deb3d8fce]
2018-02-17 20:31:25,063 TRACE org.hibernate.type.CollectionType @ Created
collection wrapper:
[org.dspace.content.DSpaceObject.resourcePolicies#b9f6c429-3567-4800-b55c-940deb3d8fce]
2018-02-17 20:31:25,063 TRACE org.hibernate.type.CollectionType @ Created
collection wrapper:
[org.dspace.eperson.EPerson.groups#b9f6c429-3567-4800-b55c-940deb3d8fce]
2018-02-17 20:31:25,064 INFO
org.hibernate.engine.internal.StatisticalLoggingSessionEventListener
@ Session Metrics {
102177 nanoseconds spent acquiring 1 JDBC connections;
0 nanoseconds spent releasing 0 JDBC connections;
15913 nanoseconds spent preparing 1 JDBC statements;
195207 nanoseconds spent executing 1 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 partial-flushes (flushing a total of 0
entities and 0 collections)
=====
Should we consider this is a performance bug and issue a jira ticket?
Best,
Ying
--
You received this message because you are subscribed to the Google Groups
"DSpace Technical Support" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To post to this group, send email to [email protected].
Visit this group at https://groups.google.com/group/dspace-tech.
For more options, visit https://groups.google.com/d/optout.
