PurePath vs CPU Sampling
Hi
Our customer tries to investigate what takes the WAS startup to last so long (more than 10 minutes).
When he check the startup PurePath’s its seems that every startup holds a different method as the “star” method that taking the longest time.
When he took a CPU sampling along the startup time he found that methods that “stars” in the PurePath Hotspots with 188 seconds (with 48% CPU) only last 11 seconds in the CPU Sampling.
Can anyone helps with (first) understand why the WAS startup is so long and (second) how to explain the gap between the PurePath timing and the one from the CPU Sampling.
Attach the PurePath and the CPU Sampling.
Best regards and thanks in advance
Yos
Yosi,
It looks like your I/O is very slow. For example, a single call to getBooleanAttributes takes 6.7 seconds. If you look at the timings for getBooleanAttributes from the 'Contributors' tab for the slowest PP, there are about 800 calls > 140 milliseconds, and another 20 or so < 10 milliseconds. That suggests to me that the slower calls are accessing a remote file system.
(btw, You can focus on a particular method in the Contributors tab by typing ctrl-F and typing the name of the method into the search box.)
Your startup sequence is clearly doing a lot. The application uses the Eclipse Modeling Framework as well as the Websphere Business Level Application framework. Internally, you can see legacy OTI code in the Eclipse libraries as well as Object Web. loadClass is called over 9000 times, which suggests that your model has over 9000 types of objects for which classes are being generated on the fly during startup.
So there's a lot going on, combined with a very slow file system, that produces the long start-up time.
As for the CPU sample, I'd like to know whether the sample was collected at the default 50 milliseconds, or at the highest sampling rate of 10 milliseconds. If the former, it's certainly possible that the discrepancy between the PurePath data and the CPU sample was due to calls to getBooleanAttributes being missed. The CPU sample is not really designed to measure CPU timings with any particular accuracy, but rather to sweep the process to provide a more comprehensive (although lower accuracy) view than the PurePath data.
It's not as thought the CPU sample is telling you something different about where the time is going: it's mostly file operations, with class loading and zip files making an appearance, just as they do in the method hotspots data.
Finally, the fact that the "top" method in the method hotspots dashboard is different for each PurePath is a strength, not a weakness. It's easy to take a collection of PurePaths and either analyze them in the aggregate (e.g., using ctrl-A to select all before you drill down) or analyze them individually. What we see in your data when we exclude the slowest PurePath is that class loading is a relatively much higher percentage of the execution time, but class loading is still pretty fast. They're faster because they're doing less file I/O. What you don't see is a very different story from one PurePath to the other (although I've certainly seen sessions where there were five or six different reasons for the top 10 PurePaths being slow).
-- Graeme
Yosi-
So, you are using dynatrace to instrument the start up execution of WAS? If that is the case, the explanation for the slow start up may go beyond just the method execution that is part of the start up process. Where is the dynatrace collector in relation to this WAS agent? If there is any kind of network latency, that could explain the long start up time. The dynatrace agent has to send information about every single method to the collector while the JVM starts up. Network latency will delay this process, and as a result can cause a severe delay (or even timeout) to the JVM starting up.
Thanks,
Kevin
