How to debug Requests to NRM that take too long

Sonatype Nexus Repository
1

Hey guys,

I have a small amount of requests to my Nexus Repository Manager 3.16.1-02 that are taking too long to respond.
The connections are spread over all my repositories (mainly maven2, npm and docker).
Overall there are around 5m requests per day to this single instance.

Some requests (e.g. GET) are taking more than 20 seconds to finish.

I have begun to debug what can cause the delay and came up with the following example for a slow request:

Apache (Nexus-Host)
-----------------
access_log
192.168.0.2 "192.168.0.1, 192.168.0.2" - - [28/Oct/2019:14:20:49 +0100] "GET /repository/repository-name/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256 HTTP/1.1" 404 2061 12621640 "-" "Artifactory/6.11.1" "https" "443"

Jetty (Nexus-Host)
----------------
request.log
192.168.0.1 - user-name [28/Oct/2019:14:21:01 +0100] "GET /repository/repository-name/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256 HTTP/1.1" 404 - 2061 12620 "Artifactory/6.11.1"


Nexus (Nexus-Host)
------------------
nexus.log
2019-10-28 14:20:49,273+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:49,273+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:49,273+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:49,274+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256'}, payload=null}
2019-10-28 14:20:49,274+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:49,275+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256'}, payload=null}
2019-10-28 14:20:49,275+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:49,275+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256'}, payload=null}
2019-10-28 14:20:49,275+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:49,276+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256'}, payload=null}
2019-10-28 14:20:49,276+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:49,276+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256'}, payload=null}
2019-10-28 14:20:49,276+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:49,573+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:20:49,573+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:50,309+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:20:50,309+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:50,795+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:20:50,796+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:51,205+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:20:51,205+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:51,802+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:20:51,802+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:52,905+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:20:52,905+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:53,652+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:20:53,652+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:53,652+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=502, message='null'}, payload=null}
2019-10-28 14:20:53,652+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:53,780+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:20:53,780+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:56,308+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:20:56,309+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:56,660+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:20:56,661+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:57,189+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:20:57,189+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:57,395+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:20:57,395+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:57,986+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:20:57,986+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:58,408+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:20:58,408+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:58,532+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:20:58,533+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:58,656+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:20:58,656+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:58,782+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:20:58,782+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:20:59,095+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:20:59,095+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:21:01,683+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:21:01,683+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:21:01,892+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:21:01,892+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:21:01,892+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:21:01,892+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Request: Request{action='GET', path='/group-name/artifact-name/19.10.28.01/artifact-name-19.10.28.01.pom.sha256', parameters={}, payload=HttpRequestPayloadAdapter{contentType='null', size=-1}, multipart=false}
2019-10-28 14:21:01,892+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=400, message='Repository version policy: SNAPSHOT does not allow version: 19.10.28.01'}, payload=null}
2019-10-28 14:21:01,892+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}
2019-10-28 14:21:01,892+0100 DEBUG [qtp1005103742-12256]  user-name org.sonatype.nexus.repository.view.Router - Response: Response{status=Status{successful=false, code=404, message='null'}, payload=null}

In this example the Request takes around 13 seconds to finish.
The debug messages from “o.s.n.repository.view.Router” are the ones that were the most promising for a further investigation. Thats why i turned on DEBUG for this module.

Is there any information in these messages and how should i continue my investigations?

Looking forward to your advice!
Mario

2

This would be a good place to start:

3

hy rseddon

thank you for your quick response. good point to check the outbound connections.
unfortunately I have the same issues for my docker registry. and there is no group repo or remote repo. just one hosted repository.
but I will double check the outbound connections for npm and maven.

do you have another suggestion?

/mario

4

Another thing to check would be to make sure you’re meeting our system requirements: https://help.sonatype.com/display/NXRM3/System+Requirements