Uploaded image for project: 'Artifactory Binary Repository'
  1. Artifactory Binary Repository
  2. RTFACT-19693

Nuget API performance can be degraded due to excessive OData (Java) Logging

    Details

    • Type: Bug
    • Status: Open
    • Priority: Critical
    • Resolution: Unresolved
    • Affects Version/s: 6.10.3
    • Fix Version/s: None
    • Component/s: NuGet
    • Labels:
      None

      Description

      Nuget packages resolution times can increase significantly (and cause build timeouts) in case there's a relatively large Nuget API usage, and Java Logging is set to FINE (see bottom of ticket for config location).

      Here a few example requests:

      20190626141131|71235|REQUEST|127.0.0.1|anonymous|GET|/api/nuget/nugets/Download/StyleCop.Analyzers/1.1.118|HTTP/1.0|200|377566
      20190626141317|60969|REQUEST|127.0.0.1|anonymous|GET|/api/nuget/nugets/Download/System.Xml.ReaderWriter/4.3.1|HTTP/1.0|200|1380436
      20190626141330|61149|REQUEST|127.0.0.1|anonymous|GET|/api/nuget/nugets/Download/System.Spatial/5.8.4|HTTP/1.0|200|1115668
      

      Taking thread dumps from an instance suffering from prolonged requests, you will see threads being blocked due to a shared (java.util.logging) Log manager:

      "http-nio-8081-exec-206" Id=8039 in BLOCKED on lock=java.util.logging.ConsoleHandler@210077a7
           owned by http-nio-8081-exec-202 Id=8034
          at java.util.logging.StreamHandler.publish(StreamHandler.java:206)
          at java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:116)
          at java.util.logging.Logger.log(Logger.java:738)
          at java.util.logging.Logger.doLog(Logger.java:765)
          at java.util.logging.Logger.log(Logger.java:851)
          at org.odata4j.producer.inmemory.InMemoryEdmGenerator.generateToOneNavProperties(InMemoryEdmGenerator.java:274)
          at org.odata4j.producer.inmemory.InMemoryEdmGenerator.createNavigationProperties(InMemoryEdmGenerator.java:246)
          at org.odata4j.producer.inmemory.InMemoryEdmGenerator.generateEdm(InMemoryEdmGenerator.java:94)
          at org.odata4j.producer.inmemory.InMemoryProducer.getMetadata(InMemoryProducer.java:98)
          at org.odata4j.producer.inmemory.InMemoryProducer.getEntitiesCount(InMemoryProducer.java:542)
          at org.jfrog.repomd.nuget.odata.response.CountResponseBuilder.createResponse(CountResponseBuilder.java:23)
          at org.jfrog.repomd.nuget.rest.handler.NuGetLocalRepoHandler.findPackagesByIdCount(NuGetLocalRepoHandler.java:162)
          at org.artifactory.addon.nuget.search.delegate.id.FindPackagesByIdFeedRequestDelegate.getLocalCountResponse(FindPackagesByIdFeedRequestDelegate.java:47)
          at org.artifactory.addon.nuget.search.delegate.BaseRequestDelegate.getLocalCount(BaseRequestDelegate.java:73)
          at org.artifactory.addon.nuget.search.delegate.VirtualRepoSearchHandler.getRepoCount(VirtualRepoSearchHandler.java:70)
          at org.artifactory.addon.nuget.search.delegate.VirtualRepoSearchHandler.getRepoCountSizeNoSkip(VirtualRepoSearchHandler.java:159)
          at org.artifactory.addon.nuget.search.delegate.VirtualRepoSearchHandler.handleSkipAndTop(VirtualRepoSearchHandler.java:85)
          at org.artifactory.addon.nuget.search.delegate.VirtualRepoSearchHandler.getFeedFromRepo(VirtualRepoSearchHandler.java:54)
          at org.artifactory.addon.nuget.search.delegate.BaseRequestDelegate.responseFromVirtual(BaseRequestDelegate.java:147)
          at org.artifactory.addon.nuget.search.delegate.id.FindPackagesByIdFeedRequestDelegate.handleRequestForVirtual(FindPackagesByIdFeedRequestDelegate.java:37)
          at org.artifactory.addon.nuget.search.delegate.id.FindPackagesByIdFeedRequestDelegate.handleRequestForVirtual(FindPackagesByIdFeedRequestDelegate.java:23)
          at org.artifactory.addon.nuget.search.NuPkgSearchRequestHandler.delegateSearchRequestToRepos(NuPkgSearchRequestHandler.java:83)
          at org.artifactory.addon.nuget.search.NuPkgSearchRequestHandler.findPackagesById(NuPkgSearchRequestHandler.java:51)
          at org.artifactory.addon.nuget.repo.NuGetVirtualRepoHandler.findPackagesById(NuGetVirtualRepoHandler.java:165)
          at org.jfrog.repomd.nuget.rest.NuGetSubResource.findPackagesById(NuGetSubResource.java:133)  
      

      Sigfnifically slowing down the

      Jul 02, 2019 4:28:39 PM org.odata4j.producer.inmemory.InMemoryEdmGenerator generateToOneNavProperties
      FINE: genToOnNavProp V2FeedPackage - IconUrl(class java.lang.String) eetName2: null
      Jul 02, 2019 4:28:39 PM org.odata4j.producer.inmemory.InMemoryEdmGenerator generateToOneNavProperties
      FINE: genToOnNavProp V2FeedPackage - PackageSize(long) eetName2: null
      Jul 02, 2019 4:28:39 PM org.odata4j.producer.inmemory.InMemoryEdmGenerator generateToOneNavProperties
      FINE: genToOnNavProp V2FeedPackage - MinClientVersion(class java.lang.String) eetName2: null
      Jul 02, 2019 4:28:39 PM org.odata4j.producer.inmemory.InMemoryEdmGenerator generateToOneNavProperties
      FINE: genToOnNavProp V2FeedPackage - DownloadCount(long) eetName2: null
      Jul 02, 2019 4:28:39 PM org.odata4j.producer.inmemory.InMemoryEdmGenerator generateToOneNavProperties
      FINE: genToOnNavProp V2FeedPackage - Published(class java.lang.String) eetName2: null
      
      • Workaround: lower the Java logging configuration (not log4j under the Tomcat configurable logging (separate from Artifactory's codebase) $ARTIFACTORY_HOME/conf/tomcat/logging.properties from:

      java.util.logging.ConsoleHandler.level = FINE

      to:

      java.util.logging.ConsoleHandler.level = INFO

      • Was not able to reproduce locally!

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              andreik Andrei Komarov
            • Votes:
              2 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated: