Mirror of the lttng-dev mailing list
 help / color / mirror / Atom feed
* [lttng-dev] UST performance
@ 2015-04-27  3:01 zhenyu.ren
  2015-04-28 15:47 ` Mathieu Desnoyers
  2015-04-29  1:31 ` [lttng-dev] 答复: " zhenyu.ren
  0 siblings, 2 replies; 5+ messages in thread
From: zhenyu.ren @ 2015-04-27  3:01 UTC (permalink / raw)


Hi,dev? ? About a month ago,I asked a question about how to do time recording for ust event when vdso_clock_gettime not availble on my platform?Glibc too old?.Recently I implemented a lib to analyze vdso in memory and lookuped the symbol vdso_clock_gettime successfully.With this vdso_clock_gettime availble,I get a 16% improvement in time spending per ust event. I.E. I measured the time taked by a event with 10 bytes string :?no ? vdso_clock_gettime : 0.642us?with vdso_clock_gettime?0.554usHowever?Both the numbers are much higher than the following 0.28us(But closed to 0.5us --W/O opt). So what's the difference between UST(0.28us) and UST W/O OPT(0.5us)???PS:My hardware2 x Xeon E5-2430 ?2.20GHz 100MHz FSB (24 cores)?94.6GB / 96GB 1333MHz DDR3 == 6 x 16GB, 6 x emptyThankszhenyu.ren

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20150427/c43822fb/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: temp4cj.png
Type: application/octet-stream
Size: 34762 bytes
Desc: not available
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20150427/c43822fb/attachment-0001.obj>


^ permalink raw reply	[flat|nested] 5+ messages in thread

* [lttng-dev] UST performance
  2015-04-27  3:01 [lttng-dev] UST performance zhenyu.ren
@ 2015-04-28 15:47 ` Mathieu Desnoyers
  2015-04-29  1:31 ` [lttng-dev] 答复: " zhenyu.ren
  1 sibling, 0 replies; 5+ messages in thread
From: Mathieu Desnoyers @ 2015-04-28 15:47 UTC (permalink / raw)


Hi, 

Is your sched_getcpu() system call a vdso too ? This may explain the difference. 

Moreover, make sure you #define _LGPL_SOURCE in your benchmark program 
before including any lttng ust header. It will inline many functions associated with 
tracepoints. 

Then, you can try using "perf" to profile the runtime execution of your program 
traced by lttng-ust ? This should give us the information we need to investigate the 
performance profile. 

Thanks, 

Mathieu 

----- Original Message -----

> Hi,dev

> About a month ago,I asked a question about how to do time recording for ust
> event when vdso_clock_gettime not availble on my platform?Glibc too
> old?.Recently I implemented a lib to analyze vdso in memory and lookuped the
> symbol vdso_clock_gettime successfully.With this vdso_clock_gettime
> availble,I get a 16% improvement in time spending per ust event. I.E. I
> measured the time taked by a event with 10 bytes string :

> no vdso_clock_gettime : 0.642us
> with vdso_clock_gettime?0.554us

> However?Both the numbers are much higher than the following 0.28us(But closed
> to 0.5us --W/O opt). So what's the difference between UST(0.28us) and UST
> W/O OPT(0.5us)??

> PS:My hardware
> 2 x Xeon E5-2430 2.20GHz 100MHz FSB (24 cores) 94.6GB / 96GB 1333MHz DDR3 ==
> 6 x 16GB, 6 x empty

> Thanks
> zhenyu.ren

> _______________________________________________
> lttng-dev mailing list
> lttng-dev at lists.lttng.org
> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

-- 
Mathieu Desnoyers 
EfficiOS Inc. 
http://www.efficios.com 
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20150428/19a46d40/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: temp4cj.png
Type: image/png
Size: 34762 bytes
Desc: not available
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20150428/19a46d40/attachment-0001.png>


^ permalink raw reply	[flat|nested] 5+ messages in thread

* [lttng-dev] 答复: UST performance
  2015-04-27  3:01 [lttng-dev] UST performance zhenyu.ren
  2015-04-28 15:47 ` Mathieu Desnoyers
@ 2015-04-29  1:31 ` zhenyu.ren
  2015-04-29  2:25   ` Mathieu Desnoyers
  2015-04-29  3:39   ` [lttng-dev] 答复:答复: " zhenyu.ren
  1 sibling, 2 replies; 5+ messages in thread
From: zhenyu.ren @ 2015-04-29  1:31 UTC (permalink / raw)


Hi,Mathieu> Is your sched_getcpu() system call a vdso too ? ?I use?VSYSCALL_ADDR(__NR_vgetcpu) instead sched_getcpu so there is no getcpu system calls.
> make sure you #define _LGPL_SOURCE in your benchmark program ? ?I do it as you suggested but no difference.
> Then, you can try using "perf" to profile the runtime execution?$~/renzhyu/perf record ./sample
WARNING: Kernel address maps (/proc/{kallsyms,modules}) are restricted,
check /proc/sys/kernel/kptr_restrict.

Samples in kernel functions may not be resolved if a suitable vmlinux
file is not found in the buildid cache or in the vmlinux path.

Samples in kernel modules won't be resolved at all.

If some relocation was applied (e.g. kexec) symbols may be misresolved
even with a suitable vmlinux or kallsyms file.


using 5720094251 ns
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.221 MB perf.data (~9658 samples) ]
$~/renzhyu/perf report
Events: 5K cycles
16.82% sample liblttng-ust.so.0.0.0 [.] lttng_event_commit10.55% sample liblttng-ust.so.0.0.0 [.] lttng_event_strcpy10.45% sample [kernel.kallsyms] [k] 0xffffffff8103548a8.16% sample liblttng-ust.so.0.0.0 [.] lttng_event_reserve7.57% sample sample [.] __event_get_size__sample_component___message6.42% sample sample [.] __event_probe__sample_component___message6.24% sample liblttng-ust.so.0.0.0 [.] lttng_write_event_header5.40% sample sample [.] _rcu_read_lock_update5.35% sample sample [.] _rcu_read_unlock_bp5.17% sample liburcu-bp.so.2.0.0 [.] rcu_read_unlock_bp4.14% sample ld-2.5.so [.] __tls_get_addr3.38% sample [vdso] [.] 0x7fff8f72e6be3.35% sample sample [.] main1.88% sample sample [.] lib_ring_buffer_ctx_init1.79% sample sample [.] _rcu_read_lock_bp1.20% sample liburcu-bp.so.2.0.0 [.] rcu_read_lock_bp0.66% sample sample [.] lib_ring_buffer_align_ctx0.38% sample sample [.] cds_list_empty0.37% sample sample [.] lib_ring_buffer_align0.35% sample liburcu-bp.so.2.0.0 [.] __tls_get_addr at plt0.28% sample sample [.] __event_get_align__sample_component___message 0.09% sample ld-2.5.so [.] do_lookup_The symbol? 0xffffffff8103548a is in?native_write_msr_safe,I don't know what the function is and why that kernel function can be TOP 3.ffffffff81035480 <native_write_msr_safe>:
ffffffff81035480: 55 push %rbp
ffffffff81035481: 89 f9 mov %edi,%ecx
ffffffff81035483: 89 f0 mov %esi,%eax
ffffffff81035485: 48 89 e5 mov %rsp,%rbp
ffffffff81035488: 0f 30 wrmsr
ffffffff8103548a: 31 c0 xor %eax,%eax
ffffffff8103548c: c9 leaveq
ffffffff8103548d: c3 retq
ffffffff8103548e: 66 90 xchg %ax,%axPS:my sample.c#include <time.h>
#include <unistd.h>
#include <stdio.h>
#define _LGPL_SOURCE
#define TRACEPOINT_DEFINE
#include "sample_component_provider.h"

#define NUM 10000000
int main(int argc, char **argv)
{
 int i = 0;
 struct timespec bef,aft;
 long diff;
 clock_gettime(CLOCK_MONOTONIC,&bef);
 for (i = 0; i < NUM; i++) {
tracepoint(sample_component, message, "HelloWorld");
 }
 clock_gettime(CLOCK_MONOTONIC,&aft);
 diff = (aft.tv_sec-bef.tv_sec)*1000000000+(aft.tv_nsec-bef.tv_nsec);
 printf("using %ld ns\n", diff);
 return 0;
}
Thankszhenyu.ren------------------------------------------------------------------????Mathieu Desnoyers <mathieu.desnoyers at efficios.com>?????2015?4?28?(???) 23:47????zhenyu.ren <zhenyu.ren at aliyun.com>????lttng-dev <lttng-dev at lists.lttng.org>????Re: [lttng-dev] UST performance
Hi,
Is your sched_getcpu() system call a vdso too ? This may explain the difference.

Moreover, make sure you #define _LGPL_SOURCE in your benchmark program
before including any lttng ust header. It will inline many functions associated with
tracepoints.

Then, you can try using "perf" to profile the runtime execution of your program
traced by lttng-ust ? This should give us the information we need to investigate the
performance profile.

Thanks,

Mathieu


Hi,dev
? ? About a month ago,I asked a question about how to do time recording for ust event when vdso_clock_gettime not availble on my platform?Glibc too old?.Recently I implemented a lib to analyze vdso in memory and lookuped the symbol vdso_clock_gettime successfully.With this vdso_clock_gettime availble,I get a 16% improvement in time spending per ust event. I.E. I measured the time taked by a event with 10 bytes string :
?no ? vdso_clock_gettime : 0.642us?with vdso_clock_gettime?0.554us
However?Both the numbers are much higher than the following 0.28us(But closed to 0.5us --W/O opt). So what's the difference between UST(0.28us) and UST W/O OPT(0.5us)???


PS:My hardware2 x Xeon E5-2430 ?2.20GHz 100MHz FSB (24 cores)?94.6GB / 96GB 1333MHz DDR3 == 6 x 16GB, 6 x empty
Thankszhenyu.ren


_______________________________________________
lttng-dev mailing list
lttng-dev at lists.lttng.org
http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev



-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20150429/84c72d06/attachment-0001.html>


^ permalink raw reply	[flat|nested] 5+ messages in thread

* [lttng-dev] 答复: UST performance
  2015-04-29  1:31 ` [lttng-dev] 答复: " zhenyu.ren
@ 2015-04-29  2:25   ` Mathieu Desnoyers
  2015-04-29  3:39   ` [lttng-dev] 答复:答复: " zhenyu.ren
  1 sibling, 0 replies; 5+ messages in thread
From: Mathieu Desnoyers @ 2015-04-29  2:25 UTC (permalink / raw)


----- Original Message -----

> Hi,Mathieu

> > Is your sched_getcpu() system call a vdso too

> I use VSYSCALL_ADDR(__NR_vgetcpu) instead sched_getcpu so there is no getcpu
> system calls.

> > make sure you #define _LGPL_SOURCE in your benchmark program

> I do it as you suggested but no difference.

> > Then, you can try using "perf" to profile the runtime execution

> $~/renzhyu/perf record ./sample
> WARNING: Kernel address maps (/proc/{kallsyms,modules}) are restricted,
> check /proc/sys/kernel/kptr_restrict.

> Samples in kernel functions may not be resolved if a suitable vmlinux
> file is not found in the buildid cache or in the vmlinux path.

> Samples in kernel modules won't be resolved at all.

> If some relocation was applied (e.g. kexec) symbols may be misresolved
> even with a suitable vmlinux or kallsyms file.

> using 5720094251 ns
> [ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 0.221 MB perf.data (~9658 samples) ]

> $~/renzhyu/perf report
> Events: 5K cycles
> 16.82% sample liblttng-ust.so.0.0.0 [.] lttng_event_commit
> 10.55% sample liblttng-ust.so.0.0.0 [.] lttng_event_strcpy
> 10.45% sample [kernel.kallsyms] [k] 0xffffffff8103548a
> 8.16% sample liblttng-ust.so.0.0.0 [.] lttng_event_reserve
> 7.57% sample sample [.] __event_get_size__sample_component___message
> 6.42% sample sample [.] __event_probe__sample_component___message
> 6.24% sample liblttng-ust.so.0.0.0 [.] lttng_write_event_header
> 5.40% sample sample [.] _rcu_read_lock_update
> 5.35% sample sample [.] _rcu_read_unlock_bp
> 5.17% sample liburcu-bp.so.2.0.0 [.] rcu_read_unlock_bp
> 4.14% sample ld-2.5.so [.] __tls_get_addr
> 3.38% sample [vdso] [.] 0x7fff8f72e6be
> 3.35% sample sample [.] main
> 1.88% sample sample [.] lib_ring_buffer_ctx_init
> 1.79% sample sample [.] _rcu_read_lock_bp
> 1.20% sample liburcu-bp.so.2.0.0 [.] rcu_read_lock_bp
> 0.66% sample sample [.] lib_ring_buffer_align_ctx
> 0.38% sample sample [.] cds_list_empty
> 0.37% sample sample [.] lib_ring_buffer_align
> 0.35% sample liburcu-bp.so.2.0.0 [.] __tls_get_addr at plt
> 0.28% sample sample [.] __event_get_align__sample_component___message
> 0.09% sample ld-2.5.so [.] do_lookup_

Did you compile your program and the probe provider 
(tp.c) with -O2 ? 

Did you define _LGPL_SOURCE at the top of both files ? 
(the code and the probe provider) 

I tried your sample.c program here: 

CPU: 
Intel(R) Core(TM) i7-4600U CPU @ 2.10GHz 
This is within a virtual machine. 

And I get 302 ns/event (total: 3019987815ns exec time) 

I see that in the numbers you provided in your earlier email, 
you talk about "us" (microseconds), did you actually mean 
"ns" (nanoseconds) ? 

I enabled tracing this way: 

lttng create --snapshot 
lttng enable-event -u -a 
lttng start 

Thoughts ? 

Thanks, 

Mathieu 

> The symbol 0xffffffff8103548a is in native_write_msr_safe,I don't know what
> the function is and why that kernel function can be TOP 3.
> ffffffff81035480 <native_write_msr_safe>:
> ffffffff81035480: 55 push %rbp
> ffffffff81035481: 89 f9 mov %edi,%ecx
> ffffffff81035483: 89 f0 mov %esi,%eax
> ffffffff81035485: 48 89 e5 mov %rsp,%rbp
> ffffffff81035488: 0f 30 wrmsr
> ffffffff8103548a: 31 c0 xor %eax,%eax
> ffffffff8103548c: c9 leaveq
> ffffffff8103548d: c3 retq
> ffffffff8103548e: 66 90 xchg %ax,%ax

> PS:my sample.c

> #include <time.h>
> #include <unistd.h>
> #include <stdio.h>
> #define _LGPL_SOURCE
> #define TRACEPOINT_DEFINE
> #include "sample_component_provider.h"

> #define NUM 10000000
> int main(int argc, char **argv)
> {
> int i = 0;
> struct timespec bef,aft;
> long diff;
> clock_gettime(CLOCK_MONOTONIC,&bef);
> for (i = 0; i < NUM; i++) {
> tracepoint(sample_component, message, "HelloWorld");
> }
> clock_gettime(CLOCK_MONOTONIC,&aft);
> diff = (aft.tv_sec-bef.tv_sec)*1000000000+(aft.tv_nsec-bef.tv_nsec);
> printf("using %ld ns\n", diff);
> return 0;
> }

> Thanks
> zhenyu.ren

> > ------------------------------------------------------------------
> 
> > ????Mathieu Desnoyers <mathieu.desnoyers at efficios.com>
> 
> > ?????2015?4?28?(???) 23:47
> 
> > ????zhenyu.ren <zhenyu.ren at aliyun.com>
> 
> > ? ??lttng-dev <lttng-dev at lists.lttng.org>
> 
> > ? ??Re: [lttng-dev] UST performance
> 

> > Hi,
> 

> > Is your sched_getcpu() system call a vdso too ? This may explain the
> > difference.
> 

> > Moreover, make sure you #define _LGPL_SOURCE in your benchmark program
> 
> > before including any lttng ust header. It will inline many functions
> > associated with
> 
> > tracepoints.
> 

> > Then, you can try using "perf" to profile the runtime execution of your
> > program
> 
> > traced by lttng-ust ? This should give us the information we need to
> > investigate the
> 
> > performance profile.
> 

> > Thanks,
> 

> > Mathieu
> 

> > ----- Original Message -----
> 

> > > Hi,dev
> > 
> 

> > > About a month ago,I asked a question about how to do time recording for
> > > ust
> > > event when vdso_clock_gettime not availble on my platform?Glibc too
> > > old?.Recently I implemented a lib to analyze vdso in memory and lookuped
> > > the
> > > symbol vdso_clock_gettime successfully.With this vdso_clock_gettime
> > > availble,I get a 16% improvement in time spending per ust event. I.E. I
> > > measured the time taked by a event with 10 bytes string :
> > 
> 

> > > no vdso_clock_gettime : 0.642us
> > 
> 
> > > with vdso_clock_gettime?0.554us
> > 
> 

> > > However?Both the numbers are much higher than the following 0.28us(But
> > > closed
> > > to 0.5us --W/O opt). So what's the difference between UST(0.28us) and UST
> > > W/O OPT(0.5us)??
> > 
> 

> > > PS:My hardware
> > 
> 
> > > 2 x Xeon E5-2430 2.20GHz 100MHz FSB (24 cores) 94.6GB / 96GB 1333MHz DDR3
> > > ==
> > > 6 x 16GB, 6 x empty
> > 
> 

> > > Thanks
> > 
> 
> > > zhenyu.ren
> > 
> 

> > > _______________________________________________
> > 
> 
> > > lttng-dev mailing list
> > 
> 
> > > lttng-dev at lists.lttng.org
> > 
> 
> > > http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
> > 
> 

> > --
> 
> > Mathieu Desnoyers
> 
> > EfficiOS Inc.
> 
> > http://www.efficios.com
> 

-- 
Mathieu Desnoyers 
EfficiOS Inc. 
http://www.efficios.com 
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20150429/a5cdc5a0/attachment-0001.html>


^ permalink raw reply	[flat|nested] 5+ messages in thread

* [lttng-dev] 答复:答复: UST performance
  2015-04-29  1:31 ` [lttng-dev] 答复: " zhenyu.ren
  2015-04-29  2:25   ` Mathieu Desnoyers
@ 2015-04-29  3:39   ` zhenyu.ren
  1 sibling, 0 replies; 5+ messages in thread
From: zhenyu.ren @ 2015-04-29  3:39 UTC (permalink / raw)


Oh,My mistake. I am not using -O2 (I copied the Makefile from lttng-ust-2.6.0/doc/examples/easy-ust/Makefile :) ). When compiled with -O2, I get a 0.454us/event(10M events total?4548921074 ns).>Did you define _LGPL_SOURCE at the top of both files ? (the code and the probe provider)? Yes,I did define it all of the files(provider(.h/.c) and sample.c)
>I see that in the numbers you provided in your earlier email, you talk about "us" (microseconds), did you actually mean "ns" (nanoseconds) ?? Yes,I use "us", say? 0.554us , 0.28us, 0.5us and the latest 0.454us . If use "ns",they are 554ns, 280ns,500ns,454ns ,it seems no mistake here?My CPU is?2 x Xeon E5-2420 ?1.90GHz , OS: RHEL6,2.6.32-220?Maybe the fact my ust event slower than yours is due to the CPU ability,I am not sure about that. Does you perf report show something like? native_write_msr_safe?Thankszhenyu.ren------------------------------------------------------------------????Mathieu Desnoyers <mathieu.desnoyers at efficios.com>?????2015?4?29?(???) 10:25????zhenyu.ren <zhenyu.ren at aliyun.com>????lttng-dev <lttng-dev at lists.lttng.org>????Re: ???[lttng-dev] UST performance
Hi,Mathieu
> Is your sched_getcpu() system call a vdso too
? ?I use?VSYSCALL_ADDR(__NR_vgetcpu) instead sched_getcpu so there is no getcpu system calls.
> make sure you #define _LGPL_SOURCE in your benchmark program
? ?I do it as you suggested but no difference.

> Then, you can try using "perf" to profile the runtime execution?
$~/renzhyu/perf record ./sample
WARNING: Kernel address maps (/proc/{kallsyms,modules}) are restricted,
check /proc/sys/kernel/kptr_restrict.

Samples in kernel functions may not be resolved if a suitable vmlinux
file is not found in the buildid cache or in the vmlinux path.

Samples in kernel modules won't be resolved at all.

If some relocation was applied (e.g. kexec) symbols may be misresolved
even with a suitable vmlinux or kallsyms file.


using 5720094251 ns
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.221 MB perf.data (~9658 samples) ]


$~/renzhyu/perf report
Events: 5K cycles
16.82% sample liblttng-ust.so.0.0.0 [.] lttng_event_commit10.55% sample liblttng-ust.so.0.0.0 [.] lttng_event_strcpy10.45% sample [kernel.kallsyms] [k] 0xffffffff8103548a8.16% sample liblttng-ust.so.0.0.0 [.] lttng_event_reserve7.57% sample sample [.] __event_get_size__sample_component___message6.42% sample sample [.] __event_probe__sample_component___message6.24% sample liblttng-ust.so.0.0.0 [.] lttng_write_event_header5.40% sample sample [.] _rcu_read_lock_update5.35% sample sample [.] _rcu_read_unlock_bp5.17% sample liburcu-bp.so.2.0.0 [.] rcu_read_unlock_bp4.14% sample ld-2.5.so [.] __tls_get_addr3.38% sample [vdso] [.] 0x7fff8f72e6be3.35% sample sample [.] main1.88% sample sample [.] lib_ring_buffer_ctx_init1.79% sample sample [.] _rcu_read_lock_bp1.20% sample liburcu-bp.so.2.0.0 [.] rcu_read_lock_bp0.66% sample sample [.] lib_ring_buffer_align_ctx0.38% sample sample [.] cds_list_empty0.37% sample sample [.] lib_ring_buffer_align0.35% sample liburcu-bp.so.2.0.0 [.] __tls_get_addr at plt0.28% sample sample [.] __event_get_align__sample_component___message0.09% sample ld-2.5.so [.] do_lookup_Did you compile your program and the probe provider
(tp.c) with -O2 ?

Did you define _LGPL_SOURCE at the top of both files ?
(the code and the probe provider)

I tried your sample.c program here:

CPU:
Intel(R) Core(TM) i7-4600U CPU @ 2.10GHzThis is within a virtual machine.

And I get 302 ns/event (total: 3019987815ns exec time)

I see that in the numbers you provided in your earlier email,
you talk about "us" (microseconds), did you actually mean"ns" (nanoseconds) ?

I enabled tracing this way:

lttng create --snapshot
lttng enable-event -u -a
lttng start

Thoughts ?

Thanks,

Mathieu
The symbol? 0xffffffff8103548a is in?native_write_msr_safe,I don't know what the function is and why that kernel function can be TOP 3.ffffffff81035480 <native_write_msr_safe>:
ffffffff81035480: 55 push %rbp
ffffffff81035481: 89 f9 mov %edi,%ecx
ffffffff81035483: 89 f0 mov %esi,%eax
ffffffff81035485: 48 89 e5 mov %rsp,%rbp
ffffffff81035488: 0f 30 wrmsr
ffffffff8103548a: 31 c0 xor %eax,%eax
ffffffff8103548c: c9 leaveq
ffffffff8103548d: c3 retq
ffffffff8103548e: 66 90 xchg %ax,%ax
PS:my sample.c
#include <time.h>
#include <unistd.h>
#include <stdio.h>
#define _LGPL_SOURCE
#define TRACEPOINT_DEFINE
#include "sample_component_provider.h"

#define NUM 10000000
int main(int argc, char **argv)
{
 int i = 0;
 struct timespec bef,aft;
 long diff;
 clock_gettime(CLOCK_MONOTONIC,&bef);
 for (i = 0; i < NUM; i++) {
tracepoint(sample_component, message, "HelloWorld");
 }
 clock_gettime(CLOCK_MONOTONIC,&aft);
 diff = (aft.tv_sec-bef.tv_sec)*1000000000+(aft.tv_nsec-bef.tv_nsec);
 printf("using %ld ns\n", diff);
 return 0;
}

Thankszhenyu.ren------------------------------------------------------------------????Mathieu Desnoyers <mathieu.desnoyers at efficios.com>?????2015?4?28?(???) 23:47????zhenyu.ren <zhenyu.ren at aliyun.com>????lttng-dev <lttng-dev at lists.lttng.org>????Re: [lttng-dev] UST performance
Hi,
Is your sched_getcpu() system call a vdso too ? This may explain the difference.

Moreover, make sure you #define _LGPL_SOURCE in your benchmark program
before including any lttng ust header. It will inline many functions associated with
tracepoints.

Then, you can try using "perf" to profile the runtime execution of your program
traced by lttng-ust ? This should give us the information we need to investigate the
performance profile.

Thanks,

Mathieu


Hi,dev
? ? About a month ago,I asked a question about how to do time recording for ust event when vdso_clock_gettime not availble on my platform?Glibc too old?.Recently I implemented a lib to analyze vdso in memory and lookuped the symbol vdso_clock_gettime successfully.With this vdso_clock_gettime availble,I get a 16% improvement in time spending per ust event. I.E. I measured the time taked by a event with 10 bytes string :
?no ? vdso_clock_gettime : 0.642us?with vdso_clock_gettime?0.554us
However?Both the numbers are much higher than the following 0.28us(But closed to 0.5us --W/O opt). So what's the difference between UST(0.28us) and UST W/O OPT(0.5us)???



PS:My hardware2 x Xeon E5-2430 ?2.20GHz 100MHz FSB (24 cores)?94.6GB / 96GB 1333MHz DDR3 == 6 x 16GB, 6 x empty
Thankszhenyu.ren



_______________________________________________
lttng-dev mailing list
lttng-dev at lists.lttng.org
http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev



-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com



-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20150429/4e24ceec/attachment-0001.html>


^ permalink raw reply	[flat|nested] 5+ messages in thread

end of thread, other threads:[~2015-04-29  3:39 UTC | newest]

Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2015-04-27  3:01 [lttng-dev] UST performance zhenyu.ren
2015-04-28 15:47 ` Mathieu Desnoyers
2015-04-29  1:31 ` [lttng-dev] 答复: " zhenyu.ren
2015-04-29  2:25   ` Mathieu Desnoyers
2015-04-29  3:39   ` [lttng-dev] 答复:答复: " zhenyu.ren

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox