Question about the performance of LTTng-UST

Question about the performance of LTTng-UST

[changz]

[-- Attachment #1.1: Type: text/plain, Size: 673 bytes --]

Hi All,

I wrote a very simple test code like this:

         for (i = 0; i < 0xffffff; i++) {
                 tracepoint(sample_component, message, "This is a 
performance test:","main",i);
         }

And then I started lttng and ran the test code:
time  ./test
real0m16.120s
user0m8.280s
sys0m7.789s

 From the result of time output, you can see sys time is about half of 
the whole run-time. I wondered where the cost was from.
So I used strace to track it and found amount of system calls (get_cpu 
and clock_gettime) during the run-time.
I know these system calls are used for ring-buffer. But I just think the 
cost is a little heavy.

What do you think?

BR
Zheng

[-- Attachment #1.2: Type: text/html, Size: 8052 bytes --]

[-- Attachment #2: Type: text/plain, Size: 155 bytes --]

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

Re: Question about the performance of LTTng-UST

[changz]

On 7/25/2012 21:29 PM, Mathieu Desnoyers wrote:
> * changz (zheng.chang@emc.com) wrote:
>> Hi All,
>>
>> I wrote a very simple test code like this:
>>
>>          for (i = 0; i < 0xffffff; i++) {
>>                  tracepoint(sample_component, message, "This is a
>> performance test:","main",i);
>>          }
>>
>> And then I started lttng and ran the test code:
>> time  ./test
>> real0m16.120s
> This is indeed very high (96 microsecond per event). There is something
> wrong with your system (what architecture, kernel version do you use ?
> Getting you dmesg log would be useful too, especially to find out which
> clock source your kernel uses. Also, are you in a virtualized
> environment ? If yes, which ?)
Mathieu,

My OS is a X86 linux kernel 2.6.38 running on Vmware workstation for 
windows.
linux-gate.so was linked to my test code.
And here is a message found in dmesg output:
[2.228750] Switching to clocksource tsc

I found a benchmark data about vmware system call. It says the 
virtualization can cause ten times delay than it runs on host directly.
So I guess that's the reason why my test code ran slowly.

Could you provide more info about the impact introduced by different 
clock sources?

Thanks
Zheng
>> user0m8.280s
>> sys0m7.789s
>>
>>  From the result of time output, you can see sys time is about half of
>> the whole run-time. I wondered where the cost was from.
>> So I used strace to track it and found amount of system calls (get_cpu
>> and clock_gettime) during the run-time.
>> I know these system calls are used for ring-buffer. But I just think the
>> cost is a little heavy.
>>
>> What do you think?
> On x86, these calls are done through a kernel vDSO. Having those showing
> up in strace tells me that you kernel might be quite old, or use use an
> architecture that implements those as standard system calls rather than
> vDSO.
>
> Thanks,
>
> Mathieu
>
>> BR
>> Zheng
>> _______________________________________________
>> lttng-dev mailing list
>> lttng-dev@lists.lttng.org
>> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
>

Re: Question about the performance of LTTng-UST

[Mathieu Desnoyers]

* changz (zheng.chang@emc.com) wrote:
> Hi All,
>
> I wrote a very simple test code like this:
>
>         for (i = 0; i < 0xffffff; i++) {
>                 tracepoint(sample_component, message, "This is a  
> performance test:","main",i);
>         }
>
> And then I started lttng and ran the test code:
> time  ./test
> real0m16.120s

This is indeed very high (96 microsecond per event). There is something
wrong with your system (what architecture, kernel version do you use ?
Getting you dmesg log would be useful too, especially to find out which
clock source your kernel uses. Also, are you in a virtualized
environment ? If yes, which ?)

> user0m8.280s
> sys0m7.789s
>
> From the result of time output, you can see sys time is about half of  
> the whole run-time. I wondered where the cost was from.
> So I used strace to track it and found amount of system calls (get_cpu  
> and clock_gettime) during the run-time.
> I know these system calls are used for ring-buffer. But I just think the  
> cost is a little heavy.
>
> What do you think?

On x86, these calls are done through a kernel vDSO. Having those showing
up in strace tells me that you kernel might be quite old, or use use an
architecture that implements those as standard system calls rather than
vDSO.

Thanks,

Mathieu

>
> BR
> Zheng

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


-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com