Following up with more info on the problem I described on Monday last...
On closer inspection of the logs, I see the errors I described occur
somewhat prior to my delete request and therefore seem to have nothing
to do with whatever my problem is. I am attaching the tail of my
httpd, dspace, solr, and cocoon logs that will hopefully provide some
better info.
This is a plain vanilla installation of DSpace 4.1 with only minor
changes to build.properties and dspace.cfg necessary to connect to the
database, etc.
The problem is that deletes take an excruciating amount of time -- 22
minutes in the example I am attaching. The hardware/software details
are;
RedHat Linux 6; 4 cpu, 16GB
tomcat 7.0.50
java 7 (1.7.0.45)
maven 3.1.1
ant 1.9.2
postgresql 9.2
Browser doesn't seem to matter -- I have used Chrome, Firefox, and
Safari. No errors on the browser end.
As you will see be checking the log files I have attached, NOTHING
seems to be happening between the time I click 'delete' and when the
community list reappears. During this time, my cpu usage is high, but
memory usage is under 20%.
Immediately prior to doing the delete, I optimized the solr search index.
This is really weird, and I hope somebody will have time to take a
look at the logs I have attached and point me in the right direction!
More info available on demand, if needed of course.
Thanks in advance,
Bill
On Mon, Mar 3, 2014 at 3:33 PM, Bill Tantzen <[email protected]> wrote:
> I'm having problems with upload and delete in my DSpace 4.0
httpd_access_log
========================================
555.55.0.249 - [email protected] [05/Mar/2014:08:08:18 -0600] "POST /admin/item
HTTP/1.1" 200 17995
555.55.0.249 - [email protected] [05/Mar/2014:08:08:21 -0600] "POST /admin/item
HTTP/1.1" 302 -
555.55.0.249 - [email protected] [05/Mar/2014:08:30:46 -0600] "GET
/community-list HTTP/1.1" 200 272354
solr.log
========================================
2014-03-05 08:08:22,757 INFO org.apache.solr.search.SolrIndexSearcher @
Opening Searcher@1e783d5e realtime
2014-03-05 08:08:22,757 INFO
org.apache.solr.update.processor.LogUpdateProcessor @ [search] webapp=/solr
path=/update params={wt=javabin&version=2} {deleteByQuery=handle:"11299/162412"
(-1461744831177949184)} 0 123
2014-03-05 08:08:22,766 INFO org.apache.solr.update.UpdateHandler @ start
commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
2014-03-05 08:08:22,771 INFO org.apache.solr.core.SolrCore @
SolrDeletionPolicy.onCommit: commits: num=2
commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@/swadm/usr/local/dspace/solr/search/data/index
lockFactory=org.apache.lucene.store.NativeFSLockFactory@576ad7b3;
maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_17,generation=43}
commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@/swadm/usr/local/dspace/solr/search/data/index
lockFactory=org.apache.lucene.store.NativeFSLockFactory@576ad7b3;
maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_18,generation=44}
2014-03-05 08:08:22,771 INFO org.apache.solr.core.SolrCore @ newest commit
generation = 44
2014-03-05 08:08:22,771 INFO org.apache.solr.search.SolrIndexSearcher @
Opening Searcher@6b4c6c08 main
2014-03-05 08:08:22,772 INFO org.apache.solr.core.SolrCore @
QuerySenderListener sending requests to Searcher@6b4c6c08
main{StandardDirectoryReader(segments_17:73792:nrt _sgu(4.4):C33939/1)}
2014-03-05 08:08:22,773 INFO org.apache.solr.core.SolrCore @
QuerySenderListener done.
2014-03-05 08:08:22,773 INFO
org.apache.solr.handler.component.SpellCheckComponent @ Building spell index
for spell checker: default
2014-03-05 08:08:22,772 INFO org.apache.solr.update.UpdateHandler @
end_commit_flush
coccoon.log
========================================
2014-03-05 08:08:18,179 INFO
org.apache.cocoon.components.treeprocessor.ConcreteTreeProcessor$TreeProcessorRedirector
- Redirecting to 'cocoon:/admin/item/delete'
2014-03-05 08:08:18,194 INFO org.apache.cocoon.caching.impl.CacheImpl - Cache
HIT for PK_G-file-jndi:/localhost/aspects/protodocument.xml
2014-03-05 08:08:18,213 INFO org.apache.cocoon.caching.impl.CacheImpl - Cache
HIT for
PK_G-aspect-cocoon://DRI/9/admin/item/delete?pipelinehash=823411183535858997_T-Navigation--6017467027264227236
2014-03-05 08:08:18,213 INFO org.apache.cocoon.caching.impl.CacheImpl -
Removing cached response for
PK_G-aspect-cocoon://DRI/9/admin/item/delete?pipelinehash=823411183535858997_T-Navigation--6017467027264227236
2014-03-05 08:08:18,216 INFO org.apache.cocoon.caching.impl.CacheImpl - Cache
HIT for
PK_G-aspect-cocoon://DRI/8/admin/item/delete?pipelinehash=3157996667701012698_T-Navigation--6017467027264227236
2014-03-05 08:08:18,216 INFO org.apache.cocoon.caching.impl.CacheImpl -
Removing cached response for
PK_G-aspect-cocoon://DRI/8/admin/item/delete?pipelinehash=3157996667701012698_T-Navigation--6017467027264227236
2014-03-05 08:08:18,312 INFO org.apache.cocoon.caching.impl.CacheImpl - Cache
HIT for
PK_G-aspect-cocoon://DRI/7/admin/item/delete?pipelinehash=7126144719367704649_T-Navigation--6017467027264227236
2014-03-05 08:08:18,313 INFO org.apache.cocoon.caching.impl.CacheImpl -
Removing cached response for
PK_G-aspect-cocoon://DRI/7/admin/item/delete?pipelinehash=7126144719367704649_T-Navigation--6017467027264227236
2014-03-05 08:08:18,333 INFO org.apache.cocoon.caching.impl.CacheImpl - Cache
HIT for
PK_G-aspect-cocoon://DRI/6/admin/item/delete?pipelinehash=-7229113651460070484_T-SystemwideAlerts-1_T-Navigation--3660601964701593207
2014-03-05 08:08:18,333 INFO org.apache.cocoon.caching.impl.CacheImpl -
Removing cached response for
PK_G-aspect-cocoon://DRI/6/admin/item/delete?pipelinehash=-7229113651460070484_T-SystemwideAlerts-1_T-Navigation--3660601964701593207
2014-03-05 08:08:18,337 INFO org.apache.cocoon.caching.impl.CacheImpl - Cache
MISS for PK_G-aspect-cocoon://DRI/5/admin/item_T-Navigation-4392787051513151044
2014-03-05 08:08:18,337 INFO org.apache.cocoon.caching.impl.CacheImpl - Cache
MISS for PK_G-aspect-cocoon://DRI/4/admin/item_T-Navigation-1
2014-03-05 08:08:18,337 INFO org.apache.cocoon.caching.impl.CacheImpl - Cache
MISS for PK_G-aspect-cocoon://DRI/3/admin/item
2014-03-05 08:08:18,337 INFO org.apache.cocoon.caching.impl.CacheImpl - Cache
MISS for PK_G-aspect-cocoon://DRI/2/admin/item
2014-03-05 08:08:18,338 INFO org.apache.cocoon.caching.impl.CacheImpl - Cache
MISS for
PK_G-aspect-cocoon://DRI/1/admin/item_T-PageNotFound--5257993712106285231
2014-03-05 08:08:18,353 INFO org.apache.cocoon.caching.impl.CacheImpl - Cache
MISS for
PK_G-file-cocoon://DRI/admin/item_T-IncludePageMeta--5534495057400678945_T-IncludePageMeta-7145676799531262490_T-IncludePageMeta-7904007307692048974_T-xslt-jndi:/localhost/themes/Mirage/Mirage.xsl_T-i18n-context://i18n/?en_US__S-xhtml-;doctype-public=-//W3C//DTD
XHTML 1.0
Strict//EN;doctype-system=http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd;encoding=UTF-8;indent=yes
2014-03-05 08:08:18,414 INFO org.apache.cocoon.caching.impl.CacheImpl -
Caching new response for
PK_G-aspect-cocoon://DRI/9/admin/item/delete?pipelinehash=823411183535858997_T-Navigation--6017467027264227236
2014-03-05 08:08:18,415 INFO org.apache.cocoon.caching.impl.CacheImpl -
Caching new response for
PK_G-aspect-cocoon://DRI/8/admin/item/delete?pipelinehash=3157996667701012698_T-Navigation--6017467027264227236
2014-03-05 08:08:18,415 INFO org.apache.cocoon.caching.impl.CacheImpl -
Caching new response for
PK_G-aspect-cocoon://DRI/7/admin/item/delete?pipelinehash=7126144719367704649_T-Navigation--6017467027264227236
2014-03-05 08:08:18,415 INFO org.apache.cocoon.caching.impl.CacheImpl -
Caching new response for
PK_G-aspect-cocoon://DRI/6/admin/item/delete?pipelinehash=-7229113651460070484_T-SystemwideAlerts-1_T-Navigation--3660601964701593207
2014-03-05 08:08:18,418 INFO cocoon.access - 'admin/item' Processed by Apache
Cocoon in 272 milliseconds.
immediately followed by (22 minutes later)
========================================
2014-03-05 08:30:46,305 INFO
org.apache.cocoon.components.treeprocessor.ConcreteTreeProcessor$TreeProcessorRedirector
- Redirecting to '/community-list'
2014-03-05 08:30:46,307 INFO org.apache.cocoon.caching.impl.CacheImpl - Cache
MISS for PK_G-aspect-cocoon://DRI/5/admin/item_T-Navigation-4392787051513151044
2014-03-05 08:30:46,307 INFO org.apache.cocoon.caching.impl.CacheImpl - Cache
MISS for PK_G-aspect-cocoon://DRI/4/admin/item_T-Navigation-1
2014-03-05 08:30:46,307 INFO org.apache.cocoon.caching.impl.CacheImpl - Cache
MISS for PK_G-aspect-cocoon://DRI/3/admin/item
2014-03-05 08:30:46,307 INFO org.apache.cocoon.caching.impl.CacheImpl - Cache
MISS for PK_G-aspect-cocoon://DRI/2/admin/item
2014-03-05 08:30:46,307 INFO org.apache.cocoon.caching.impl.CacheImpl - Cache
MISS for
PK_G-aspect-cocoon://DRI/1/admin/item_T-PageNotFound--5257993712106285231
etc
etc
etc
dspace.log
========================================
2014-03-05 08:08:21,994 INFO org.dspace.content.Item @
[email protected]:session_id=8CD5D269BE6B93DED4721EA260772085:ip_addr=555.55.0.249:delete_item:item_id=39244
2014-03-05 08:08:22,041 INFO org.dspace.content.Item @
[email protected]:session_id=8CD5D269BE6B93DED4721EA260772085:ip_addr=555.55.0.249:remove_bundle:item_id=39244,bundle_id=102602
2014-03-05 08:08:22,193 INFO org.dspace.content.Bundle @
[email protected]:session_id=8CD5D269BE6B93DED4721EA260772085:ip_addr=555.55.0.249:delete_bundle:bundle_id=102602
2014-03-05 08:08:22,195 INFO org.dspace.content.Bundle @
[email protected]:session_id=8CD5D269BE6B93DED4721EA260772085:ip_addr=555.55.0.249:remove_bitstream:bundle_id=102602,bitstream_id=254866
2014-03-05 08:08:22,197 INFO org.dspace.content.Bitstream @
[email protected]:session_id=8CD5D269BE6B93DED4721EA260772085:ip_addr=555.55.0.249:delete_bitstream:bitstream_id=254866
2014-03-05 08:08:22,324 INFO org.dspace.content.Item @
[email protected]:session_id=8CD5D269BE6B93DED4721EA260772085:ip_addr=555.55.0.249:remove_bundle:item_id=39244,bundle_id=102601
2014-03-05 08:08:22,345 INFO org.dspace.content.Bundle @
[email protected]:session_id=8CD5D269BE6B93DED4721EA260772085:ip_addr=555.55.0.249:delete_bundle:bundle_id=102601
2014-03-05 08:08:22,347 INFO org.dspace.content.Bundle @
[email protected]:session_id=8CD5D269BE6B93DED4721EA260772085:ip_addr=555.55.0.249:remove_bitstream:bundle_id=102601,bitstream_id=254865
2014-03-05 08:08:22,348 INFO org.dspace.content.Bitstream @
[email protected]:session_id=8CD5D269BE6B93DED4721EA260772085:ip_addr=555.55.0.249:delete_bitstream:bitstream_id=254865
2014-03-05 08:08:22,599 INFO org.dspace.content.Collection @
[email protected]:session_id=8CD5D269BE6B93DED4721EA260772085:ip_addr=555.55.0.249:remove_item:collection_id=817,item_id=39244
2014-03-05 08:08:22,628 WARN org.dspace.discovery.IndexEventConsumer @ REMOVE
event, could not get object for BUNDLE id=102602, perhaps it has been deleted.
2014-03-05 08:08:22,630 WARN org.dspace.discovery.IndexEventConsumer @ REMOVE
event, could not get object for BUNDLE id=102601, perhaps it has been deleted.
2014-03-05 08:08:22,632 WARN org.dspace.discovery.IndexEventConsumer @ MODIFY
event, could not get object for ITEM id=39244, perhaps it has been deleted.
2014-03-05 08:08:22,632 WARN org.dspace.discovery.IndexEventConsumer @ REMOVE
event, could not get object for ITEM id=39244, perhaps it has been deleted.
immediately followed by (22 minutes later)
========================================
2014-03-05 08:30:47,393 INFO
org.dspace.app.xmlui.aspect.artifactbrowser.CommunityBrowser @
[email protected]:session_id=8CD5D269BE6B93DED4721EA260772085:ip_addr=555.55.0.249:view_community_list:
catalina.out
========================================
70286224 [http-apr-8080-exec-3] INFO
org.apache.solr.update.processor.LogUpdateProcessor – [search] webapp=/solr
path=/update params={wt=javabin&version=2} {deleteByQuery=handle:"11299/162412"
(-1461744831177949184)} 0 123
70286233 [http-apr-8080-exec-4] INFO org.apache.solr.update.UpdateHandler –
start
commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
70286238 [http-apr-8080-exec-4] INFO org.apache.solr.core.SolrCore –
SolrDeletionPolicy.onCommit: commits: num=2
commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@/swadm/usr/local/dspace/solr/search/data/index
lockFactory=org.apache.lucene.store.NativeFSLockFactory@576ad7b3;
maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_17,generation=43}
commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@/swadm/usr/local/dspace/solr/search/data/index
lockFactory=org.apache.lucene.store.NativeFSLockFactory@576ad7b3;
maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_18,generation=44}
70286238 [http-apr-8080-exec-4] INFO org.apache.solr.core.SolrCore – newest
commit generation = 44
70286238 [http-apr-8080-exec-4] INFO org.apache.solr.search.SolrIndexSearcher
– Opening Searcher@6b4c6c08 main
70286239 [searcherExecutor-4-thread-1] INFO org.apache.solr.core.SolrCore –
QuerySenderListener sending requests to Searcher@6b4c6c08
main{StandardDirectoryReader(segments_17:73792:nrt _sgu(4.4):C33939/1)}
70286240 [searcherExecutor-4-thread-1] INFO org.apache.solr.core.SolrCore –
QuerySenderListener done.
70286240 [searcherExecutor-4-thread-1] INFO
org.apache.solr.handler.component.SpellCheckComponent – Building spell index
for spell checker: default
70286239 [http-apr-8080-exec-4] INFO org.apache.solr.update.UpdateHandler –
end_commit_flush
71150000 [commitScheduler-11-thread-1] INFO
org.apache.solr.update.UpdateHandler – start
commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
71150016 [commitScheduler-11-thread-1] INFO org.apache.solr.core.SolrCore –
SolrDeletionPolicy.onCommit: commits: num=2
commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@/swadm/usr/local/dspace/solr/statistics/data/index
lockFactory=org.apache.lucene.store.NativeFSLockFactory@eecb914;
maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@/swadm/usr/local/dspace/solr/statistics/data/index
lockFactory=org.apache.lucene.store.NativeFSLockFactory@eecb914;
maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
71150017 [commitScheduler-11-thread-1] INFO org.apache.solr.core.SolrCore –
newest commit generation = 3
71150018 [commitScheduler-11-thread-1] INFO
org.apache.solr.search.SolrIndexSearcher – Opening Searcher@a113b57 main
71150018 [commitScheduler-11-thread-1] INFO
org.apache.solr.update.UpdateHandler – end_commit_flush
71150058 [searcherExecutor-5-thread-1] INFO org.apache.solr.core.SolrCore –
QuerySenderListener sending requests to Searcher@a113b57
main{StandardDirectoryReader(segments_3:5:nrt _0(4.4):C8 _1(4.4):C2)}
71150058 [searcherExecutor-5-thread-1] INFO org.apache.solr.core.SolrCore –
QuerySenderListener done.
71150060 [searcherExecutor-5-thread-1] INFO org.apache.solr.core.SolrCore –
[statistics] Registered new searcher Searcher@a113b57
main{StandardDirectoryReader(segments_3:5:nrt _0(4.4):C8 _1(4.4):C2)}
------------------------------------------------------------------------------
Subversion Kills Productivity. Get off Subversion & Make the Move to Perforce.
With Perforce, you get hassle-free workflows. Merge that actually works.
Faster operations. Version large binaries. Built-in WAN optimization and the
freedom to use Git, Perforce or both. Make the move to Perforce.
http://pubads.g.doubleclick.net/gampad/clk?id=122218951&iu=/4140/ostg.clktrk
_______________________________________________
DSpace-tech mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/dspace-tech
List Etiquette: https://wiki.duraspace.org/display/DSPACE/Mailing+List+Etiquette
