We very often receive support tickets due to slow performance which are ultimately traced back to poorly performing storage. At the moment these are quite time consuming to debug, we typically have to get multiple thread dumps taken at the exact time the performance problem is occurring.
I think we can make it much easier for us to diagnose these types of issues by adding a relatively simple logging enhancement.
We currently have the "org.sonatype.nexus.httpclient.outbound" logger for outbound http requests. This is extremely useful for debugging performance problems caused by slow outbound connections from Nexus Repo to remote servers. It produces logging that looks like this:
2019-12-13 09:05:45,617-0600 DEBUG [qtp1314948779-197] admin org.sonatype.nexus.httpclient.outbound - https://repo1.maven.org/maven2/ant/ant/maven-metadata.xml > GET /maven2/ant/ant/maven-metadata.xml HTTP/1.1
2019-12-13 09:05:45,760-0600 DEBUG [qtp1314948779-197] admin org.sonatype.nexus.httpclient.outbound - https://repo1.maven.org/maven2/ant/ant/maven-metadata.xml < HTTP/1.1 304 Not Modified @ 143.4 ms
I'd like to see us add a similar logger for storage requests. This would consist of:
- A debug message logged right before a file is read or written to storage, stating what the path to be written is.
- A second debug message logged after the read or write is complete, also stating the path, and additionally printing the time it took for the request to complete ( or fail?) and how many bytes were written.
Additionally, we should log timing around deletes and renames.