Details
-
Type:
Bug
-
Status: Closed
-
Priority:
Major
-
Resolution: Not A Bug
-
Affects Version/s: 2.12.0
-
Fix Version/s: None
-
Component/s: RubyGems
-
Labels:
Description
I'm noticing when a non-cached 20MB gem file is requested through a Nexus rubygems proxy repository, there is a consistent processing delay of 5-6 seconds that is not easily explained.
The log messages during the delay relate to httpclient expiring connections and Nexus copying the gem file and attributes file to storage.
This 5-6 second delay per gem file should be reduced or eliminated.
See lines 142-150 in the attached rubygems-processing-delay.txt
jvm 1 | 2016-01-06 11:58:00,833-0400 DEBUG [H2DBWriter] *SYSTEM com.sonatype.nexus.licensing.api.access.h2.H2DatabaseManager - Executed UIPTracker batch insert, 1 statements executed jvm 1 | 2016-01-06 11:58:04,489-0400 DEBUG [qtp444280102-83] admin remote.storage.outbound - [rubygems] GET https://rubygems.org/gems/jruby-jars-1.7.18.gem -> HTTP/1.1 200 OK; 10.01 s jvm 1 | 2016-01-06 11:58:04,489-0400 DEBUG [qtp444280102-83] admin org.sonatype.nexus.plugins.ruby.proxy.DefaultProxyRubyRepository - Caching item rubygems:/gems/j/jruby-jars-1.7.18.gem in local storage of repository. jvm 1 | 2016-01-06 11:58:04,489-0400 TRACE [qtp444280102-83] admin org.sonatype.nexus.plugins.ruby.proxy.RubyFSLocalRepositoryStorage - Resolve request path '/gems/jruby-jars-1.7.18.gem' to file: '/app/nexus-testing/2.12.0-01/nexus-professional-2.12.0-01-bundle/sonatype-work/nexus/storage/rubygems/gems/jruby-jars-1.7.18.gem' jvm 1 | 2016-01-06 11:58:04,490-0400 DEBUG [qtp444280102-83] admin org.sonatype.nexus.plugins.ruby.NexusRubygemsFacade - file :: /gems/jruby-jars-1.7.18.gem :: query=[/gems/jruby-jars-1.7.18.gem, ] jvm 1 | 2016-01-06 11:58:04,540-0400 TRACE [qtp444280102-83] admin org.sonatype.nexus.plugins.ruby.proxy.RubyFSLocalRepositoryStorage - Resolve request path '/gems/j/jruby-jars-1.7.18.gem' to file: '/app/nexus-testing/2.12.0-01/nexus-professional-2.12.0-01-bundle/sonatype-work/nexus/storage/rubygems/gems/j/jruby-jars-1.7.18.gem' jvm 1 | 2016-01-06 11:58:04,540-0400 DEBUG [qtp444280102-83] admin org.sonatype.nexus.proxy.storage.local.fs.DefaultFSPeer - Storing file to /app/nexus-testing/2.12.0-01/nexus-professional-2.12.0-01-bundle/sonatype-work/nexus/storage/rubygems/gems/j/jruby-jars-1.7.18.gem jvm 1 | 2016-01-06 11:58:05,053-0400 DEBUG [HC4x-EvictingThread] *SYSTEM org.sonatype.nexus.apachehttpclient.Hc4ProviderImpl$ManagedClientConnectionManager - Closing expired connections jvm 1 | 2016-01-06 11:58:05,054-0400 DEBUG [HC4x-EvictingThread] *SYSTEM org.sonatype.nexus.apachehttpclient.Hc4ProviderImpl$ManagedClientConnectionManager - Closing connections idle longer than 30000 MILLISECONDS jvm 1 | 2016-01-06 11:58:10,053-0400 DEBUG [HC4x-EvictingThread] *SYSTEM org.sonatype.nexus.apachehttpclient.Hc4ProviderImpl$ManagedClientConnectionManager - Closing expired connections jvm 1 | 2016-01-06 11:58:10,054-0400 DEBUG [HC4x-EvictingThread] *SYSTEM org.sonatype.nexus.apachehttpclient.Hc4ProviderImpl$ManagedClientConnectionManager - Closing connections idle longer than 30000 MILLISECONDS jvm 1 | 2016-01-06 11:58:10,960-0400 DEBUG [qtp444280102-83] admin org.sonatype.nexus.apachehttpclient.Hc4ProviderImpl$ManagedClientConnectionManager - Connection [id: 9][route: {s}->https://rubygems.global.ssl.fastly.net:443] can be kept alive for 30.0 seconds jvm 1 | 2016-01-06 11:58:10,960-0400 DEBUG [qtp444280102-83] admin org.sonatype.nexus.apachehttpclient.Hc4ProviderImpl$ManagedClientConnectionManager - Connection released: [id: 9][route: {s}->https://rubygems.global.ssl.fastly.net:443][total kept alive: 2; route allocated: 1 of 20; total allocated: 2 of 200] jvm 1 | 2016-01-06 11:58:10,967-0400 DEBUG [qtp444280102-83] admin org.sonatype.nexus.proxy.attributes.DefaultLSAttributeStorage - Storing attributes on UID=rubygems:/gems/j/jruby-jars-1.7.18.gem jvm 1 | 2016-01-06 11:58:10,967-0400 TRACE [qtp444280102-83] admin org.sonatype.nexus.plugins.ruby.proxy.RubyFSLocalRepositoryStorage - Resolve request path '/.nexus/attributes/gems/j/jruby-jars-1.7.18.gem' to file: '/app/nexus-testing/2.12.0-01/nexus-professional-2.12.0-01-bundle/sonatype-work/nexus/storage/rubygems/.nexus/attributes/gems/j/jruby-jars-1.7.18.gem' jvm 1 | 2016-01-06 11:58:10,968-0400 TRACE [qtp444280102-83] admin org.sonatype.nexus.plugins.ruby.proxy.RubyFSLocalRepositoryStorage - Resolve request path '/.nexus/attributes/gems/j/jruby-jars-1.7.18.gem' to file: '/app/nexus-testing/2.12.0-01/nexus-professional-2.12.0-01-bundle/sonatype-work/nexus/storage/rubygems/.nexus/attributes/gems/j/jruby-jars-1.7.18.gem' jvm 1 | 2016-01-06 11:58:10,968-0400 DEBUG [qtp444280102-83] admin org.sonatype.nexus.proxy.storage.local.fs.DefaultFSPeer - Storing file to /app/nexus-testing/2.12.0-01/nexus-professional-2.12.0-01-bundle/sonatype-work/nexus/storage/rubygems/.nexus/attributes/gems/j/jruby-jars-1.7.18.gem jvm 1 | 2016-01-06 11:58:10,968-0400 DEBUG [qtp444280102-83] admin org.sonatype.nexus.plugins.ruby.proxy.DefaultProxyRubyRepository - Removing path /gems/j/jruby-jars-1.7.18.gem from NFC. jvm 1 | 2016-01-06 11:58:10,968-0400 TRACE [qtp444280102-83] admin org.sonatype.nexus.plugins.ruby.proxy.RubyFSLocalRepositoryStorage - Resolve request path '/gems/j/jruby-jars-1.7.18.gem' to file: '/app/nexus-testing/2.12.0-01/nexus-professional-2.12.0-01-bundle/sonatype-work/nexus/storage/rubygems/gems/j/jruby-jars-1.7.18.gem' jvm 1 | 2016-01-06 11:58:10,968-0400 DEBUG [qtp444280102-83] admin org.sonatype.nexus.proxy.attributes.DefaultLSAttributeStorage - Loading attributes on UID=rubygems:/gems/j/jruby-jars-1.7.18.gem jvm 1 | 2016-01-06 11:58:10,968-0400 TRACE [qtp444280102-83] admin org.sonatype.nexus.plugins.ruby.proxy.RubyFSLocalRepositoryStorage - Resolve request path '/.nexus/attributes/gems/j/jruby-jars-1.7.18.gem' to file: '/app/nexus-testing/2.12.0-01/nexus-professional-2.12.0-01-bundle/sonatype-work/nexus/storage/rubygems/.nexus/attributes/gems/j/jruby-jars-1.7.18.gem' jvm 1 | 2016-01-06 11:58:10,970-0400 DEBUG [qtp444280102-83] admin org.sonatype.nexus.plugins.ruby.proxy.DefaultProxyRubyRepository - Item ResourceStoreRequest{requestPath='/gems/j/jruby-jars-1.7.18.gem', requestContext=RequestContext{this=org.sonatype.nexus.proxy.RequestContext@3bf46a57, parent=null}, pathStack=[], processedRepositories=[rubygems], appliedMappings={}} found in local storage. jvm 1 | 2016-01-06 11:58:10,970-0400 DEBUG [qtp444280102-83] admin org.sonatype.sisu.goodies.eventbus.internal.DefaultEventBus - Event 'RepositoryItemEventCacheCreate(sender="rubygems" [id=rubygems], rubygems:/gems/j/jruby-jars-1.7.18.gem)' fired jvm 1 | 2016-01-06 11:58:10,970-0400 TRACE [qtp444280102-83] admin org.sonatype.sisu.goodies.eventbus.internal.DefaultEventBus - Dispatching 'RepositoryItemEventCacheCreate(sender="rubygems" [id=rubygems], rubygems:/gems/j/jruby-jars-1.7.18.gem)' to [wrapper public void com.sonatype.nexus.plugins.smartproxy.event.internal.PublishEventInspector.on(org.sonatype.nexus.proxy.events.RepositoryItemEventCacheCreate) throws java.lang.Exception]
Attachments
Issue Links
- is superceded by
-
NEXUS-9617 log time to complete the entire remote storage request
-
- Open
-