test_perf_event: large value for CPU cycles


riya
 

Hi,

I'm running tests/python/test_perf_event.py. I changed the following
to print out 'cpu cycles' value and increased the number of times
'getuid()' syscall is executed:

diff --git a/tests/python/test_perf_event.py b/tests/python/test_perf_event.py
index 224faff..bd9e268 100755
--- a/tests/python/test_perf_event.py
+++ b/tests/python/test_perf_event.py
@@ -18,12 +18,14 @@ BPF_HISTOGRAM(dist);
int kprobe__sys_getuid(void *ctx) {
u32 cpu = bpf_get_smp_processor_id();
u64 val = cnt1.perf_read(cpu);
+ bpf_trace_printk("entry: cycls: %llu\\n", val);
prev.update(&cpu, &val);
return 0;
}
int kretprobe__sys_getuid(void *ctx) {
u32 cpu = bpf_get_smp_processor_id();
u64 val = cnt1.perf_read(cpu);
+ bpf_trace_printk("exit: cycls: %llu\\n", val);
u64 *prevp = prev.lookup(&cpu);
if (prevp)
dist.increment(bpf_log2l(val - *prevp));
@@ -39,7 +41,7 @@ int kretprobe__sys_getuid(void *ctx) {
if ctypes.get_errno() == 2:
raise self.skipTest("hardware events unsupported")
raise
- for i in range(0, 100):
+ for i in range(0, 10000000):
os.getuid()
b["dist"].print_log2_hist()


With this change, I sometimes see very high value for 'CPU cycles'
counter (see output below)

Is this expected? Please let me know. Thanks!

I've already disabled NMI by doing sudo sh -c "echo 0 >
/proc/sys/kernel/nmi_watchdog"

sudo-8580 [006] d... 10746.773075: : entry: cycls: 1874922986
sudo-8580 [006] d... 10746.773092: : exit: cycls: 1874922986

sudo-8580 [001] d... 10746.778428: : entry: cycls: 144504920
sudo-8580 [001] d... 10746.778459: : exit: cycls: 144504920

sudo-8580 [001] d... 10746.778588: : entry: cycls: 144597669
sudo-8580 [001] d... 10746.778598: : exit: cycls: 144597669

sh-8581 [007] d... 10746.779968: : entry: cycls:
18446744071909310443
sh-8581 [007] d... 10746.779981: : exit: cycls:
18446744071909310443

sudo-8580 [000] d... 10746.780445: : entry: cycls:
18446744072592498664
sudo-8580 [000] d... 10746.780459: : exit: cycls:
18446744072592498664

sshd-8679 [001] d... 10749.599000: : entry: cycls: 173580086
sshd-8679 [001] d... 10749.599017: : exit: cycls: 173580086

sshd-8679 [001] d... 10749.641906: : entry: cycls: 230568964
sshd-8679 [001] d... 10749.641916: : exit: cycls: 230568964

sshd-8679 [001] d... 10749.641921: : entry: cycls: 230571582
sshd-8679 [001] d... 10749.641922: : exit: cycls: 230571582

sshd-8679 [001] d... 10749.641926: : entry: cycls: 230573602
sshd-8679 [001] d... 10749.641927: : exit: cycls: 230573602

sshd-8679 [001] d... 10749.641930: : entry: cycls: 230575185
sshd-8679 [001] d... 10749.641931: : exit: cycls: 230575185

sshd-8679 [001] d... 10749.642585: : entry: cycls: 231016394
sshd-8679 [001] d... 10749.642594: : exit: cycls: 231016394

sshd-8679 [001] d... 10749.643903: : entry: cycls: 232919009
sshd-8679 [001] d... 10749.643911: : exit: cycls: 232919009

sshd-8679 [001] d... 10749.644015: : entry: cycls: 233038255
sshd-8679 [001] d... 10749.644022: : exit: cycls: 233038255

sshd-8679 [001] d... 10749.644660: : entry: cycls: 233943332
sshd-8679 [001] d... 10749.644667: : exit: cycls: 233943332

sshd-8680 [007] d... 10749.645712: : entry: cycls:
18446744071924982598
sshd-8680 [007] d... 10749.645726: : exit: cycls:
18446744071924982598

sshd-8680 [007] d... 10749.645759: : entry: cycls:
18446744071924986843
sshd-8680 [007] d... 10749.645761: : exit: cycls:
18446744071924986843


riya
 

Looks like its due to sign extension when copied from
perf_event_read_local to BPF userspace.

On Mon, Aug 29, 2016 at 5:12 PM, riya khanna <riyakhanna1983@...> wrote:
Hi,

I'm running tests/python/test_perf_event.py. I changed the following
to print out 'cpu cycles' value and increased the number of times
'getuid()' syscall is executed:

diff --git a/tests/python/test_perf_event.py b/tests/python/test_perf_event.py
index 224faff..bd9e268 100755
--- a/tests/python/test_perf_event.py
+++ b/tests/python/test_perf_event.py
@@ -18,12 +18,14 @@ BPF_HISTOGRAM(dist);
int kprobe__sys_getuid(void *ctx) {
u32 cpu = bpf_get_smp_processor_id();
u64 val = cnt1.perf_read(cpu);
+ bpf_trace_printk("entry: cycls: %llu\\n", val);
prev.update(&cpu, &val);
return 0;
}
int kretprobe__sys_getuid(void *ctx) {
u32 cpu = bpf_get_smp_processor_id();
u64 val = cnt1.perf_read(cpu);
+ bpf_trace_printk("exit: cycls: %llu\\n", val);
u64 *prevp = prev.lookup(&cpu);
if (prevp)
dist.increment(bpf_log2l(val - *prevp));
@@ -39,7 +41,7 @@ int kretprobe__sys_getuid(void *ctx) {
if ctypes.get_errno() == 2:
raise self.skipTest("hardware events unsupported")
raise
- for i in range(0, 100):
+ for i in range(0, 10000000):
os.getuid()
b["dist"].print_log2_hist()


With this change, I sometimes see very high value for 'CPU cycles'
counter (see output below)

Is this expected? Please let me know. Thanks!

I've already disabled NMI by doing sudo sh -c "echo 0 >
/proc/sys/kernel/nmi_watchdog"

sudo-8580 [006] d... 10746.773075: : entry: cycls: 1874922986
sudo-8580 [006] d... 10746.773092: : exit: cycls: 1874922986

sudo-8580 [001] d... 10746.778428: : entry: cycls: 144504920
sudo-8580 [001] d... 10746.778459: : exit: cycls: 144504920

sudo-8580 [001] d... 10746.778588: : entry: cycls: 144597669
sudo-8580 [001] d... 10746.778598: : exit: cycls: 144597669

sh-8581 [007] d... 10746.779968: : entry: cycls:
18446744071909310443
sh-8581 [007] d... 10746.779981: : exit: cycls:
18446744071909310443

sudo-8580 [000] d... 10746.780445: : entry: cycls:
18446744072592498664
sudo-8580 [000] d... 10746.780459: : exit: cycls:
18446744072592498664

sshd-8679 [001] d... 10749.599000: : entry: cycls: 173580086
sshd-8679 [001] d... 10749.599017: : exit: cycls: 173580086

sshd-8679 [001] d... 10749.641906: : entry: cycls: 230568964
sshd-8679 [001] d... 10749.641916: : exit: cycls: 230568964

sshd-8679 [001] d... 10749.641921: : entry: cycls: 230571582
sshd-8679 [001] d... 10749.641922: : exit: cycls: 230571582

sshd-8679 [001] d... 10749.641926: : entry: cycls: 230573602
sshd-8679 [001] d... 10749.641927: : exit: cycls: 230573602

sshd-8679 [001] d... 10749.641930: : entry: cycls: 230575185
sshd-8679 [001] d... 10749.641931: : exit: cycls: 230575185

sshd-8679 [001] d... 10749.642585: : entry: cycls: 231016394
sshd-8679 [001] d... 10749.642594: : exit: cycls: 231016394

sshd-8679 [001] d... 10749.643903: : entry: cycls: 232919009
sshd-8679 [001] d... 10749.643911: : exit: cycls: 232919009

sshd-8679 [001] d... 10749.644015: : entry: cycls: 233038255
sshd-8679 [001] d... 10749.644022: : exit: cycls: 233038255

sshd-8679 [001] d... 10749.644660: : entry: cycls: 233943332
sshd-8679 [001] d... 10749.644667: : exit: cycls: 233943332

sshd-8680 [007] d... 10749.645712: : entry: cycls:
18446744071924982598
sshd-8680 [007] d... 10749.645726: : exit: cycls:
18446744071924982598

sshd-8680 [007] d... 10749.645759: : entry: cycls:
18446744071924986843
sshd-8680 [007] d... 10749.645761: : exit: cycls:
18446744071924986843


riya
 

So the following change fixes the problem:

diff --git a/src/cc/export/helpers.h b/src/cc/export/helpers.h
index a5afa44..c4fbac6 100644
--- a/src/cc/export/helpers.h
+++ b/src/cc/export/helpers.h
@@ -166,7 +166,7 @@ static int (*bpf_skb_get_tunnel_key)(void *ctx,
void *to, u32 size, u64 flags) =
(void *) BPF_FUNC_skb_get_tunnel_key;
static int (*bpf_skb_set_tunnel_key)(void *ctx, void *from, u32 size,
u64 flags) =
(void *) BPF_FUNC_skb_set_tunnel_key;
-static int (*bpf_perf_event_read)(void *map, u32 index) =
+static u64 (*bpf_perf_event_read)(void *map, u32 index) =
(void *) BPF_FUNC_perf_event_read;
static int (*bpf_redirect)(int ifindex, u32 flags) =
(void *) BPF_FUNC_redirect;

On Tue, Aug 30, 2016 at 12:22 AM, riya khanna <riyakhanna1983@...> wrote:
Looks like its due to sign extension when copied from
perf_event_read_local to BPF userspace.


On Mon, Aug 29, 2016 at 5:12 PM, riya khanna <riyakhanna1983@...> wrote:
Hi,

I'm running tests/python/test_perf_event.py. I changed the following
to print out 'cpu cycles' value and increased the number of times
'getuid()' syscall is executed:

diff --git a/tests/python/test_perf_event.py b/tests/python/test_perf_event.py
index 224faff..bd9e268 100755
--- a/tests/python/test_perf_event.py
+++ b/tests/python/test_perf_event.py
@@ -18,12 +18,14 @@ BPF_HISTOGRAM(dist);
int kprobe__sys_getuid(void *ctx) {
u32 cpu = bpf_get_smp_processor_id();
u64 val = cnt1.perf_read(cpu);
+ bpf_trace_printk("entry: cycls: %llu\\n", val);
prev.update(&cpu, &val);
return 0;
}
int kretprobe__sys_getuid(void *ctx) {
u32 cpu = bpf_get_smp_processor_id();
u64 val = cnt1.perf_read(cpu);
+ bpf_trace_printk("exit: cycls: %llu\\n", val);
u64 *prevp = prev.lookup(&cpu);
if (prevp)
dist.increment(bpf_log2l(val - *prevp));
@@ -39,7 +41,7 @@ int kretprobe__sys_getuid(void *ctx) {
if ctypes.get_errno() == 2:
raise self.skipTest("hardware events unsupported")
raise
- for i in range(0, 100):
+ for i in range(0, 10000000):
os.getuid()
b["dist"].print_log2_hist()


With this change, I sometimes see very high value for 'CPU cycles'
counter (see output below)

Is this expected? Please let me know. Thanks!

I've already disabled NMI by doing sudo sh -c "echo 0 >
/proc/sys/kernel/nmi_watchdog"

sudo-8580 [006] d... 10746.773075: : entry: cycls: 1874922986
sudo-8580 [006] d... 10746.773092: : exit: cycls: 1874922986

sudo-8580 [001] d... 10746.778428: : entry: cycls: 144504920
sudo-8580 [001] d... 10746.778459: : exit: cycls: 144504920

sudo-8580 [001] d... 10746.778588: : entry: cycls: 144597669
sudo-8580 [001] d... 10746.778598: : exit: cycls: 144597669

sh-8581 [007] d... 10746.779968: : entry: cycls:
18446744071909310443
sh-8581 [007] d... 10746.779981: : exit: cycls:
18446744071909310443

sudo-8580 [000] d... 10746.780445: : entry: cycls:
18446744072592498664
sudo-8580 [000] d... 10746.780459: : exit: cycls:
18446744072592498664

sshd-8679 [001] d... 10749.599000: : entry: cycls: 173580086
sshd-8679 [001] d... 10749.599017: : exit: cycls: 173580086

sshd-8679 [001] d... 10749.641906: : entry: cycls: 230568964
sshd-8679 [001] d... 10749.641916: : exit: cycls: 230568964

sshd-8679 [001] d... 10749.641921: : entry: cycls: 230571582
sshd-8679 [001] d... 10749.641922: : exit: cycls: 230571582

sshd-8679 [001] d... 10749.641926: : entry: cycls: 230573602
sshd-8679 [001] d... 10749.641927: : exit: cycls: 230573602

sshd-8679 [001] d... 10749.641930: : entry: cycls: 230575185
sshd-8679 [001] d... 10749.641931: : exit: cycls: 230575185

sshd-8679 [001] d... 10749.642585: : entry: cycls: 231016394
sshd-8679 [001] d... 10749.642594: : exit: cycls: 231016394

sshd-8679 [001] d... 10749.643903: : entry: cycls: 232919009
sshd-8679 [001] d... 10749.643911: : exit: cycls: 232919009

sshd-8679 [001] d... 10749.644015: : entry: cycls: 233038255
sshd-8679 [001] d... 10749.644022: : exit: cycls: 233038255

sshd-8679 [001] d... 10749.644660: : entry: cycls: 233943332
sshd-8679 [001] d... 10749.644667: : exit: cycls: 233943332

sshd-8680 [007] d... 10749.645712: : entry: cycls:
18446744071924982598
sshd-8680 [007] d... 10749.645726: : exit: cycls:
18446744071924982598

sshd-8680 [007] d... 10749.645759: : entry: cycls:
18446744071924986843
sshd-8680 [007] d... 10749.645761: : exit: cycls:
18446744071924986843