Shark failing to get entire stack

classic Classic list List threaded Threaded
9 messages Options
Reply | Threaded
Open this post in threaded view
|

Shark failing to get entire stack

Jonathan Watt-3
I'm using Shark to try to profile a bug in the official FF4 beta 7 Mac build
which is causing Firefox to sit at 100% CPU, while minimized, with no tabs of
interest (as far as I can tell) open.

        0.0% 54.6% XUL nsCanvasRenderingContext2D::
                                  DrawImage(nsIDOMElement*, float, float,
                                    float, float, float, float, float,
                                    float, unsigned char)
        0.0% 54.6% XUL moz_cairo_fill_preserve
        0.0% 54.6% XUL  cairo_gstate_fill
        0.0% 54.5% XUL   cairo_surface_fill
        0.0% 54.5% XUL    cairo_quartz_surface_fill
        0.0% 54.1% XUL     cairo_quartz_draw_image
        0.0% 54.1% CoreGraphics      CGContextDrawImage
        0.0% 54.1% libRIP.A.dylib       ripc_DrawImage
        0.0% 53.9% libRIP.A.dylib        ripc_RenderImage
        0.0% 53.9% libRIP.A.dylib         ripl_BltImage
        0.0% 53.4% libRIP.A.dylib          ripl_Mark
        0.0% 53.4% CoreGraphics           argb32_image
        10.5% 53.4% CoreGraphics            argb32_image_mark
        42.9% 42.9% CoreGraphics             argb32_sample_ARGB32

My first problem is that in Top-Down Tree view Shark claims that
nsCanvasRenderingContext2D::DrawImage is the top of the call stack, which of
course is nonsense. Does anyone know why it's doing that, and how I can get it
to figure out/display the full call stack?

I'm also seeing a lot of "Unknown Library" entries without symbols. For example:

        0.0% 0.3% XUL js::mjit::JaegerShot(JSContext*)
        0.1% 0.1% Unknown Library 0x1145ee000 [621.5KB]
        0.0% 0.0% XUL js::mjit::stubs::ValueToBoolean(js::VMFrame&)
        0.0% 0.0% XUL js::mjit::stubs::UncachedCallHelper(
                                   js::VMFrame&, unsigned int,
                                   js::mjit::stubs::UncachedCallResult*)
        0.0% 0.0% Unknown Library 0x1327b3eb8 [unknown]
        0.0% 0.0% Unknown Library 0x1269e61c9 [unknown]
        0.0% 0.0% Unknown Library 0x1264fa228 [unknown]
        0.0% 0.0% Unknown Library 0x1264f4460 [unknown]
        0.0% 0.0% Unknown Library 0x1224fe2e4 [unknown]
        0.0% 0.0% Unknown Library 0x11d067c9e [unknown]
        0.0% 0.0% Unknown Library 0x11477febc [unknown]

This is with KernelDebugKit mounted. Does anyone know how I can get Shark to
identify these libraries and find the symbols for these things too?

Jonathan
_______________________________________________
dev-performance mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-performance
Reply | Threaded
Open this post in threaded view
|

Re: Shark failing to get entire stack

Mike Shaver
On Sat, Nov 13, 2010 at 12:13 PM, Jonathan Watt <[hidden email]> wrote:
> I'm using Shark to try to profile a bug in the official FF4 beta 7 Mac build
> which is causing Firefox to sit at 100% CPU, while minimized, with no tabs of
> interest (as far as I can tell) open.
>
>        0.0%    54.6%   XUL     nsCanvasRenderingContext2D::
>                                  DrawImage(nsIDOMElement*, float, float,
>                                    float, float, float, float, float,
>                                    float, unsigned char)

Are you compiling with frame pointer use enabled, such as via
--enable-profiling?  Without that the profiler can't look farther
back, and by default we omit the frame pointer on x86 in order to have
an extra register for our code.

> I'm also seeing a lot of "Unknown Library" entries without symbols. For example:
>
>        0.0%    0.3%    XUL     js::mjit::JaegerShot(JSContext*)
>        0.1%    0.1%    Unknown Library  0x1145ee000 [621.5KB]
>        0.0%    0.0%    XUL      js::mjit::stubs::ValueToBoolean(js::VMFrame&)
>        0.0%    0.0%    XUL      js::mjit::stubs::UncachedCallHelper(
>                                   js::VMFrame&, unsigned int,
>                                   js::mjit::stubs::UncachedCallResult*)
>        0.0%    0.0%    Unknown Library  0x1327b3eb8 [unknown]
>        0.0%    0.0%    Unknown Library  0x1269e61c9 [unknown]
>        0.0%    0.0%    Unknown Library  0x1264fa228 [unknown]
>        0.0%    0.0%    Unknown Library  0x1264f4460 [unknown]
>        0.0%    0.0%    Unknown Library  0x1224fe2e4 [unknown]
>        0.0%    0.0%    Unknown Library  0x11d067c9e [unknown]
>        0.0%    0.0%    Unknown Library  0x11477febc [unknown]
>
> This is with KernelDebugKit mounted. Does anyone know how I can get Shark to
> identify these libraries and find the symbols for these things too?

Those are almost certainly the code generated by the JS JITs, so there
are no symbols to be loaded.  Are they consuming a meaningful portion
of the time?

Mike
_______________________________________________
dev-performance mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-performance
Reply | Threaded
Open this post in threaded view
|

Re: Shark failing to get entire stack

Jonathan Watt-3
On 13/11/2010 20:28, Mike Shaver wrote:

> On Sat, Nov 13, 2010 at 12:13 PM, Jonathan Watt <[hidden email]> wrote:
>> I'm using Shark to try to profile a bug in the official FF4 beta 7 Mac build
>> which is causing Firefox to sit at 100% CPU, while minimized, with no tabs of
>> interest (as far as I can tell) open.
>>
>>        0.0%    54.6%   XUL     nsCanvasRenderingContext2D::
>>                                  DrawImage(nsIDOMElement*, float, float,
>>                                    float, float, float, float, float,
>>                                    float, unsigned char)
>
> Are you compiling with frame pointer use enabled, such as via
> --enable-profiling?

I didn't create this build - when I say "official" b7, I mean:

ftp://ftp.mozilla.org/pub/mozilla.org/firefox/releases/4.0b7/mac/en-US/Firefox%204.0%20Beta%207.dmg

for which I'm obtaining symbols by using fetch-symbols.py:

http://hg.mozilla.org/users/jwatt_jwatt.org/fetch-symbols

The problem doesn't seem to reproduce in a build I've spun myself, and I don't
want to restart my instance of official b7 in case I have trouble reproducing
the problem again.

> Without that the profiler can't look farther
> back, and by default we omit the frame pointer on x86 in order to have
> an extra register for our code.

Last time I tried this sort of stuff on Windows I seem to remember that the
symbol and source servers allowed me to get full stacks when running release
builds. Maybe this isn't currently possible on Mac? But doesn't crash reporter
somehow figure out full stacks for mac crash reports?

>> I'm also seeing a lot of "Unknown Library" entries without symbols. For example:
>>
>>        0.0%    0.3%    XUL     js::mjit::JaegerShot(JSContext*)
>>        0.1%    0.1%    Unknown Library  0x1145ee000 [621.5KB]
>>        0.0%    0.0%    XUL      js::mjit::stubs::ValueToBoolean(js::VMFrame&)
>>        0.0%    0.0%    XUL      js::mjit::stubs::UncachedCallHelper(
>>                                   js::VMFrame&, unsigned int,
>>                                   js::mjit::stubs::UncachedCallResult*)
>>        0.0%    0.0%    Unknown Library  0x1327b3eb8 [unknown]
>>        0.0%    0.0%    Unknown Library  0x1269e61c9 [unknown]
>>        0.0%    0.0%    Unknown Library  0x1264fa228 [unknown]
>>        0.0%    0.0%    Unknown Library  0x1264f4460 [unknown]
>>        0.0%    0.0%    Unknown Library  0x1224fe2e4 [unknown]
>>        0.0%    0.0%    Unknown Library  0x11d067c9e [unknown]
>>        0.0%    0.0%    Unknown Library  0x11477febc [unknown]
>>
>> This is with KernelDebugKit mounted. Does anyone know how I can get Shark to
>> identify these libraries and find the symbols for these things too?
>
> Those are almost certainly the code generated by the JS JITs, so there
> are no symbols to be loaded.  Are they consuming a meaningful portion
> of the time?

About a third of the total time seems to be scattered across hundreds of these,
although each one in itself is typically around 0.1%.

This is also happening for stacks where the code hasn't been generated by JIT.
Some examples are:

0.0%   0.1%   Unknown Library  0x102153000 [unknown]
0.1%   0.1%   XUL                nsDisplayItem::RecomputeVisibility
0.0%   0.0%   XUL                  mozilla::FrameLayerBuilder::DrawThebesLayer
0.0%   0.0%   XUL                    nsRegion::SetToElements(unsigned int)


0.0%   0.1%   Unknown Library 0x11f639610 [unknown]
0.0%   0.0%   XUL          nsChildView::Invalidate
0.0%   0.0%   libobjc.A.dylib    objc_msgSend
0.0%   0.0%   XUL              0x1005a31b8 [209.1KB]


0.0%   0.0%   Unknown Library   0x6d656c6500000001 [unreadable]
0.0%   0.0%   XUL                 nsCanvasRenderingContext2D::DrawImage


0.0%   0.0%   Unknown Library   0x5a0000143ac [unreadable]
0.0%   0.0%   XUL                 nsIFrame::ComputeBorderRadii


0.0%   0.0%   Unknown Library   0x1341df7e9 [unknown]
0.0%   0.0%   XUL                 nsGenericElement::SetAttrAndNotify
0.0%   0.0%   XUL                   nsGenericElement::FindAttributeDependence

Jonathan
_______________________________________________
dev-performance mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-performance
Reply | Threaded
Open this post in threaded view
|

Re: Shark failing to get entire stack

Mike Shaver
On Sat, Nov 13, 2010 at 1:24 PM, Jonathan Watt <[hidden email]> wrote:
> Last time I tried this sort of stuff on Windows I seem to remember that the
> symbol and source servers allowed me to get full stacks when running release
> builds. Maybe this isn't currently possible on Mac? But doesn't crash reporter
> somehow figure out full stacks for mac crash reports?

The debugger can do it, profilers generally can't because the work
involved in correctly sampling the return addresses is much too high
for their sampling rates.  Profilers also can't do it on Windows,
generally.

You could just break in gdb and look at the stack that way, though, as
poor man's profiling.  Given the very high proportion of CPU that's
there, I suspect it wouldn't take too make interrupts to figure out
what you want.

> 0.0%   0.1%   Unknown Library  0x102153000 [unknown]
> 0.1%   0.1%   XUL                nsDisplayItem::RecomputeVisibility
> 0.0%   0.0%   XUL                  mozilla::FrameLayerBuilder::DrawThebesLayer
> 0.0%   0.0%   XUL                    nsRegion::SetToElements(unsigned int)

I don't remember off-hand how to tell what library is loaded at that
address, but if symbolicating with the downloaded symbols doesn't
work, then I'm not sure there's much you can do other than disassemble
and poke with a debugger to see what's at that code address.

Mike
_______________________________________________
dev-performance mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-performance
Reply | Threaded
Open this post in threaded view
|

Re: Shark failing to get entire stack

Jonathan Watt-3
On 13/11/2010 21:32, Mike Shaver wrote:

> On Sat, Nov 13, 2010 at 1:24 PM, Jonathan Watt <[hidden email]> wrote:
>> Last time I tried this sort of stuff on Windows I seem to remember that the
>> symbol and source servers allowed me to get full stacks when running release
>> builds. Maybe this isn't currently possible on Mac? But doesn't crash reporter
>> somehow figure out full stacks for mac crash reports?
>
> The debugger can do it, profilers generally can't because the work
> involved in correctly sampling the return addresses is much too high
> for their sampling rates.  Profilers also can't do it on Windows,
> generally.

Could they not potentially store some information and figure out this stuff
during the sample analysis after the profile run? Maybe I'm just showing my
ignorance of how things work under the hood here. :)

> You could just break in gdb and look at the stack that way, though, as
> poor man's profiling.  Given the very high proportion of CPU that's
> there, I suspect it wouldn't take too make interrupts to figure out
> what you want.

Yeah, I was hoping to avoid using gdb. Last time I did, gdb itself crashed and
took down the attached app, after which I couldn't reproduce the problem. If
there are no other options then that's what I'll do though.

>> 0.0%   0.1%   Unknown Library  0x102153000 [unknown]
>> 0.1%   0.1%   XUL                nsDisplayItem::RecomputeVisibility
>> 0.0%   0.0%   XUL                  mozilla::FrameLayerBuilder::DrawThebesLayer
>> 0.0%   0.0%   XUL                    nsRegion::SetToElements(unsigned int)
>
> I don't remember off-hand how to tell what library is loaded at that
> address, but if symbolicating with the downloaded symbols doesn't
> work, then I'm not sure there's much you can do other than disassemble
> and poke with a debugger to see what's at that code address.

Okay. Thanks for the help.

Jonathan
_______________________________________________
dev-performance mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-performance
Reply | Threaded
Open this post in threaded view
|

Re: Shark failing to get entire stack

Mike Shaver
On Sat, Nov 13, 2010 at 1:47 PM, Jonathan Watt <[hidden email]> wrote:
> Could they not potentially store some information and figure out this stuff
> during the sample analysis after the profile run? Maybe I'm just showing my
> ignorance of how things work under the hood here. :)

They could do that, in theory, but in practice unless you do the
analysis based on the debug info the "some information" they need is
"the entire stack", which is impractical to copy and store N times per
second.

> Yeah, I was hoping to avoid using gdb. Last time I did, gdb itself crashed and
> took down the attached app, after which I couldn't reproduce the problem. If
> there are no other options then that's what I'll do though.

You might try building a newer gdb from source, if you're using
Apple's stock one.

Mike
_______________________________________________
dev-performance mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-performance
Reply | Threaded
Open this post in threaded view
|

Re: Shark failing to get entire stack

Jonathan Watt-3
On 13/11/2010 21:47, Mike Shaver wrote:
> On Sat, Nov 13, 2010 at 1:47 PM, Jonathan Watt <[hidden email]> wrote:
>> Could they not potentially store some information and figure out this stuff
>> during the sample analysis after the profile run? Maybe I'm just showing my
>> ignorance of how things work under the hood here. :)
>
> They could do that, in theory, but in practice unless you do the
> analysis based on the debug info the "some information" they need is
> "the entire stack", which is impractical to copy and store N times per
> second.

Pity.

>> Yeah, I was hoping to avoid using gdb. Last time I did, gdb itself crashed and
>> took down the attached app, after which I couldn't reproduce the problem. If
>> there are no other options then that's what I'll do though.
>
> You might try building a newer gdb from source, if you're using
> Apple's stock one.

Good idea.

Thanks for the help and info.
_______________________________________________
dev-performance mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-performance
Reply | Threaded
Open this post in threaded view
|

Re: Shark failing to get entire stack

Boris Zbarsky
In reply to this post by Jonathan Watt-3
On 11/13/10 3:13 PM, Jonathan Watt wrote:
> My first problem is that in Top-Down Tree view Shark claims that
> nsCanvasRenderingContext2D::DrawImage is the top of the call stack, which of
> course is nonsense. Does anyone know why it's doing that, and how I can get it
> to figure out/display the full call stack?

Shaver covered this.

> I'm also seeing a lot of "Unknown Library" entries without symbols. For example:

Shaver also covered this, but one thing that I've found somewhat works
is to blame the entire "Unknown Library" library to callers.  That will
make all the mjit-generated code time look like self time for JaegerShot
and similar for tjit-generated code (becomes self time for some method I
can't recall the name of right now), and more importatly makes other
things called from jit code look like they were called from JaegerShot
and the other method, respectively.  This might not help you much past
"30% of our time is spent in code we generated outselves", but more
often it turns out that the real time sinks are things the code we
generated calls.

-Boris
_______________________________________________
dev-performance mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-performance
Reply | Threaded
Open this post in threaded view
|

Re: Shark failing to get entire stack

Jonathan Watt-3
On 14/11/2010 03:42, Boris Zbarsky wrote:

> one thing that I've found somewhat works
> is to blame the entire "Unknown Library" library to callers.  That will
> make all the mjit-generated code time look like self time for JaegerShot
> and similar for tjit-generated code (becomes self time for some method I
> can't recall the name of right now), and more importatly makes other
> things called from jit code look like they were called from JaegerShot
> and the other method, respectively.  This might not help you much past
> "30% of our time is spent in code we generated outselves", but more
> often it turns out that the real time sinks are things the code we
> generated calls.

Good tip, thanks.
_______________________________________________
dev-performance mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-performance