CPU on Method Hotspots dashlet does not agree with Methods dashlet
We've found a situation where the underlying purepaths for a single Method Hotspots dashlet were inconsistent, depending on which method was selected. Here are the details:
I selected 20 purepaths from the Purepath dashlet, and drilled down into Method Hotspots. As the attached figure 1 shows, the top CPU user was info(Object, Object[]). Further down on the list was process(Object, Writer). If I go back to that same Purepath dashlet and those same 20 purepaths, drill down into methods, and sort by CPU Sum, I see something different (see figure 2). Now process(Object, Writer) is the top CPU user.
Investigating further, I went back to Method Hotspots, selected info(Object, Object[]), and drilled down into Purepaths. As expected, 20 purepaths were displayed. Then I went back to Method Hotspots, selected process(Object, Writer), and drilled down into Purepaths...and only 1 purepath was displayed!
In other words, for the method-level data shown in the same Method Hotspots dashlet, info(Object, Object[]) represented an aggregation of 20 purepaths as expected, but process(Object, Writer) only represented a single purepath. This gives a completely misleading picture of what the hotspots actually are of course. Is there an explanation for this behavior?
BTW, this is a stored session, and the dashlet filters are set the same for all the dashlets involved. We're using dynaTrace 6.1.
Hi. I think I have an explanation for this but I first want to check this with engineering if this is really the case. Here is my guess
The Methods Dashlet only shows "Instrumented" methods and therefore the CPU Data that we book on these PurePath Nodes that come in through our Sensors. The Method Hotspots Dashlet also includes Auto Sensors - which is more granular and has more methods. Now - if you instrument process and just look at that method (e.g: hide Auto Sensors in the PurePath tree) then you will probably see CPU Sum 1140. When you turn on Auto Sensors you will most likely see that this method also called other methods that got picked up by Auto Sensors. So the 1140ms is actually spread across several methods.
My assumption now is that the Methods Dashlet shows the Total CPU time that was booked on that instrumented node whereas the Method Hotspot just shows the time that was consumed in that method and shows all other "child methods" as additional hotspots with their share of the CPU.
Now - let me double check this with engineering as I am not sure if this is really correct. But it was my first thought when I looked at your screenshots
Andi
That makes a certain amount of sense, Andi, but even with that, it seems odd that drilling down into Purepaths from the process() method on MethodHotspots would only bring up 1 purepath. It definitely was called in all 20 purepaths, and was instrumented. Even if it wasn't instrumented, I can't imagine the sampling process used to populate MethodHotspots would have missed process() 19 out of 20 times. I'll be interested to hear what the engineers have to say about it.
Thats correct. If that is the case it almost sounds like a bug in correctly applying the filter to the dashlet you drill down to. any chance you can share that exported session?
hi Glenn,
so far Andi's explanations were correct, the method hotspots dashlet takes auto-sensors into account whereas the method dashlet does not.
so this explains the CPU timing differences you see.
the drilldown from the method should result in all PurePaths where this method was actually called, so if it's really called in all 20 PurePaths then it is indeed interesting why it would only result in 1 PurePath.
as Andi asked: could you maybe export those PurePaths to a session and share that with us?
best,
Christian
