ftrace perf: Fixes and speedup

Currently we check sample type for ftrace:function event even if it's not created as sampling event. That prevents creating ftrace_function event in counting mode.

Making sure we check sample types only for sampling events.

Before:

  $ sudo perf stat -e ftrace:function ls
  ...

Performance counter stats for 'ls':

<not supported> ftrace:function

0.001983662 seconds time elapsed

After:

  $ sudo perf stat -e ftrace:function ls
  ...

   Performance counter stats for 'ls':

              44,498      ftrace:function

         0.037534722 seconds time elapsed

Suggested-by Namhyung Kim <[email protected]>

Signed-off-by Jiri Olsa <[email protected]>

We suppress events with attr::exclude_kernel set when the event is generated, so following capture will give no warning but won't produce any data:

  $ sudo perf record -e sched:sched_switch:u ls
  $ sudo /perf script | wc -l
  0

Checking the attr::exclude_(kernel|user) at the event init time and failing right away for tracepoints from uprobes/kprobes and native ones:

  $ sudo perf record -e sched:sched_switch:u ls
  Error:
  The sys_perf_event_open() syscall returned with 22 (Invalid argument) for event (sched:sched_switch).
  /bin/dmesg may provide additional information.
  No CONFIG_PERF_EVENTS=y kernel support configured?

  $ sudo perf record -e probe:sys_read:u ls
  Error:
  The sys_perf_event_open() syscall returned with 22 (Invalid argument) for event (probe:sys_read).
  /bin/dmesg may provide additional information.
  No CONFIG_PERF_EVENTS=y kernel support configured?

  $ ./perf record -e probe_ex:main:k ./ex
  Error:
  The sys_perf_event_open() syscall returned with 22 (Invalid argument) for event (probe_ex:main).
  /bin/dmesg may provide additional information.
  No CONFIG_PERF_EVENTS=y kernel support configured?

Acked-by Namhyung Kim <[email protected]>

Signed-off-by Jiri Olsa <[email protected]>

We suppress events with attr::exclude_kernel set when the event is generated, so following capture will give no warning but won't produce any data:

  $ sudo perf record -e sched:sched_switch:u ls
  $ sudo /perf script | wc -l
  0

Checking the attr::exclude_(kernel|user) at the event init time and failing right away for tracepoints from uprobes/kprobes and native ones:

  $ sudo perf record -e sched:sched_switch:u ls
  Error:
  The sys_perf_event_open() syscall returned with 22 (Invalid argument) for event (sched:sched_switch).
  /bin/dmesg may provide additional information.
  No CONFIG_PERF_EVENTS=y kernel support configured?

  $ sudo perf record -e probe:sys_read:u ls
  Error:
  The sys_perf_event_open() syscall returned with 22 (Invalid argument) for event (probe:sys_read).
  /bin/dmesg may provide additional information.
  No CONFIG_PERF_EVENTS=y kernel support configured?

  $ ./perf record -e probe_ex:main:k ./ex
  Error:
  The sys_perf_event_open() syscall returned with 22 (Invalid argument) for event (probe_ex:main).
  /bin/dmesg may provide additional information.
  No CONFIG_PERF_EVENTS=y kernel support configured?

Quoted 24 lines · Jiri Olsa

We suppress events with attr::exclude_kernel set when the event is generated, so following capture will give no warning but won't produce any data:

  $ sudo perf record -e sched:sched_switch:u ls
  $ sudo /perf script | wc -l
  0

Checking the attr::exclude_(kernel|user) at the event init time and failing right away for tracepoints from uprobes/kprobes and native ones:

  $ sudo perf record -e sched:sched_switch:u ls
  Error:
  The sys_perf_event_open() syscall returned with 22 (Invalid argument) for event (sched:sched_switch).
  /bin/dmesg may provide additional information.
  No CONFIG_PERF_EVENTS=y kernel support configured?

  $ sudo perf record -e probe:sys_read:u ls
  Error:
  The sys_perf_event_open() syscall returned with 22 (Invalid argument) for event (probe:sys_read).
  /bin/dmesg may provide additional information.
  No CONFIG_PERF_EVENTS=y kernel support configured?

Quoted 5 lines

  $ ./perf record -e probe_ex:main:k ./ex
  Error:
  The sys_perf_event_open() syscall returned with 22 (Invalid argument) for event (probe_ex:main).
  /bin/dmesg may provide additional information.
  No CONFIG_PERF_EVENTS=y kernel support configured?

Not sure about this one. The previous behaviour suggests exclude_{user,kernel} is implemented, while the new behaviour says these flags are not implemented, which is a functional regression.

That is, if all events are from kernel space, and we exclude all kernel events, 0 is the right answer not an error.

Sure, with uprobes the situation is currently broken, but this isn't a fix.

Quoted 18 lines · Peter Zijlstra

Quoted 17 lines · Jiri Olsa

We suppress events with attr::exclude_kernel set when the event is generated, so following capture will give no warning but won't produce any data:

  $ sudo perf record -e sched:sched_switch:u ls
  $ sudo /perf script | wc -l
  0

Checking the attr::exclude_(kernel|user) at the event init time and failing right away for tracepoints from uprobes/kprobes and native ones:

  $ sudo perf record -e sched:sched_switch:u ls
  Error:
  The sys_perf_event_open() syscall returned with 22 (Invalid argument) for event (sched:sched_switch).
  /bin/dmesg may provide additional information.
  No CONFIG_PERF_EVENTS=y kernel support configured?

Quoted 3 lines

Not sure about this one. The previous behaviour suggests exclude_{user,kernel} is implemented, while the new behaviour says these flags are not implemented, which is a functional regression.

well I would not expect 'sched:sched_switch:u' to work (be implemented)

and I thought it's better to trigger an error than silently 'produce' no data

Quoted 24 lines · Jiri Olsa

Quoted 22 lines · Peter Zijlstra

Quoted 12 lines · Jiri Olsa

We suppress events with attr::exclude_kernel set when the event is generated, so following capture will give no warning but won't produce any data:

  $ sudo perf record -e sched:sched_switch:u ls
  $ sudo /perf script | wc -l
  0

Checking the attr::exclude_(kernel|user) at the event init time and failing right away for tracepoints from uprobes/kprobes and native ones:

Quoted 5 lines

  $ sudo perf record -e sched:sched_switch:u ls
  Error:
  The sys_perf_event_open() syscall returned with 22 (Invalid argument) for event (sched:sched_switch).
  /bin/dmesg may provide additional information.
  No CONFIG_PERF_EVENTS=y kernel support configured?

Not sure about this one. The previous behaviour suggests exclude_{user,kernel} is implemented, while the new behaviour says these flags are not implemented, which is a functional regression.

Quoted 3 lines

well I would not expect 'sched:sched_switch:u' to work (be implemented)

and I thought it's better to trigger an error than silently 'produce' no data

We're not in the business of protecting people from themselves are we? And if you want to help them, do so in userspace.

And its not like the [uk] flags are hard to implement here.

Quoted 5 lines

Quoted 3 lines

Quoted 3 lines

Quoted 3 lines

  $ sudo perf record -e sched:sched_switch:u ls
  $ sudo /perf script | wc -l
  0

And its not like the [uk] flags are hard to implement here.

sched:sched_switch:u ?

Quoted 7 lines · Jiri Olsa

Quoted 5 lines

Quoted 3 lines

Quoted 3 lines

Quoted 3 lines

  $ sudo perf record -e sched:sched_switch:u ls
  $ sudo /perf script | wc -l
  0

And its not like the [uk] flags are hard to implement here.

sched:sched_switch:u ?

As per the above, its implemented and correct. The answer is 0.

The only problem is that currently it assumes all tracepoint events are from the kernel, and that is wrong for uprobes.

But returning an error is not right, its a valid configuration, a daft one, sure, but not invalid.

Similarly uprobe:foo:k is daft, but broken.

Having following commands running concurrently:

  # perf record -e ftrace:function -a -o krava.data sleep 10
  # perf record -e ftrace:function --filter 'ip == SyS_read' ls

will end up in the latter one to fail on the filter rules and store all functions (in perf.data) as instructed by the first perf record instead of just SyS_read records.

The reason for this is, that tracepoint code by default triggers all events that registered for the tracepoint.

While ftrace:function is special because ftrace_ops itself carries a filter and only the event that owns ftrace_ops is eligible to be triggered.

Fixing this by using ftrace_ops::private value to keep the perf_event pointer. This way we don't need to search for triggered event (as tracepoint handler does) and directly store sample.

Acked-by Namhyung Kim <[email protected]>

Suggested-by Steven Rostedt <[email protected]>

Signed-off-by Jiri Olsa <[email protected]>

Fixing this by using ftrace_ops::private value to keep the perf_event pointer. This way we don't need to search for triggered event (as tracepoint handler does) and directly store sample.

Quoted 4 lines · Jiri Olsa

Fixing this by using ftrace_ops::private value to keep the perf_event pointer. This way we don't need to search for triggered event (as tracepoint handler does) and directly store sample.

container_of(ops, struct perf_event, ftrace_ops) would also have worked, right?

Quoted 8 lines · Peter Zijlstra

Quoted 4 lines · Jiri Olsa

Fixing this by using ftrace_ops::private value to keep the perf_event pointer. This way we don't need to search for triggered event (as tracepoint handler does) and directly store sample.

container_of(ops, struct perf_event, ftrace_ops) would also have worked, right?

yes, I think that would work too

Change __ftrace_hash_rec_update to return true in case we need to update dynamic ftrace call records. It return false in case no update is needed.

Signed-off-by Jiri Olsa <[email protected]>

---
 kernel/trace/ftrace.c | 27 +++++++++++++++++----------
 1 file changed, 17 insertions(+), 10 deletions(-)

kernel/trace/ftrace.c +17 -10

index eca592f977b2..3a9a12215b50 100644
@@ -1610,7 +1610,7 @@ static bool test_rec_ops_needs_regs(struct dyn_ftrace *rec)
 	return  keep_regs;
 }
 
-static void __ftrace_hash_rec_update(struct ftrace_ops *ops,
+static bool __ftrace_hash_rec_update(struct ftrace_ops *ops,
 				     int filter_hash,
 				     bool inc)
 {

@@ -1618,12 +1618,13 @@ static void __ftrace_hash_rec_update(struct ftrace_ops *ops,
 	struct ftrace_hash *other_hash;
 	struct ftrace_page *pg;
 	struct dyn_ftrace *rec;
+	bool update = false;
 	int count = 0;
 	int all = 0;
 
 	/* Only update if the ops has been registered */
 	if (!(ops->flags & FTRACE_OPS_FL_ENABLED))
-		return;
+		return false;
 
 	/*
 	 * In the filter_hash case:

@@ -1650,7 +1651,7 @@ static void __ftrace_hash_rec_update(struct ftrace_ops *ops,
 		 * then there's nothing to do.
 		 */
 		if (ftrace_hash_empty(hash))
-			return;
+			return false;
 	}
 
 	do_for_each_ftrace_rec(pg, rec) {

@@ -1694,7 +1695,7 @@ static void __ftrace_hash_rec_update(struct ftrace_ops *ops,
 		if (inc) {
 			rec->flags++;
 			if (FTRACE_WARN_ON(ftrace_rec_count(rec) == FTRACE_REF_MAX))
-				return;
+				return false;
 
 			/*
 			 * If there's only a single callback registered to a

@@ -1720,7 +1721,7 @@ static void __ftrace_hash_rec_update(struct ftrace_ops *ops,
 				rec->flags |= FTRACE_FL_REGS;
 		} else {
 			if (FTRACE_WARN_ON(ftrace_rec_count(rec) == 0))
-				return;
+				return false;
 			rec->flags--;
 
 			/*

@@ -1753,22 +1754,28 @@ static void __ftrace_hash_rec_update(struct ftrace_ops *ops,
 			 */
 		}
 		count++;
+
+		/* Must match FTRACE_UPDATE_CALLS in ftrace_modify_all_code() */
+		update |= ftrace_test_record(rec, 1) != FTRACE_UPDATE_IGNORE;
+
 		/* Shortcut, if we handled all records, we are done. */
 		if (!all && count == hash->count)
-			return;
+			return update;
 	} while_for_each_ftrace_rec();
+
+	return update;
 }
 
-static void ftrace_hash_rec_disable(struct ftrace_ops *ops,
+static bool ftrace_hash_rec_disable(struct ftrace_ops *ops,
 				    int filter_hash)
 {
-	__ftrace_hash_rec_update(ops, filter_hash, 0);
+	return __ftrace_hash_rec_update(ops, filter_hash, 0);
 }
 
-static void ftrace_hash_rec_enable(struct ftrace_ops *ops,
+static bool ftrace_hash_rec_enable(struct ftrace_ops *ops,
 				   int filter_hash)
 {
-	__ftrace_hash_rec_update(ops, filter_hash, 1);
+	return __ftrace_hash_rec_update(ops, filter_hash, 1);
 }
 
 static void ftrace_hash_rec_update_modify(struct ftrace_ops *ops,

Signature · 1 line

2.4.3

Currently dynamic ftrace calls are updated any time the ftrace_ops is un/registered. If we do this update only when it's needed, we save lot of time for perf system wide ftrace function sampling/counting.

The reason is that for system wide sampling/counting, perf creates event for each cpu in the system.

Each event then registers separate copy of ftrace_ops, which ends up in FTRACE_UPDATE_CALLS updates. On servers with many cpus that means serious stall (240 cpus server):

Counting:

  # time ./perf stat -e ftrace:function -a sleep 1

   Performance counter stats for 'system wide':

              370,663      ftrace:function

          1.401427505 seconds time elapsed

  real    3m51.743s
  user    0m0.023s
  sys     3m48.569s

Sampling:

  # time ./perf record -e ftrace:function -a sleep 1
  [ perf record: Woken up 0 times to write data ]
  Warning:
  Processed 141200 events and lost 5 chunks!

[ perf record: Captured and wrote 10.703 MB perf.data (135950 samples) ]

  real    2m31.429s
  user    0m0.213s
  sys     2m29.494s

There's no reason to do the FTRACE_UPDATE_CALLS update for each event in perf case, because all the ftrace_ops always share the same filter, so the updated calls are always the same.

It's required that only first ftrace_ops registration does the FTRACE_UPDATE_CALLS update (also sometimes the second if the first one used the trampoline), but the rest can be only cheaply linked into the ftrace_ops list.

Counting:

  # time ./perf stat -e ftrace:function -a sleep 1

   Performance counter stats for 'system wide':

             398,571      ftrace:function

         1.377503733 seconds time elapsed

  real    0m2.787s
  user    0m0.005s
  sys     0m1.883s

Sampling:

  # time ./perf record -e ftrace:function -a sleep 1
  [ perf record: Woken up 0 times to write data ]
  Warning:
  Processed 261730 events and lost 9 chunks!

[ perf record: Captured and wrote 19.907 MB perf.data (256293 samples) ]

  real    1m31.948s
  user    0m0.309s
  sys     1m32.051s

Signed-off-by Jiri Olsa <[email protected]>

---
 kernel/trace/ftrace.c | 10 +++++-----
 1 file changed, 5 insertions(+), 5 deletions(-)

kernel/trace/ftrace.c +5 -5

index 3a9a12215b50..22ef6fc597a2 100644
@@ -2651,7 +2651,6 @@ static int ftrace_startup(struct ftrace_ops *ops, int command)
 		return ret;
 
 	ftrace_start_up++;
-	command |= FTRACE_UPDATE_CALLS;
 
 	/*
 	 * Note that ftrace probes uses this to start up

@@ -2672,7 +2671,8 @@ static int ftrace_startup(struct ftrace_ops *ops, int command)
 		return ret;
 	}
 
-	ftrace_hash_rec_enable(ops, 1);
+	if (ftrace_hash_rec_enable(ops, 1))
+		command |= FTRACE_UPDATE_CALLS;
 
 	ftrace_startup_enable(command);
 

@@ -2702,11 +2702,11 @@ static int ftrace_shutdown(struct ftrace_ops *ops, int command)
 
 	/* Disabling ipmodify never fails */
 	ftrace_hash_ipmodify_disable(ops);
-	ftrace_hash_rec_disable(ops, 1);
 
-	ops->flags &= ~FTRACE_OPS_FL_ENABLED;
+	if (ftrace_hash_rec_disable(ops, 1))
+		command |= FTRACE_UPDATE_CALLS;
 
-	command |= FTRACE_UPDATE_CALLS;
+	ops->flags &= ~FTRACE_OPS_FL_ENABLED;
 
 	if (saved_ftrace_func != ftrace_trace_function) {
 		saved_ftrace_func = ftrace_trace_function;

Signature · 1 line

2.4.3

Currently dynamic ftrace calls are updated any time the ftrace_ops is un/registered. If we do this update only when it's needed, we save lot of time for perf system wide ftrace function sampling/counting.

The reason is that for system wide sampling/counting, perf creates event for each cpu in the system.

Each event then registers separate copy of ftrace_ops, which ends up in FTRACE_UPDATE_CALLS updates. On servers with many cpus that means serious stall (240 cpus server):

Counting:

  # time ./perf stat -e ftrace:function -a sleep 1

   Performance counter stats for 'system wide':

              370,663      ftrace:function

          1.401427505 seconds time elapsed

  real    3m51.743s
  user    0m0.023s
  sys     3m48.569s

Sampling:

  # time ./perf record -e ftrace:function -a sleep 1
  [ perf record: Woken up 0 times to write data ]
  Warning:
  Processed 141200 events and lost 5 chunks!

[ perf record: Captured and wrote 10.703 MB perf.data (135950 samples) ]

  real    2m31.429s
  user    0m0.213s
  sys     2m29.494s

There's no reason to do the FTRACE_UPDATE_CALLS update for each event in perf case, because all the ftrace_ops always share the same filter, so the updated calls are always the same.

It's required that only first ftrace_ops registration does the FTRACE_UPDATE_CALLS update (also sometimes the second if the first one used the trampoline), but the rest can be only cheaply linked into the ftrace_ops list.

Counting:

  # time ./perf stat -e ftrace:function -a sleep 1

   Performance counter stats for 'system wide':

             398,571      ftrace:function

         1.377503733 seconds time elapsed

  real    0m2.787s
  user    0m0.005s
  sys     0m1.883s

Sampling:

  # time ./perf record -e ftrace:function -a sleep 1
  [ perf record: Woken up 0 times to write data ]
  Warning:
  Processed 261730 events and lost 9 chunks!

[ perf record: Captured and wrote 19.907 MB perf.data (256293 samples) ]

  real    1m31.948s
  user    0m0.309s
  sys     1m32.051s

Signed-off-by Jiri Olsa <[email protected]>

---