Question about the performance of LTTng-UST

DISCUSSION Mathieu Desnoyers 2 participants 2 messages Jul 25, 2012 – Jul 26, 2012 2 messages not in the archive

lore

Share & tools

lore

Mathieu Desnoyers

author

2012-07-25 13:29 UTC #1 lore raw

In reply to a message not in the archive

Quoted 4 lines · * changz ([email protected]) wrote:

Hi All,
I wrote a very simple test code like this:

Quoted 8 lines

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 ?)

Quoted 11 lines

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

Quoted 8 lines

BR
Zheng
_______________________________________________
lttng-dev mailing list
[email protected]
http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Signature · 4 lines

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

changz

2012-07-26 04:54 UTC #3 lore raw

In reply to a message not in the archive

Quoted 10 lines · Mathieu Desnoyers

Quoted 9 lines · * changz ([email protected]) 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);
         }

Quoted 8 lines

Quoted 3 lines
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

Quoted 27 lines

Quoted 11 lines
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
Quoted 6 lines
BR
Zheng
_______________________________________________
lttng-dev mailing list
[email protected]
http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev