* too many transport failure
@ 2011-04-01 0:40 Zhiwei Ying
2011-04-01 1:35 ` Josh Stone
0 siblings, 1 reply; 8+ messages in thread
From: Zhiwei Ying @ 2011-04-01 0:40 UTC (permalink / raw)
To: systemtap
Hi,
I am tracing a driver module to understand the call flow. In general I
will trace every function in the module.
probe module("xxx").function("*@*.c").call
{
printf("D %s %s\n", thread_indent(1), pp())
}
probe module("xxx").function("*@*.c").return
{
printf("D %s %s\n", thread_indent(-1), probefunc())
}
The log looks like
D 0 Audio_Timing(1245):
module("xxx").function("video_pvt_atc_check_render_health@/home/zhiwei/zhiwei-work/working_copy/otm/trunk/sshg/video/core/i686-linux-kernel/videedio_timing_control.c:1968").call
I run the code on a develop board, it reports many many "transport
failure", something like 500000+. I tried to increase the buf size for
staprun, but since there is not too much memory, only ~50M memory
could be used as the buffer for staprun, I can reduce some "transport
failure" to 200000+, the result is still not satisfied.
In this situation how can I reduce the "transport failure" to near
zero? I can tolerate some performance penalty.
pp() will print a long string, thought that consumes a lot of buffer.
Does systemtap has a ppid(), only print the function address? And
provide a map between ppid() and pp() offline, so I can restore the
pp() information offline.
Any help is appreciated.
Thanks,
Zhiwei
^ permalink raw reply [flat|nested] 8+ messages in thread* Re: too many transport failure
2011-04-01 0:40 too many transport failure Zhiwei Ying
@ 2011-04-01 1:35 ` Josh Stone
2011-04-01 9:10 ` Zhiwei Ying
2011-04-01 19:48 ` Frank Ch. Eigler
0 siblings, 2 replies; 8+ messages in thread
From: Josh Stone @ 2011-04-01 1:35 UTC (permalink / raw)
To: Zhiwei Ying; +Cc: systemtap
On 03/31/2011 05:40 PM, Zhiwei Ying wrote:
> pp() will print a long string, thought that consumes a lot of buffer.
> Does systemtap has a ppid(), only print the function address? And
> provide a map between ppid() and pp() offline, so I can restore the
> pp() information offline.
Beware, there actually is a ppid(), but it means "parent process ID".
Do you really need the complete source information that pp() gives? It
would save a lot of bandwidth to use probefunc() in the .call probes,
just as you have in the .return probes.
You could get the raw probe address with a function like this:
function REG_IP:long() %{
THIS->__retvalue = CONTEXT->regs ? REG_IP(CONTEXT->regs) : 0;
%}
Then, we don't have any automatic way to associate that to a pp(), but
you could manually save that in a global array and print them all in an
end probe as a translation key for some post-processing script.
Josh
^ permalink raw reply [flat|nested] 8+ messages in thread* Re: too many transport failure
2011-04-01 1:35 ` Josh Stone
@ 2011-04-01 9:10 ` Zhiwei Ying
2011-04-01 10:45 ` Adrien Kunysz
2011-04-01 18:18 ` Josh Stone
2011-04-01 19:48 ` Frank Ch. Eigler
1 sibling, 2 replies; 8+ messages in thread
From: Zhiwei Ying @ 2011-04-01 9:10 UTC (permalink / raw)
To: Josh Stone; +Cc: systemtap
Thanks for the help.
If I store the pp and address in the global array, will that cause a
lot of runtime overhead? Do I need to check whether the pp is saved in
the global array or not in every function tracing?
Do we have solutions like "stap -l", which prints out function name
and source code information, if it comes with function address, then
it looks perfect.
Zhiwei
On Fri, Apr 1, 2011 at 9:35 AM, Josh Stone <jistone@redhat.com> wrote:
> On 03/31/2011 05:40 PM, Zhiwei Ying wrote:
>> pp() will print a long string, thought that consumes a lot of buffer.
>> Does systemtap has a ppid(), only print the function address? And
>> provide a map between ppid() and pp() offline, so I can restore the
>> pp() information offline.
>
> Beware, there actually is a ppid(), but it means "parent process ID".
>
> Do you really need the complete source information that pp() gives? It
> would save a lot of bandwidth to use probefunc() in the .call probes,
> just as you have in the .return probes.
>
> You could get the raw probe address with a function like this:
>
> function REG_IP:long() %{
> THIS->__retvalue = CONTEXT->regs ? REG_IP(CONTEXT->regs) : 0;
> %}
>
> Then, we don't have any automatic way to associate that to a pp(), but
> you could manually save that in a global array and print them all in an
> end probe as a translation key for some post-processing script.
>
>
> Josh
>
^ permalink raw reply [flat|nested] 8+ messages in thread* Re: too many transport failure
2011-04-01 9:10 ` Zhiwei Ying
@ 2011-04-01 10:45 ` Adrien Kunysz
2011-04-01 18:18 ` Josh Stone
1 sibling, 0 replies; 8+ messages in thread
From: Adrien Kunysz @ 2011-04-01 10:45 UTC (permalink / raw)
To: Zhiwei Ying; +Cc: Josh Stone, systemtap
[-- Attachment #1: Type: text/plain, Size: 1757 bytes --]
You can match symbols addresses to names by looking at /proc/kallsyms
or using the lookup_symbol_name() kernel function. Both require the
kernel to be compiled with the CONFIG_KALLSYMS option I think.
On Fri, Apr 01, 2011 at 05:10:50PM +0800, Zhiwei Ying wrote:
> If I store the pp and address in the global array, will that cause a
> lot of runtime overhead? Do I need to check whether the pp is saved in
> the global array or not in every function tracing?
>
> Do we have solutions like "stap -l", which prints out function name
> and source code information, if it comes with function address, then
> it looks perfect.
>
> Zhiwei
>
>
> On Fri, Apr 1, 2011 at 9:35 AM, Josh Stone <jistone@redhat.com> wrote:
> > On 03/31/2011 05:40 PM, Zhiwei Ying wrote:
> >> pp() will print a long string, thought that consumes a lot of buffer.
> >> Does systemtap has a ppid(), only print the function address? And
> >> provide a map between ppid() and pp() offline, so I can restore the
> >> pp() information offline.
> >
> > Beware, there actually is a ppid(), but it means "parent process ID".
> >
> > Do you really need the complete source information that pp() gives? It
> > would save a lot of bandwidth to use probefunc() in the .call probes,
> > just as you have in the .return probes.
> >
> > You could get the raw probe address with a function like this:
> >
> > function REG_IP:long() %{
> > THIS->__retvalue = CONTEXT->regs ? REG_IP(CONTEXT->regs) : 0;
> > %}
> >
> > Then, we don't have any automatic way to associate that to a pp(), but
> > you could manually save that in a global array and print them all in an
> > end probe as a translation key for some post-processing script.
> >
> >
> > Josh
> >
[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 197 bytes --]
^ permalink raw reply [flat|nested] 8+ messages in thread* Re: too many transport failure
2011-04-01 9:10 ` Zhiwei Ying
2011-04-01 10:45 ` Adrien Kunysz
@ 2011-04-01 18:18 ` Josh Stone
1 sibling, 0 replies; 8+ messages in thread
From: Josh Stone @ 2011-04-01 18:18 UTC (permalink / raw)
To: Zhiwei Ying; +Cc: systemtap
On 04/01/2011 02:10 AM, Zhiwei Ying wrote:
> Thanks for the help.
>
> If I store the pp and address in the global array, will that cause a
> lot of runtime overhead? Do I need to check whether the pp is saved in
> the global array or not in every function tracing?
You could store it as an associative array, so overwriting is no issue:
global pps
...
probe ... {
ip = REG_IP()
pps[ip] = pp()
}
The overhead is not too big, just a hash table lookup and a string copy.
You could add "if (!(ip in pps))" to avoid the string copy, but then
you're doing the hash table twice. It's probably not a big deal for
performance either way, but the more troubling part is that you'd be
storing all the visited pp() strings again in kernel memory, which you
said is limited.
> Do we have solutions like "stap -l", which prints out function name
> and source code information, if it comes with function address, then
> it looks perfect.
If you examine pass-2 (option -p2), you'll see the probe addresses. But
since you're dealing with relocatable modules, it will give an address
relative to wherever the .text section of the module is loaded at
runtime. For example:
> $ stap -e 'probe module("video").function("*").call {}' -p2 -w
> # probes
> module("video").function("input_report_key@include/linux/input.h:1374").call /* pc=.text+0x518 */ /* <- module("video").function("*").call */
> module("video").function("acpi_video_bus_DOS@drivers/acpi/video.c:763").call /* pc=.text+0x135 */ /* <- module("video").function("*").call */
> module("video").function("acpi_video_device_state_seq_show@drivers/acpi/video.c:1201").call /* pc=.text+0xf26 */ /* <- module("video").function("*").call */
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: too many transport failure
2011-04-01 1:35 ` Josh Stone
2011-04-01 9:10 ` Zhiwei Ying
@ 2011-04-01 19:48 ` Frank Ch. Eigler
2011-04-01 20:07 ` Josh Stone
1 sibling, 1 reply; 8+ messages in thread
From: Frank Ch. Eigler @ 2011-04-01 19:48 UTC (permalink / raw)
To: Josh Stone; +Cc: Zhiwei Ying, systemtap
jistone wrote:
> [...]
>> pp() will print a long string, thought that consumes a lot of buffer.
>> [...]
> You could get the raw probe address with a function like this:
>
> function REG_IP:long() %{
> THIS->__retvalue = CONTEXT->regs ? REG_IP(CONTEXT->regs) : 0;
> %}
That's weird, we have uaddr() already. There should be a raw
version of it with that content, named something better.
> Then, we don't have any automatic way to associate that to a pp() [...]
What about symname(REG_IP())?
- FChE
^ permalink raw reply [flat|nested] 8+ messages in thread* Re: too many transport failure
2011-04-01 19:48 ` Frank Ch. Eigler
@ 2011-04-01 20:07 ` Josh Stone
2011-04-06 1:33 ` Zhiwei Ying
0 siblings, 1 reply; 8+ messages in thread
From: Josh Stone @ 2011-04-01 20:07 UTC (permalink / raw)
To: Frank Ch. Eigler; +Cc: Zhiwei Ying, systemtap
On 04/01/2011 12:48 PM, Frank Ch. Eigler wrote:
>
> jistone wrote:
>
>> [...]
>>> pp() will print a long string, thought that consumes a lot of buffer.
>>> [...]
>> You could get the raw probe address with a function like this:
>>
>> function REG_IP:long() %{
>> THIS->__retvalue = CONTEXT->regs ? REG_IP(CONTEXT->regs) : 0;
>> %}
>
> That's weird, we have uaddr() already. There should be a raw
> version of it with that content, named something better.
Yeah, I was surprised too. I have to wonder if we had some reason for
that omission, but I didn't find any such documentation...
>> Then, we don't have any automatic way to associate that to a pp() [...]
>
> What about symname(REG_IP())?
Sure, this should give the same info as probefunc() would directly in
the probe, though symname can be delayed. So long as you don't care
about the rest of pp(), like source location, then you could print each
IP at probe time and symname(ip) later to decode them.
^ permalink raw reply [flat|nested] 8+ messages in thread* Re: too many transport failure
2011-04-01 20:07 ` Josh Stone
@ 2011-04-06 1:33 ` Zhiwei Ying
0 siblings, 0 replies; 8+ messages in thread
From: Zhiwei Ying @ 2011-04-06 1:33 UTC (permalink / raw)
To: Josh Stone; +Cc: Frank Ch. Eigler, systemtap
Thanks everyone for the help. I did some experiment to test uaddr()
and REG_IP. uaddr is not useful, while REG_IP is ok but not perfect to
match pp()
First I tested with uaddr, the return value of uaddr cannot match
pp(). Some different functions have same uaddr.
USER, 0 read_chardev(19657): 8048487
process("/ddtv/read_chardev").function("main@../../../test/script/read_chardev.c:13").call
argc=0x1 argv=0xbfa008a4
USER, 0 read_chardev(19657): 8048474
process("/ddtv/read_chardev").function("user_trace@../../../test/script/read_chardev.c:8").call
funcName=0x8048604
USER 0 read_chardev(19657): 80484bb user_trace
DRVR 0 read_chardev(19657): 8ae416
module("chardev").function("device_open@/ddtv/chardev.c:144").call
DRVR 0 read_chardev(19657): 8ae416
module("chardev").function("trace_kmalloc@include/trace/events/kmem.h:87").call
DRVR 0 read_chardev(19657): 8ae416 trace_kmalloc
DRVR 0 read_chardev(19657): 8ae416
module("chardev").function("kern_alloc@/ddtv/chardev.c:73").call
DRVR 0 read_chardev(19657): 8ae416 kern_alloc
DRVR 0 read_chardev(19657): 8ae416
module("chardev").function("kern_alloc1@/ddtv/chardev.c:79").call
DRVR 0 read_chardev(19657): 8ae416 kern_alloc1
DRVR 0 read_chardev(19657): 8ae416
module("chardev").function("trace_kmalloc@include/trace/events/kmem.h:87").call
DRVR 0 read_chardev(19657): 8ae416 trace_kmalloc
DRVR 0 read_chardev(19657): 8ae416 device_open
DRVR 0 read_chardev(19657): 8ae416
module("chardev").function("device_read@/ddtv/chardev.c:205").call
DRVR 0 read_chardev(19657): 8ae416 device_read
USER, 0 read_chardev(19657): 8048474
process("/ddtv/read_chardev").function("user_trace@../../../test/script/read_chardev.c:8").call
funcName=0xbfa00768
USER 0 read_chardev(19657): 804851e user_trace
USER, 0 read_chardev(19657): 8048474
process("/ddtv/read_chardev").function("user_trace@../../../test/script/read_chardev.c:8").call
funcName=0x8048632
USER 0 read_chardev(19657): 804852a user_trace
DRVR 0 read_chardev(19657): 8ae416
module("chardev").function("device_release@/ddtv/chardev.c:188").call
DRVR 0 read_chardev(19657): 8ae416 device_release
USER 0 read_chardev(19657): 60acc6 main return=0x0
start dumping
ip=8048487 pp=process("/ddtv/tread_chardev").function("main@../../../test/script/read_chardev.c:13").call
ip=8048474 pp=process("/ddtv/read_chardev").function("user_trace@../../../test/script/read_chardev.c:8").call
ip=80484bb pp=process("/ddtv/read_chardev").function("user_trace@../../../test/script/read_chardev.c:8").return
ip=8ae416 pp=module("chardev").function("device_open@/ddtv/chardev.c:144").call
ip=804851e pp=process("/ddtv/read_chardev").function("user_trace@../../../test/script/read_chardev.c:8").return
ip=804852a pp=process("/ddtv/read_chardev").function("user_trace@../../../test/script/read_chardev.c:8").return
ip=60acc6 pp=process("/ddtv/read_chardev").function("main@../../../test/script/read_chardev.c:13").return
end of tracing
Then I tried with REG_IP, different function has different REG_IP
value. What's this IP? The IP of instrumentation function or the
function being instrumented? I got two REG_IP value for the return
function of user_trace. If one function's REG_IP is not unique, I have
concern on the size the hash table.
USER, 0 read_chardev(20705): 8048487
process("/ddtv/read_chardev").function("main@../../../test/script/read_chardev.c:13").call
argc=0x1 argv=0xbfca5084
USER, 0 read_chardev(20705): 8048474
process("/ddtv/read_chardev").function("user_trace@../../../test/script/read_chardev.c:8").call
funcName=0x8048604
USER 0 read_chardev(20705): 80484bb user_trace
DRVR 0 read_chardev(20705): f840621f
module("chardev").function("device_open@/ddtv/chardev.c:144").call
DRVR 0 read_chardev(20705): f84061aa
module("chardev").function("trace_kmalloc@include/trace/events/kmem.h:87").call
DRVR 0 read_chardev(20705): f8406292 trace_kmalloc
DRVR 0 read_chardev(20705): f84061f5
module("chardev").function("kern_alloc@/ddtv/chardev.c:73").call
DRVR 0 read_chardev(20705): f84062a9 kern_alloc
DRVR 0 read_chardev(20705): f840620b
module("chardev").function("kern_alloc1@/ddtv/chardev.c:79").call
DRVR 0 read_chardev(20705): f84062b3 kern_alloc1
DRVR 0 read_chardev(20705): f84061aa
module("chardev").function("trace_kmalloc@include/trace/events/kmem.h:87").call
DRVR 0 read_chardev(20705): f84062e9 trace_kmalloc
DRVR 0 read_chardev(20705): c04d40a0 device_open
DRVR 0 read_chardev(20705): f8406090
module("chardev").function("device_read@/ddtv//chardev.c:205").call
DRVR 0 read_chardev(20705): c04d1d98 device_read
USER, 0 read_chardev(20705): 8048474
process("/ddtv/read_chardev").function("user_trace@../../../test/script/read_chardev.c:8").call
funcName=0xbfca4f48
USER 0 read_chardev(20705): 804851e user_trace
USER, 0 read_chardev(20705): 8048474
process("/ddtv/read_chardev").function("user_trace@../../../test/script/read_chardev.c:8").call
funcName=0x8048632
USER 0 read_chardev(20705): 804852a user_trace
DRVR 0 read_chardev(20705): f8406074
module("chardev").function("device_release@/ddtv/chardev.c:188").call
DRVR 0 read_chardev(20705): c04d292f device_release
USER 0 read_chardev(20705): 60acc6 main return=0x0
start dumping
ip=8048487 pp=process("/ddtv/read_chardev").function("main@../../../test/script/read_chardev.c:13").call
ip=8048474 pp=process("/ddtv/read_chardev").function("user_trace@../../../test/script/read_chardev.c:8").call
ip=80484bb pp=user_trace
ip=f840621f pp=module("chardev").function("device_open@/ddtv/chardev.c:144").call
ip=f84061aa pp=module("chardev").function("trace_kmalloc@include/trace/events/kmem.h:87").call
ip=f8406292 pp=trace_kmalloc
ip=f84061f5 pp=module("chardev").function("kern_alloc@/ddtv/chardev.c:73").call
ip=f84062a9 pp=kern_alloc
ip=f840620b pp=module("chardev").function("kern_alloc1@/ddtv/chardev.c:79").call
ip=f84062b3 pp=kern_alloc1
ip=f84062e9 pp=trace_kmalloc
ip=c04d40a0 pp=device_open
ip=f8406090 pp=module("chardev").function("device_read@/ddtv/chardev.c:205").call
ip=c04d1d98 pp=device_read
ip=804851e pp=user_trace
ip=804852a pp=user_trace
ip=f8406074 pp=module("chardev").function("device_release@/ddtv/chardev.c:188").call
ip=c04d292f pp=device_release
ip=60acc6 pp=main
end of tracing
On Sat, Apr 2, 2011 at 4:07 AM, Josh Stone <jistone@redhat.com> wrote:
> On 04/01/2011 12:48 PM, Frank Ch. Eigler wrote:
>>
>> jistone wrote:
>>
>>> [...]
>>>> pp() will print a long string, thought that consumes a lot of buffer.
>>>> [...]
>>> You could get the raw probe address with a function like this:
>>>
>>> function REG_IP:long() %{
>>> THIS->__retvalue = CONTEXT->regs ? REG_IP(CONTEXT->regs) : 0;
>>> %}
>>
>> That's weird, we have uaddr() already. There should be a raw
>> version of it with that content, named something better.
>
> Yeah, I was surprised too. I have to wonder if we had some reason for
> that omission, but I didn't find any such documentation...
>
>>> Then, we don't have any automatic way to associate that to a pp() [...]
>>
>> What about symname(REG_IP())?
>
> Sure, this should give the same info as probefunc() would directly in
> the probe, though symname can be delayed. So long as you don't care
> about the rest of pp(), like source location, then you could print each
> IP at probe time and symname(ip) later to decode them.
>
^ permalink raw reply [flat|nested] 8+ messages in thread
end of thread, other threads:[~2011-04-06 1:33 UTC | newest]
Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2011-04-01 0:40 too many transport failure Zhiwei Ying
2011-04-01 1:35 ` Josh Stone
2011-04-01 9:10 ` Zhiwei Ying
2011-04-01 10:45 ` Adrien Kunysz
2011-04-01 18:18 ` Josh Stone
2011-04-01 19:48 ` Frank Ch. Eigler
2011-04-01 20:07 ` Josh Stone
2011-04-06 1:33 ` Zhiwei Ying
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).