Thanks! -- I missed a couple of these.  Yes, really verbose output!  No 
problem, because I have yet to move this to production.
--Bill

On Thursday, February 22, 2018 at 12:50:33 PM UTC-6, Ying Jin wrote:
>
> Hi Bill,
>
> I put some extra lines in log4j.properties
>
> First, change this to DEBUG
>
> loglevel.other=DEBUG
>
> And add following:
>
> log4j.logger.org.hibernate=INFO, hb
>
> log4j.logger.org.hibernate.SQL=DEBUG
>
> log4j.logger.org.hibernate.type=TRACE
>
> log4j.logger.org.hibernate.hql.ast.AST=info
>
> log4j.logger.org.hibernate.tool.hbm2ddl=warn
>
> log4j.logger.org.hibernate.hql=debug
>
> log4j.logger.org.hibernate.cache=info
>
> log4j.logger.org.hibernate.jdbc=debug
>
> log4j.logger.org.hibernate.stat=debug
>
> Also, I added extra lines to hibernate.cfg.xml file:
>
> <property name="hibernate.generate_statistics">true</property>
>
>         <property name="org.hibernate.stat">debug</property>
>
>         <property name="show_sql">true</property>
>
>         <property name="format_sql">true</property>
>
>         <property name="use_sql_comments">true</property>
>
> It generates huge log files, so be careful with using it. I only use this 
> on our development server and when I am not debugging, I turn them off.
>
> Hope this helps!
>
> Best,
> Ying
>
> On Thursday, February 22, 2018 at 10:40:09 AM UTC-6, Bill T wrote:
>>
>> Ying
>>
>> As you've noticed I'm having the same difficulties with DSpace 6x...  How 
>> did you get this log info?  I have show_sql = true in hibernate.cfg, but 
>> I'm not seeing the same info...
>> --Bill
>>
>> On Wednesday, February 21, 2018 at 4:02:06 PM UTC-6, Ying Jin wrote:
>>>
>>> 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,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,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 dspace-tech+unsubscr...@googlegroups.com.
To post to this group, send email to dspace-tech@googlegroups.com.
Visit this group at https://groups.google.com/group/dspace-tech.
For more options, visit https://groups.google.com/d/optout.

Reply via email to