Recently I was investigating a response timeout issue in an Adobe Experience Manager (AEM) implementation. The AEM application serves content both to the browser and portal application. The portal system makes a request to AEM, and AEM processes that request and returns the request in JSON format. As per the architecture, the response from AEM should reach the portal within five seconds.
Using browser developer tools, we were able to see the response time. It was going beyond five seconds, but the response time did not show detail around how much time was spent on the AEM side or where exactly the delay was occurring.
That’s when I remembered Sling Main Servlet uses the Request Progress Tracker to log information about the requests that come into AEM. I accessed request data through Web Console Recent Request interface, and to my dismay I saw only twenty recent request logs were created. In the production environment there were millions of requests coming through, yet only twenty logs created, and I was not able to find which request consumed a lot of processing time.
Below is sample of a recent request interface:
Whenever I refreshed the browser, I got a new set of requests and still wasn’t able to find the particular request that went beyond five seconds. In the production environment, it can be extremely difficult to locate the exact request because of the large number of requests.
What other options do we have to find the long processing request, analyzing request.log and access.log for start and end time of request?
How many requests we will go through in the logs file?
How long will it take to complete the analysis in production environment, and when we will find the root cause and ultimately solve the issue?
Apache Sling is very powerful framework. It provides tools to assist DevOps in such situations. One hidden gem of Apache Sling is Request Processing Analyzer. Request Processing Analyzer is a bundle that you need to install in AEM instance. Once you install you can configure it in OSGI Configuration.
In the above example, I am looking for a request that takes more than five seconds and less than ten seconds, and which also has extension JSON.
Once this is saved it will create a log file named requesttracker.txt in ${sling.home}/logs folder. Now, it’s time to analyze the requesttracker.txt file. Use the same bundle jar file to open a graphical user interface (GUI) with the following command: java -jar org.apache.sling.reqanalyzer-0.0.1-SNAPSHOT.jar requesttracker.txt
It will show a GUI like below one:
The GUI displays as six columns with the following information:
- Start time stamp in ms since the Epoch
- Request processing time in ms
- Request method
- Request URL
- Response content type (plus character encoding if available)
- Response status
When looking at the GUI in this example, I am interested in the url /content/we-retail/us/men.html which took a 1374 milliseconds. Next, I click on that row, and it opens another window with detailed information about the request.
The first column shows the timestamp of each step that the request goes through, and the second column shows the delta of time between each step. The third column shows which step is processed. By going through each step we are able to see what actually happens behind the scene, and dig into what causes a delay in response time.
Reference: https://sling.apache.org/documentation/bundles/request-analysis.html
Instructions to Get Request Processing Analyzer
- Download the code from this URL: http://svn.apache.org/repos/asf/sling/trunk/contrib/extensions/reqanalyzer/
- Build the bundle using the following command: mvn clean install
- From the target folder you will see the following file: org.apache.sling.reqanalyzer-0.0.1-SNAPSHOT.jar
- Install the above bundle directly in OSGI Bundles interface
Have you had similar success with Request Processing Analyzer? Leave a comment below with any thoughts or questions.
