Uploaded image for project: 'Dev - Nexus Repo'
  1. Dev - Nexus Repo
  2. NEXUS-9602

rubygem proxy repository gem processing is slower than expected during initial caching

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Not A Bug
    • Affects Version/s: 2.12.0
    • Fix Version/s: None
    • Component/s: RubyGems

      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

          Improvement - An improvement or enhancement to an existing feature or task. NEXUS-9617 log time to complete the entire remote storage request

          • Minor - Minor loss of function, or other problem where easy workaround is present.
          • Open

            Activity

              People

              Assignee:
              Unassigned Unassigned
              Reporter:
              plynch Peter Lynch
              CC:
              Christian Meier
              Last Updated By:
              Peter Lynch Peter Lynch
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:

                  tigCommentSecurity.panel-title