Performance is critical for any customer facing application.
For web projects optimizing performance involves cache tuning, CSS/JS minification, deferred loading, adaptive serving and more front end techniques. However, when creating dynamic pages server side, as is done in classic AEM development, you also need to optimize the server side performance.
While caching can mitigate the need to render pages on the fly, caches still need to be filled at some point. Pages that are too slow to render under high load can lead to a thundering herd problem where the server is too slow to create the cache and gets slower with each subsequent to create and cache the page.
Apache Sling, the framework underlying AEM, includes a Recent Requests OSGi console which keeps detailed logs of every step in rendering each request. This can be used to analyze and identify performance bottlenecks, however the format is... less than friendly as you can see below:
The numbers on the left are critical to identifying the performance problems. Each is the number of microseconds since the start of the request at which the line was logged. Therefore, scanning down the logs, you can identify slow steps by identifying large increases.
But which line is actually the problem? And what if a script is called many times? Each one may only take a few microseconds, but they all add up to a significant amount of time.
After banging my head against this problem on a previous project, I threw together a quick parser for the Recent Request log. I've spent some time verifying, optimizing and improving the script and made it into a small single page app.
Pasting in the same Request log from above, click Parse and you get a Flame Graph of the execution tree:
Each color in the Flame Graph denotes the component of AEM that's executing the portion of the request making it easier to classify.
The parser also outputs a searchable table of all of the logs:
During the parsing process, the parser calculates the duration of each step as well as determining how much of the execution time is from sub-components.
The parser even outputs tables of the most expensive and most common steps of the request, deduplicating repeated steps:
Sling Recent Requests Parser