LTTng » LTTng-UST

FYI, the reports given by "perf record appname" and then "perf annotate" and "perf report" would be more helpful here: they provide a breakdown (per function) of the most used functions.

Regarding Perf tool, we have problems with it on our target, it doesn't work correct and it won't record any samples. So I cant provide 'perf report' and 'perf annotate'. If we'll get it working any time soon I'll provide the needed info.

I tested commits suggested and I got the same results as you did. The time did not differ as previously between these commits. See below,

master:

root@du1:~# time ./ltt-test-2.2.0 -l 1000000 -t 1
Benchmark test starts now...
Time it took to loop 1000000 times : 8 s 678479180 ns | [8678 ns per tp]

real 0m10.750s
user 0m7.924s
sys 0m0.436s
root@du1:~# time ./ltt-test-2.2.0 -l 1000000 -t 1
Benchmark test starts now...
Time it took to loop 1000000 times : 9 s 70089336 ns | [9070 ns per tp]

real 0m11.108s
user 0m8.152s
sys 0m0.464s
root@du1:~# time ./ltt-test-2.2.0 -l 1000000 -t 1
Benchmark test starts now...
Time it took to loop 1000000 times : 8 s 682388555 ns | [8682 ns per tp]

real 0m10.722s
user 0m7.976s
sys 0m0.408s

2.1-stable:

root@du1:~# time ./ltt-test-2.1-s -l 1000000 -t 1
Benchmark test starts now...
Time it took to loop 1000000 times : 9 s 258012743 ns | [ 9258 ns per tp ]

real 0m11.290s
user 0m8.424s
sys 0m0.556s
root@du1:~# time ./ltt-test-2.1-s -l 1000000 -t 1
Benchmark test starts now...
Time it took to loop 1000000 times : 9 s 465164986 ns | [ 9465 ns per tp ]

real 0m11.495s
user 0m8.392s
sys 0m0.456s

Going back to the problem though, it seems that the difference can now be narrowed down to just a few commits, between tags stable-2.1 and v2.1.2 in UST the difference in time is still visible, as before.

Can you compare these 2 commits?

Ust:
stable-2.1 : 75ecf151e7571c682bb302e8d2206e22bdaa62b2
v2.1.2 : 3f7a0876566a432ad2cc2b27a2725641e36da92d
(other commit id's are same as in initial mail, )

stable-2.1:

root@du1:~# time ./ltt-test-2.1-s -l 1000000 -t 1
Benchmark test starts now...
Time it took to loop 1000000 times : 8 s 958886297 ns | [ 8958 ns per tp ]

real 0m10.990s
user 0m8.240s
sys 0m0.416s
root@du1:~# time ./ltt-test-2.1-s -l 1000000 -t 1
Benchmark test starts now...
Time it took to loop 1000000 times : 9 s 405790878 ns | [ 9405 ns per tp ]

real 0m11.436s
user 0m8.428s
sys 0m0.508s

v2.1.2:

root@du1:~# time ./ltt-test-2.1-s -l 1000000 -t 1
Benchmark test starts now...
Time it took to loop 1000000 times : 3 s 633527800 ns | [ 3633 ns per tp ]

real 0m5.661s
user 0m3.188s
sys 0m0.304s
root@du1:~# time ./ltt-test-2.1-s -l 1000000 -t 1
Benchmark test starts now...
Time it took to loop 1000000 times : 3 s 706052203 ns | [ 3706 ns per tp ]

real 0m5.733s
user 0m3.172s
sys 0m0.384s

Thanks,
Stanislav

> Can you compare these 2 commits?
> 
> Ust:
> stable-2.1 : 75ecf151e7571c682bb302e8d2206e22bdaa62b2
> v2.1.2 : 3f7a0876566a432ad2cc2b27a2725641e36da92d
> (other commit id's are same as in initial mail, )

On my Intel i7:

commit 75ecf151e7571c682bb302e8d2206e22bdaa62b2 (stable-2.1)

compudj@thinkos:~/git/lttng-ust/tests/hello$ (git:(75ecf15...) $)> time ./hello Hello, World!
Tracing...  done.

real    0m1.082s
user    0m0.736s
sys    0m0.316s
compudj@thinkos:~/git/lttng-ust/tests/hello$ (git:(75ecf15...) $)> time ./hello Hello, World!
Tracing...  done.

real    0m1.006s
user    0m0.712s
sys    0m0.276s
compudj@thinkos:~/git/lttng-ust/tests/hello$ (git:(75ecf15...) $)> time ./hello Hello, World!
Tracing...  done.

real    0m1.102s
user    0m0.748s
sys    0m0.332s

commit 3f7a0876566a432ad2cc2b27a2725641e36da92d (v2.1.2)

compudj@thinkos:~/git/lttng-ust/tests/hello$ (git:(v2.1.2) $)> time ./hello 
Hello, World!
Tracing...  done.

real    0m1.032s
user    0m0.616s
sys    0m0.396s
compudj@thinkos:~/git/lttng-ust/tests/hello$ (git:(v2.1.2) $)> time ./hello 
Hello, World!
Tracing...  done.

real    0m1.132s
user    0m0.788s
sys    0m0.320s
compudj@thinkos:~/git/lttng-ust/tests/hello$ (git:(v2.1.2) $)> time ./hello 
Hello, World!
Tracing...  done.

real    0m1.107s
user    0m0.764s
sys    0m0.324s

No significant difference between the two.

I suspect it could be your test program. Can you attach it to the bug
report ?

The only commit that could possibly have a performance impact would be
the following, but I don't quite see how it can be an issue:

commit 88b66998c135f5df377a1933f17fa6652c05eeae
Author: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Date:   Tue Mar 26 08:18:18 2013 -0400

    Fix: _LGPL_SOURCE rcu dereference fix

    Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>

diff --git a/include/lttng/tracepoint-rcu.h
b/include/lttng/tracepoint-rcu.h
index bae1279..ee936ff 100644
--- a/include/lttng/tracepoint-rcu.h
+++ b/include/lttng/tracepoint-rcu.h
@@ -31,7 +31,7 @@

 #define tp_rcu_read_lock_bp    rcu_read_lock_bp
 #define tp_rcu_read_unlock_bp  rcu_read_unlock_bp
-#define tp_rcu_dereference_bp  rcu_dereference_bp
+#define tp_rcu_dereference_bp  rcu_dereference
 #define TP_RCU_LINK_TEST()     1

 #else  /* _LGPL_SOURCE */

Thanks,

Mathieu

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

Hi Stanislav,

I've tried your test program in sample.tgz, and got:

compudj@thinkos:~/test/cpp/sample$ ./ltt-test -l -t
Benchmark test starts now...
Floating point exception

Looking at the code, it seems that:

struct timespec average(struct timespec *av, int s)
{
  ...
  temp.tv_nsec = (temp.tv_nsec + temp.tv_sec * 1000000000) / s;
  ...
}

is probably the culprit. Also, you might want to reconsider these calculations in the light of the tv_nsec type, which is possibly a 32-bit integer on your architecture. And I don't quite get what this line is trying to achieve.

Thanks,

Mathieu

Hi Stanislav,

I tried you program on two Intel machines without seeing different results between the two set of commits you tried.

It stays around 700ns on my i7 laptop, and it's about 1360ns on an Intel Xeon 2.0GHz.

Machine cpuinfo:

processor    : 0
vendor_id    : GenuineIntel
cpu family    : 6
model        : 58
model name    : Intel(R) Core(TM) i7-3520M CPU @ 2.90GHz
stepping    : 9
microcode    : 0x17
cpu MHz        : 1200.000
cache size    : 4096 KB
physical id    : 0
siblings    : 4
core id        : 0
cpu cores    : 2
apicid        : 0
initial apicid    : 0
fpu        : yes
fpu_exception    : yes
cpuid level    : 13
wp        : yes
flags        : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 cx16 xtpr pdcm pcid sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm ida arat epb xsaveopt pln pts dtherm tpr_shadow vnmi flexpriority ept vpid fsgsbase smep erms
bogomips    : 5786.71
clflush size    : 64
cache_alignment    : 64
address sizes    : 36 bits physical, 48 bits virtual
power management:

processor    : 0
vendor_id    : GenuineIntel
cpu family    : 6
model        : 23
model name    : Intel(R) Xeon(R) CPU           E5405  @ 2.00GHz
stepping    : 6
microcode    : 0x606
cpu MHz        : 2000.169
cache size    : 6144 KB
physical id    : 0
siblings    : 4
core id        : 0
cpu cores    : 4
apicid        : 0
initial apicid    : 0
fpu        : yes
fpu_exception    : yes
cpuid level    : 10
wp        : yes
flags        : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx lm constant_tsc arch_perfmon pebs bts rep_good nopl aperfmperf pni dtes64 monitor ds_cpl vmx tm2 ssse3 cx16 xtpr pdcm dca sse4_1 lahf_lm dtherm tpr_shadow vnmi flexpriority
bogomips    : 4001.01
clflush size    : 64
cache_alignment    : 64
address sizes    : 38 bits physical, 48 bits virtual
power management:

We have a couple of choices to try to narrow down this regression, but I think that the easiest, considering that I cannot reproduce it here, is that you try to bissect which commit from which project introduced the regression on PowerPC. It would be very much appreciated.

Otherwise, it will have to wait until we get our own PowerPC up and running here.

Thanks,

Mathieu

I see what you mean.
PowerPC is not really our final product HW, we just use it while waiting for real hw to come which is ARM Cortex-A15. We plan to utilize the new hw in the end of august. While waiting for A15 HW I can hopefully if time allows me try to narrow down this to a certain commit. Of course I will also test if this issue exists on A15 later.

So I guess for now we can put this on hold for a while.

Cheers,
Stanislav