-
Type:
Bug
-
Status: Open
-
Resolution: Unresolved
-
Affects Version/s: 6.10.3
-
Fix Version/s: None
-
Component/s: NuGet
-
Labels:None
-
Severity:Critical
-
Requirement Status:
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!
