tracing/perf: perf_trace_buf/perf_xxx hacks.

Hello.

On top of "PATCH 0/3] tracing: more list_empty(perf_events) checks" series I sent yesterday.

Compile tested only, not for inclusion yet.

But I'll appreciate if you can take a look. I'll try to test this tomorrow somehow and let you know. Right now I am looking at asm code, looks correct...

I also compiled the kernel with the additional patch below, everything compiles except sched/core.o as expected.

Oleg.

@@ -664,6 +664,8 @@ perf_trace_##call(void *__data, proto)					\
 									\
 	__data_size = ftrace_get_offsets_##call(&__data_offsets, args); \
 									\
+	BUILD_BUG_ON(!(__builtin_constant_p(!__task) && !__task));	\
+									\
 	head = this_cpu_ptr(event_call->perf_events);			\
 	if (__builtin_constant_p(!__task) && !__task &&			\
 				hlist_empty(head))			\

To simplify the review of the next patch:

1. We are going to reimplent __perf_task/counter and embedd them into TP_ARGS(). expand TRACE_EVENT(sched_stat_runtime) into DECLARE_EVENT_CLASS() + DEFINE_EVENT(), this way they can use different TP_ARGS's.

2. Change perf_trace_##call() macri to do perf_fetch_caller_regs() right before perf_trace_buf_prepare(). This way it evaluates "args" asap.

Note: after 87f44bbc perf_trace_buf_prepare() doesn't need "struct pt_regs *regs", perhaps it makes sense to remove this argument. And perhaps we can teach perf_trace_buf_submit() to accept regs == NULL and do fetch_caller_regs(CALLER_ADDR1) in this case.

3. Cosmetic, but the typecast from "void*" buys nothing. It just adds the noise, remove it.

---
 include/trace/events/sched.h |    6 +++++-
 include/trace/ftrace.h       |    7 +++----
 2 files changed, 8 insertions(+), 5 deletions(-)

index e5586ca..249c024 100644
@@ -372,7 +372,7 @@ DEFINE_EVENT(sched_stat_template, sched_stat_blocked,
  * Tracepoint for accounting runtime (time the task is executing
  * on a CPU).
  */
-TRACE_EVENT(sched_stat_runtime,
+DECLARE_EVENT_CLASS(sched_stat_runtime,
 
 	TP_PROTO(struct task_struct *tsk, u64 runtime, u64 vruntime),
 

@@ -401,6 +401,10 @@ TRACE_EVENT(sched_stat_runtime,
 			(unsigned long long)__entry->vruntime)
 );
 
+DEFINE_EVENT(sched_stat_runtime, sched_stat_runtime,
+	     TP_PROTO(struct task_struct *tsk, u64 runtime, u64 vruntime),
+	     TP_ARGS(tsk, runtime, vruntime));
+
 /*
  * Tracepoint for showing priority inheritance modifying a tasks
  * priority.

index c162a57..aed594a 100644
@@ -659,15 +659,14 @@ perf_trace_##call(void *__data, proto)					\
 	int __data_size;						\
 	int rctx;							\
 									\
-	perf_fetch_caller_regs(&__regs);				\
-									\
 	__data_size = ftrace_get_offsets_##call(&__data_offsets, args); \
 	__entry_size = ALIGN(__data_size + sizeof(*entry) + sizeof(u32),\
 			     sizeof(u64));				\
 	__entry_size -= sizeof(u32);					\
 									\
-	entry = (struct ftrace_raw_##call *)perf_trace_buf_prepare(	\
-		__entry_size, event_call->event.type, &__regs, &rctx);	\
+	perf_fetch_caller_regs(&__regs);				\
+	entry = perf_trace_buf_prepare(__entry_size,			\
+			event_call->event.type, &__regs, &rctx);	\
 	if (!entry)							\
 		return;							\
 									\

1.5.5.1

TP_perf_assign/__perf_xxx is used to change the default values of __addr/__count/__task variables for perf_trace_buf_submit().

Unfortunately, TP_perf_assign() is called "too late", we want to have a fast-path "__task != NULL" check in perf_trace_##call() at the start. So this patch simply embeds __perf_xxx() into TP_ARGS(), this way DECLARE_EVENT_CLASS() can use the result of assignments hidden in "args" right after ftrace_get_offsets_##call() which is mostly trivial.

---
 include/trace/events/sched.h |   16 +++-------------
 include/trace/ftrace.h       |   19 +++++++++++--------
 2 files changed, 14 insertions(+), 21 deletions(-)

index 249c024..2e7d994 100644
@@ -57,7 +57,7 @@ DECLARE_EVENT_CLASS(sched_wakeup_template,
 
 	TP_PROTO(struct task_struct *p, int success),
 
-	TP_ARGS(p, success),
+	TP_ARGS(__perf_task(p), success),
 
 	TP_STRUCT__entry(
 		__array(	char,	comm,	TASK_COMM_LEN	)

@@ -73,9 +73,6 @@ DECLARE_EVENT_CLASS(sched_wakeup_template,
 		__entry->prio		= p->prio;
 		__entry->success	= success;
 		__entry->target_cpu	= task_cpu(p);
-	)
-	TP_perf_assign(
-		__perf_task(p);
 	),
 
 	TP_printk("comm=%s pid=%d prio=%d success=%d target_cpu=%03d",

@@ -313,7 +310,7 @@ DECLARE_EVENT_CLASS(sched_stat_template,
 
 	TP_PROTO(struct task_struct *tsk, u64 delay),
 
-	TP_ARGS(tsk, delay),
+	TP_ARGS(__perf_task(tsk), __perf_count(delay)),
 
 	TP_STRUCT__entry(
 		__array( char,	comm,	TASK_COMM_LEN	)

@@ -325,10 +322,6 @@ DECLARE_EVENT_CLASS(sched_stat_template,
 		memcpy(__entry->comm, tsk->comm, TASK_COMM_LEN);
 		__entry->pid	= tsk->pid;
 		__entry->delay	= delay;
-	)
-	TP_perf_assign(
-		__perf_count(delay);
-		__perf_task(tsk);
 	),
 
 	TP_printk("comm=%s pid=%d delay=%Lu [ns]",

@@ -376,7 +369,7 @@ DECLARE_EVENT_CLASS(sched_stat_runtime,
 
 	TP_PROTO(struct task_struct *tsk, u64 runtime, u64 vruntime),
 
-	TP_ARGS(tsk, runtime, vruntime),
+	TP_ARGS(tsk, __perf_count(runtime), vruntime),
 
 	TP_STRUCT__entry(
 		__array( char,	comm,	TASK_COMM_LEN	)

@@ -390,9 +383,6 @@ DECLARE_EVENT_CLASS(sched_stat_runtime,
 		__entry->pid		= tsk->pid;
 		__entry->runtime	= runtime;
 		__entry->vruntime	= vruntime;
-	)
-	TP_perf_assign(
-		__perf_count(runtime);
 	),
 
 	TP_printk("comm=%s pid=%d runtime=%Lu [ns] vruntime=%Lu [ns]",

index aed594a..8886877 100644
@@ -503,8 +503,14 @@ static inline notrace int ftrace_get_offsets_##call(			\
 #undef TP_fast_assign
 #define TP_fast_assign(args...) args
 
-#undef TP_perf_assign
-#define TP_perf_assign(args...)
+#undef __perf_addr
+#define __perf_addr(a)	(a)
+
+#undef __perf_count
+#define __perf_count(c)	(c)
+
+#undef __perf_task
+#define __perf_task(t)	(t)
 
 #undef DECLARE_EVENT_CLASS
 #define DECLARE_EVENT_CLASS(call, proto, args, tstruct, assign, print)	\

@@ -632,16 +638,13 @@ __attribute__((section("_ftrace_events"))) *__event_##call = &event_##call
 #define __get_str(field) (char *)__get_dynamic_array(field)
 
 #undef __perf_addr
-#define __perf_addr(a) __addr = (a)
+#define __perf_addr(a)	(__addr = (a))
 
 #undef __perf_count
-#define __perf_count(c) __count = (c)
+#define __perf_count(c)	(__count = (c))
 
 #undef __perf_task
-#define __perf_task(t) __task = (t)
-
-#undef TP_perf_assign
-#define TP_perf_assign(args...) args
+#define __perf_task(t)	(__task = (t))
 
 #undef DECLARE_EVENT_CLASS
 #define DECLARE_EVENT_CLASS(call, proto, args, tstruct, assign, print)	\

1.5.5.1

perf_trace_buf_prepare() + perf_trace_buf_submit(task => NULL) make no sense if hlist_empty(head). Change perf_trace_##call() to check ->perf_events beforehand and do nothing if it is empty.

However, we can only do this if __task == NULL, so we also add the __builtin_constant_p(__task) check.

---
 include/trace/ftrace.h |    7 ++++++-
 1 files changed, 6 insertions(+), 1 deletions(-)

index 8886877..04455b8 100644
@@ -663,6 +663,12 @@ perf_trace_##call(void *__data, proto)					\
 	int rctx;							\
 									\
 	__data_size = ftrace_get_offsets_##call(&__data_offsets, args); \
+									\
+	head = this_cpu_ptr(event_call->perf_events);			\
+	if (__builtin_constant_p(!__task) && !__task &&			\
+				hlist_empty(head))			\
+		return;							\
+									\
 	__entry_size = ALIGN(__data_size + sizeof(*entry) + sizeof(u32),\
 			     sizeof(u64));				\
 	__entry_size -= sizeof(u32);					\

@@ -677,7 +683,6 @@ perf_trace_##call(void *__data, proto)					\
 									\
 	{ assign; }							\
 									\
-	head = this_cpu_ptr(event_call->perf_events);			\
 	perf_trace_buf_submit(entry, __entry_size, rctx, __addr,	\
 		__count, &__regs, head, __task);			\
 }

1.5.5.1

!__task looks more explicit/symmetrical to me. We need

	if (is_compile_time_true(!__task)) && list_empty)
		return;

is_compile_time_true(cond) could be defined as

	__builtin_constant_p(cond) && (cond)
or
	__builtin_constant_p(!cond) && (cond)

but the 1ts one looks more clean.

However,

OK, I do not really mind, will do.

And,

Of course! this was the main reason.

Steven, I convinced myself the patch should be correct. If you agree with this hack:

- anything else I should do apart from the change above?

- should I resend the previous "[PATCH 0/3] tracing: more list_empty(perf_events) checks" series?

This series depends on "[PATCH 3/3] tracing/perf: Move the PERF_MAX_TRACE_SIZE check into perf_trace_buf_prepare()".

Or I can drop this patch if you do not like it and rediff.

Just in case, there are other pending patches in trace_kprobe.c which I am going to resend, but they are orthogonal.

Oleg.

I knew it!

I'll pull in the patches and play with them. I'll let you know what I find.

Thanks,

-- Steve

I'm probably missing something obviuos, but what are we trying to do?

Say, "perf record -e sched:sched_switch -p1".

Every task except /sbin/init will do perf_trace_sched_switch() and perf_trace_buf_prepare() + perf_trace_buf_submit for no reason(), it doesn't have a counter.

So it makes sense to add the fast-path check at the start of perf_trace_##call(),

	if (hlist_empty(event_call->perf_events))
		return;

The problem is, we should not do this if __task != NULL (iow, if DECLARE_EVENT_CLASS() uses __perf_task()), perf_tp_event() has the additional code for this case.

So we should do

	if (!__task && hlist_empty(event_call->perf_events))
		return;

But __task is changed by "{ assign; }" block right before perf_trace_buf_submit(). Too late for the fast-path check, we already called perf_trace_buf_prepare/fetch_regs.

So. After 2/3 __perf_task() (and __perf_count/addr) is called when ftrace_get_offsets_##call(args) evaluates the arguments, and we can check !__task && hlist_empty() right after that.

Oleg.

I did some testing under kvm, not sure these numbers actually mean something, but still.

So, the test-case:

	int pipe1[2], pipe2[2];

	void *tfunc(void *arg)
	{
		for (;;) {
			char c;
			assert(read(pipe1[0], &c, 1) == 1);
			assert(write(pipe2[1], &c, 1) == 1);
		}
	}

	int main(void)
	{
		pthread_t thr;
		int nr;

		assert(pipe(pipe1) == 0);
		assert(pipe(pipe2) == 0);

		assert(pthread_create(&thr, NULL, tfunc, NULL) == 0);

		for (nr = 0; nr < 1000 * 1000; ++nr) {
			char c;

			assert(write(pipe1[1], &c, 1) == 1);
			assert(read(pipe2[0], &c, 1) == 1);
		}

		return 0;
	}

Idle machine, "/usr/bin/time -f "%e %S %U" taskset 1 ./pf" 3 times:

	20.73 20.05 0.66
	20.68 20.04 0.63
	20.68 20.02 0.65

Now with "perf record -e sched:sched_switch -p1" running,

before 3/3:

	21.59 20.77 0.80
	21.40 20.70 0.68
	21.50 20.72 0.78

after 3/3:

	21.00 20.23 0.76
	20.89 20.19 0.69
	20.94 20.26 0.66

Oleg.

Same as "perf bench sched pipe"

David

Yes.

You just cruelly disclosed the fact that I do not use perf.

Thanks. So,

	# perf record -e sched:sched_switch -p1 &
	[1] 516
	# perf bench sched pipe

3 times.

before:

     Total time: 30.119 [sec]

      30.119501 usecs/op
          33201 ops/sec

     Total time: 30.634 [sec]

      30.634105 usecs/op
          32643 ops/sec

     Total time: 30.100 [sec]

      30.100209 usecs/op
          33222 ops/sec

after:

     Total time: 29.645 [sec]

      29.645941 usecs/op
          33731 ops/sec

     Total time: 29.759 [sec]

      29.759075 usecs/op
          33603 ops/sec

     Total time: 29.803 [sec]

      29.803522 usecs/op
          33553 ops/sec

Hmm. Actually sched-pipe.c is a bit more "heavy", it does switch_mm(). And I used taskset. But it seems that this test-case shows the similar results.

Oleg.

OK, I tested this against 3.10-rc6 and then applied your patches (had to modify a little because it didn't apply that cleanly).

I ran this:

perf stat --repeat 100 -- perf bench sched pipe > /tmp/perf-bench-sched.{before, after}

before:

# tail -20 perf-bench-sched.before 
      24.115329 usecs/op
          41467 ops/sec

Performance counter stats for 'perf bench sched pipe' (100 runs):

      17851.057092 task-clock                #    0.741 CPUs utilized            ( +-  0.03% )
         1,996,681 context-switches          #    0.112 M/sec                    ( +-  0.00% )
                61 cpu-migrations            #    0.003 K/sec                    ( +-  2.13% )
             1,248 page-faults               #    0.070 K/sec                    ( +-  0.01% )
    29,738,460,230 cycles                    #    1.666 GHz                      ( +-  0.03% ) [50.91%]
   <not supported> stalled-cycles-frontend 
   <not supported> stalled-cycles-backend  
    22,108,278,276 instructions              #    0.74  insns per cycle          ( +-  0.01% ) [76.35%]
     5,275,965,301 branches                  #  295.555 M/sec                    ( +-  0.00% ) [74.14%]
        69,232,340 branch-misses             #    1.31% of all branches          ( +-  0.19% ) [74.95%]

24.089150300 seconds time elapsed ( +- 0.02% )

after:

# tail -20 perf-bench-sched.after 
      24.170945 usecs/op
          41371 ops/sec

Performance counter stats for 'perf bench sched pipe' (100 runs):

      18060.703178 task-clock                #    0.747 CPUs utilized            ( +-  0.02% )
         1,996,865 context-switches          #    0.111 M/sec                    ( +-  0.00% )
                63 cpu-migrations            #    0.003 K/sec                    ( +-  3.07% )
             1,248 page-faults               #    0.069 K/sec                    ( +-  0.01% )
    29,596,801,452 cycles                    #    1.639 GHz                      ( +-  0.02% ) [49.13%]
   <not supported> stalled-cycles-frontend 
   <not supported> stalled-cycles-backend  
    22,033,684,587 instructions              #    0.74  insns per cycle          ( +-  0.01% ) [73.34%]
     5,281,256,193 branches                  #  292.417 M/sec                    ( +-  0.00% ) [75.84%]
        66,966,995 branch-misses             #    1.27% of all branches          ( +-  0.22% ) [75.04%]

24.183738898 seconds time elapsed ( +- 0.01% )

Maybe I did something wrong, but on this box, I didn't see any significant improvement with the patches. Note, I did the test before applying all patches, and then again after applying all patches.

-- Steve

You want to compare:
perf stat --repeat 100 -p 1 -- perf bench sched pipe

so that event is tagged to pid 1 and not the perf-bench workload.

David

I guess I'm a bit confused. What's the significance of measuring pid 1 (init)?

-- Steve

I believe Oleg's point is the overhead for tasks without events associated with them. To show that create an event tagged to the init task and then run some workload -- like perf bench shed pipe. It shows that all tasks take a hit, not just the one getting profiled.

David

Oh wait, I just noticed Oleg's:

# perf record -e sched:sched_switch -p1 &

I missed that.

bah, time to re-run it.

-- Steve

New update, after running with the above command:

[root@ixf ~]# cat perf-bench-sched.before.2 | tail -20

     Total time: 11.833 [sec]

      11.833804 usecs/op
          84503 ops/sec

Performance counter stats for process id '1' (100 runs):

<not counted> task-clock
<not counted> context-switches
<not counted> cpu-migrations
<not counted> page-faults
<not counted> cycles
<not supported> stalled-cycles-frontend
<not supported> stalled-cycles-backend
<not counted> instructions
<not counted> branches
<not counted> branch-misses

11.955755673 seconds time elapsed
( +- 0.05% )

[root@ixf ~]# cat perf-bench-sched.after-2 | tail -20

     Total time: 11.490 [sec]

      11.490764 usecs/op
          87026 ops/sec

Performance counter stats for process id '1' (100 runs):

<not counted> task-clock
<not counted> context-switches
<not counted> cpu-migrations
<not counted> page-faults
<not counted> cycles
<not supported> stalled-cycles-frontend
<not supported> stalled-cycles-backend
<not counted> instructions
<not counted> branches
<not counted> branch-misses

11.511847099 seconds time elapsed
( +- 0.05% )

OK, this does give us a slight improvement. Approximately 4%.

-- Steve

Oleg, I know you sent me a mbox with these patches, but I rather pull the real email. But this is the only one I have. With a comment like that, I wouldn't pull it in.

But as you sent me them to include them, I take it, this is ready.

Peter, Frederic, can you review these patches and ack or nack them?

Thanks,

-- Steve