Line numbers reported by pp() do not respond to the reality

Line numbers reported by pp() do not respond to the reality

[Tim Beaulen]

When using the following script:

# --- testpp.stp ---
global calls

probe process("/home/kdesystemtap/kdeinstall/lib/kde4/plugins/styles/oxygen.so").statement("drawScrollBarSliderControl@*:*")
{
    if (execname() == "src") {
        calls[pp()] <<< 1;
    }
}

probe end
{
  printf("\n");
  foreach (call in calls) {
    printf("%s\n    calls: %10d\n", call, @count(calls[call]));
  }
}
# --------------------


And running it like this:
sudo stap ./testpp.stp

I get these results:
process("/home/kdesystemtap/kdeinstall/lib/kde4/plugins/styles/oxygen.so").statement("drawScrollBarSliderControl@/home/kdesystemtap/kde/src/trunk/KDE/kdebase/workspace/kstyles/oxygen/oxygenstyle.cpp:5024")
    calls:       2000
process("/home/kdesystemtap/kdeinstall/lib/kde4/plugins/styles/oxygen.so").statement("drawScrollBarSliderControl@/home/kdesystemtap/kde/src/trunk/KDE/kdebase/workspace/kstyles/oxygen/oxygenstyle.cpp:5018")
    calls:       2000
process("/home/kdesystemtap/kdeinstall/lib/kde4/plugins/styles/oxygen.so").statement("drawScrollBarSliderControl@/home/kdesystemtap/kde/src/trunk/KDE/kdebase/workspace/kstyles/oxygen/oxygenstyle.cpp:5011")
    calls:       2000
process("/home/kdesystemtap/kdeinstall/lib/kde4/plugins/styles/oxygen.so").statement("drawScrollBarSliderControl@/home/kdesystemtap/kde/src/trunk/KDE/kdebase/workspace/kstyles/oxygen/oxygenstyle.cpp:5009")
    calls:       2000
process("/home/kdesystemtap/kdeinstall/lib/kde4/plugins/styles/oxygen.so").statement("drawScrollBarSliderControl@/home/kdesystemtap/kde/src/trunk/KDE/kdebase/workspace/kstyles/oxygen/oxygenstyle.cpp:5004")
    calls:       2000
process("/home/kdesystemtap/kdeinstall/lib/kde4/plugins/styles/oxygen.so").statement("drawScrollBarSliderControl@/home/kdesystemtap/kde/src/trunk/KDE/kdebase/workspace/kstyles/oxygen/oxygenstyle.cpp:5003")
    calls:       2000
process("/home/kdesystemtap/kdeinstall/lib/kde4/plugins/styles/oxygen.so").statement("drawScrollBarSliderControl@/home/kdesystemtap/kde/src/trunk/KDE/kdebase/workspace/kstyles/oxygen/oxygenstyle.cpp:5002")
    calls:       2000
process("/home/kdesystemtap/kdeinstall/lib/kde4/plugins/styles/oxygen.so").statement("drawScrollBarSliderControl@/home/kdesystemtap/kde/src/trunk/KDE/kdebase/workspace/kstyles/oxygen/oxygenstyle.cpp:5001")
    calls:       2000
process("/home/kdesystemtap/kdeinstall/lib/kde4/plugins/styles/oxygen.so").statement("drawScrollBarSliderControl@/home/kdesystemtap/kde/src/trunk/KDE/kdebase/workspace/kstyles/oxygen/oxygenstyle.cpp:4998")
    calls:       2000
process("/home/kdesystemtap/kdeinstall/lib/kde4/plugins/styles/oxygen.so").statement("drawScrollBarSliderControl@/home/kdesystemtap/kde/src/trunk/KDE/kdebase/workspace/kstyles/oxygen/oxygenstyle.cpp:4999")
    calls:       2000
process("/home/kdesystemtap/kdeinstall/lib/kde4/plugins/styles/oxygen.so").statement("drawScrollBarSliderControl@/home/kdesystemtap/kde/src/trunk/KDE/kdebase/workspace/kstyles/oxygen/oxygenstyle.cpp:4996")
    calls:       2000
process("/home/kdesystemtap/kdeinstall/lib/kde4/plugins/styles/oxygen.so").statement("drawScrollBarSliderControl@/home/kdesystemtap/kde/src/trunk/KDE/kdebase/workspace/kstyles/oxygen/oxygenstyle.cpp:4995")
    calls:       2000



As you can see, the line numbers start at 4995 and end at 5024.

The actual part of the .cpp file including the line numbers:

4947    bool Style::drawScrollBarSliderControl( const QStyleOption*
option, QPainter* painter, const QWidget* widget ) const
4948    {
4949
4950        // cast option and check
4951        const QStyleOptionSlider *slider = qstyleoption_cast<const
QStyleOptionSlider *>( option );
4952        if( !slider ) return true;
4953
4954        const QRect& r( option->rect );
4955        const QPalette& palette( option->palette );
4956
4957        const State& flags( option->state );
4958        const bool horizontal( flags & State_Horizontal );
4959        const bool enabled( flags&State_Enabled );
4960        const bool mouseOver( enabled && (flags&State_MouseOver) );
4961
4962        // enable animation state
4963        animations().scrollBarEngine().updateState( widget,
enabled && slider && (slider->activeSubControls & SC_ScrollBarSlider)
);
4964
4965        const bool animated( enabled &&
animations().scrollBarEngine().isAnimated( widget, SC_ScrollBarSlider
) );
4966
4967        if( horizontal )
4968        {
4969            if( animated ) renderScrollBarHandle( painter, r,
palette, Qt::Horizontal, mouseOver,
animations().scrollBarEngine().opacity( widget, SC_ScrollBarSlider )
);
4970            else renderScrollBarHandle( painter, r, palette,
Qt::Horizontal, mouseOver );
4971
4972        } else {
4973
4974            if( animated ) renderScrollBarHandle( painter, r,
palette, Qt::Vertical, mouseOver,
animations().scrollBarEngine().opacity( widget, SC_ScrollBarSlider )
);
4975            else renderScrollBarHandle( painter, r, palette,
Qt::Vertical, mouseOver );
4976
4977        }
4978
4979        return true;
4980    }

As you can see, the line numbers differ. Why is that? Maybe I don not
understand the line numbers reported by pp().
I was hoping to make some sort of automatic report generator that
would be able to parse the correct line from the source file, but this
difference makes this impossible.

I am using Systemtap 1.2.

Re: Line numbers reported by pp() do not respond to the reality

[Frank Ch. Eigler]

Tim Beaulen <tbscope@gmail.com> writes:

> I get these results: [...]
> As you can see, the line numbers start at 4995 and end at 5024.
>
> The actual part of the .cpp file including the line numbers:
> 4947    bool Style::drawScrollBarSliderControl( const QStyleOption*
> option, QPainter* painter, const QWidget* widget ) const
> [...]
> 4980    }
>
> As you can see, the line numbers differ. Why is that?

They should not, something odd is going on.  When you run stap -p2 on
your script, you should get some PC addresses for the actual statement
probes.  Running binutils' addr2line on those addresses should resolve
to the same source file / line that stap.  Similarly, putting a gdb
breakpoint on the same file / line should resolve to basically the same
addresses (modulo shared library relocation type complications).

Can you compare some of the systemtap-computed values to addr2line &
gdb?

- FChE

Re: Line numbers reported by pp() do not respond to the reality

[Tim Beaulen]

sudo stap -p2 ./testpp.stp
...
# probes
process("/home/kdesystemtap/kdeinstall/lib/kde4/plugins/styles/oxygen.so").statement("drawScrollBarSliderControl@/home/kdesystemtap/kde/src/trunk/KDE/kdebase/workspace/kstyles/oxygen/oxygenstyle.cpp:4995")
/* pc=.dynamic+0x92035 */ /* <-
process("/home/kdesystemtap/kdeinstall/lib/kde4/plugins/styles/oxygen.so").statement("drawScrollBarSliderControl@*:*")
*/
...


addr2line -e /home/kdesystemtap/kdeinstall/lib/kde4/plugins/styles/oxygen.so
0x92035
/home/kdesystemtap/kde/src/trunk/KDE/kdebase/workspace/kstyles/oxygen/oxygenstyle.cpp:4995


I also checked with:
readelf --debug-dump=decodedline
/home/kdesystemtap/kdeinstall/lib/kde4/plugins/styles/oxygen.so
When I look up the address in this table, I get the same line number: 4995


I haven't checked with GDB yet but since this is the information in
the debug sections, I don't think GDB will report the correct line
number either.


I compiled everything as usual, I only added the -g compiler option.

Line numbers reported by pp() do not respond to the reality

[Tim Beaulen]

After reading the gcc man page, I think the problem is optimisation.
Like I said, I didn't change any compiler options, I only added -g.

I'll try again without optimisation.

Re: Line numbers reported by pp() do not respond to the reality

[Tim Beaulen]

I tried without optimising and everything is correct.

I know this is basic knowledge, I'm learning it by doing and making mistakes.
Sorry for the noise.

Re: Line numbers reported by pp() do not respond to the reality

[Frank Ch. Eigler]

Hi -

> I tried without optimising and everything is correct.

OK, but ...

> I know this is basic knowledge, I'm learning it by doing and making mistakes.
> Sorry for the noise.

Not at all.  I don't think this represents pilot error.  Tools like
systemtap are meant to opeate in the face of optimized, deployed
applications, not just -O0 -g ones.  It would be good to fully
understand the phenomenon here.

To that end, would you be able to share the .i file, and the object
file in question with and without -O*, along with exact gcc version
data?


- FChE

Re: Line numbers reported by pp() do not respond to the reality

[Tim Beaulen]

On Mon, Sep 6, 2010 at 2:18 PM, Frank Ch. Eigler <fche@redhat.com> wrote:
>
> Not at all.  I don't think this represents pilot error.  Tools like
> systemtap are meant to opeate in the face of optimized, deployed
> applications, not just -O0 -g ones.  It would be good to fully
> understand the phenomenon here.
>
> To that end, would you be able to share the .i file, and the object
> file in question with and without -O*, along with exact gcc version
> data?
>
>
> - FChE
>

Sorry for the delay. I didn't have time in the past week.

I tried to reproduce the difference, but now I get the same results
with and without optimisation.
I need to do some more research.