From 6d7a9ac0d5ae138d1457c4c0efd7bc1572289a94 Mon Sep 17 00:00:00 2001 From: Metin Kaya Date: Wed, 27 Dec 2023 12:09:08 +0000 Subject: [PATCH] ANDROID: sched: Add trace events for proxy execution Add sched_[start, finish]_task_selection trace events to measure the latency of proxy execution patches in task selection. Moreover, introduce trace events for interesting events in proxy execution: 1. sched_pe_enqueue_sleeping_task: a task gets enqueued on wait queue of a sleeping task (mutex owner). 2. sched_pe_activate_blocked_entity: When owner is woken and we activate tasks enqueued on the owner' blocked entities list. 3. sched_pe_migration: dependency chain crosses remote CPU. 4. sched_pe_return_migration: returning a previously proxy-migrated task to it's originating cpu. 5. sched_pe_owner_is_migrating: mutex owner task is mid-migration. New trace events can be tested via this command: $ perf trace -e sched:sched_start_task_selection \ -e sched:sched_finish_task_selection \ -e sched:sched_pe_enqueue_sleeping_task \ -e sched:sched_pe_activate_blocked_entity \ -e sched:sched_pe_migration \ -e sched:sched_pe_return_migration \ -e sched:sched_pe_owner_is_migrating Note: These trace events are not intended to merge upstream. Instead, they are only for making PE tests easier and will be converted to trace points once Proxy Execution patches hit upstream. CC: John Stultz CC: Joel Fernandes Cc: Qais Yousef CC: Ingo Molnar CC: Peter Zijlstra CC: Juri Lelli CC: Vincent Guittot CC: Dietmar Eggemann CC: Valentin Schneider CC: Steven Rostedt CC: Masami Hiramatsu CC: Mathieu Desnoyers CC: Ben Segall CC: Zimuzo Ezeozue CC: Mel Gorman CC: Will Deacon CC: Waiman Long CC: Boqun Feng CC: "Paul E. McKenney" CC: Xuewen Yan CC: K Prateek Nayak CC: Thomas Gleixner CC: Daniel Lezcano CC: kernel-team@android.com CC: linux-trace-kernel@vger.kernel.org Change-Id: Iec008efa1f954c0f0d43714fdd32cf96fc0dd561 Signed-off-by: Metin Kaya [jstultz: Add more details to the traceevents for validating proxy behavior] Signed-off-by: John Stultz Bug: 306081722 --- v10: * Add more details to the traceevents (owner task for proxy migrations, and prev, selected and next for task selection) so its easier to understand the proxy behavior. v11: * Rename sched_pe_owner_is_migrating and include owner & waiter in the trace_event * Add trace-event for activation of blocked entities * Rename sched_pe_migration * Add sched_pe_return_migration to track return migration events v12: * Renaming of selected -> donor * Nit fixup suggested by Metin * Build fixup for !SCHED_PROXY_EXEC case --- include/trace/events/sched.h | 241 +++++++++++++++++++++++++++++++++++ kernel/sched/core.c | 14 +- 2 files changed, 254 insertions(+), 1 deletion(-) diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h index 722be48dab3a..3f2e6d1d125c 100644 --- a/include/trace/events/sched.h +++ b/include/trace/events/sched.h @@ -793,6 +793,247 @@ TRACE_EVENT(sched_wake_idle_without_ipi, TP_printk("cpu=%d", __entry->cpu) ); +#ifdef CONFIG_SCHED_PROXY_EXEC +/** + * sched_pe_enqueue_sleeping_task - called when a task is enqueued on wait + * queue of a sleeping task (mutex owner). + * @mutex_owner: pointer to struct task_struct + * @blocked: pointer to struct task_struct + */ +TRACE_EVENT(sched_pe_enqueue_sleeping_task, + + TP_PROTO(struct task_struct *mutex_owner, struct task_struct *blocked), + + TP_ARGS(mutex_owner, blocked), + + TP_STRUCT__entry( + __array(char, owner_comm, TASK_COMM_LEN ) + __field(pid_t, owner_pid ) + __field(int, owner_prio ) + __field(int, owner_cpu ) + __array(char, blocked_comm, TASK_COMM_LEN ) + __field(pid_t, blocked_pid ) + __field(int, blocked_prio ) + __field(int, blocked_cpu ) + ), + + TP_fast_assign( + strscpy(__entry->owner_comm, mutex_owner->comm, TASK_COMM_LEN); + __entry->owner_pid = mutex_owner->pid; + __entry->owner_prio = mutex_owner->prio; /* XXX SCHED_DEADLINE */ + __entry->owner_cpu = task_cpu(mutex_owner); + + strscpy(__entry->blocked_comm, blocked->comm, TASK_COMM_LEN); + __entry->blocked_pid = blocked->pid; + __entry->blocked_prio = blocked->prio; /* XXX SCHED_DEADLINE */ + __entry->blocked_cpu = task_cpu(blocked); + ), + + TP_printk("task=%s pid=%d prio=%d cpu=%d blocked_on owner_task=%s owner_pid=%d owner_prio=%d owner_cpu=%d", + __entry->blocked_comm, __entry->blocked_pid, + __entry->blocked_prio, __entry->blocked_cpu, + __entry->owner_comm, __entry->owner_pid, + __entry->owner_prio, __entry->owner_cpu) +); + +/** + * sched_pe_activate_blocked_entity - called when a blocked entity is activated + * when mutex owner wakes + * @owner: pointer to struct task_struct + * @blocked: pointer to struct task_struct + */ +TRACE_EVENT(sched_pe_activate_blocked_entity, + + TP_PROTO(struct task_struct *owner, struct task_struct *blocked), + + TP_ARGS(owner, blocked), + + TP_STRUCT__entry( + __array(char, owner_comm, TASK_COMM_LEN ) + __field(pid_t, owner_pid ) + __field(int, owner_prio ) + __field(int, owner_cpu ) + __array(char, blocked_comm, TASK_COMM_LEN ) + __field(pid_t, blocked_pid ) + __field(int, blocked_prio ) + __field(int, blocked_cpu ) + ), + + TP_fast_assign( + strscpy(__entry->owner_comm, owner->comm, TASK_COMM_LEN); + __entry->owner_pid = owner->pid; + __entry->owner_prio = owner->prio; /* XXX SCHED_DEADLINE */ + __entry->owner_cpu = task_cpu(owner); + + strscpy(__entry->blocked_comm, blocked->comm, TASK_COMM_LEN); + __entry->blocked_pid = blocked->pid; + __entry->blocked_prio = blocked->prio; /* XXX SCHED_DEADLINE */ + __entry->blocked_cpu = task_cpu(blocked); + ), + + TP_printk("activating task=%s pid=%d prio=%d cpu=%d, blocked_on owner=%s pid=%d prio=%d cpu=%d", + __entry->blocked_comm, __entry->blocked_pid, + __entry->blocked_prio, __entry->blocked_cpu, + __entry->owner_comm, __entry->owner_pid, + __entry->owner_prio, __entry->owner_cpu) +); + +/** + * sched_pe_cross_remote_cpu - called when dependency chain crosses remote CPU + * @p: pointer to struct task_struct + */ +TRACE_EVENT(sched_pe_migration, + + TP_PROTO(struct task_struct *next, struct task_struct *owner), + + TP_ARGS(next, owner), + + TP_STRUCT__entry( + __array(char, next_comm, TASK_COMM_LEN ) + __field(pid_t, next_pid ) + __field(int, next_prio ) + __array(char, owner_comm, TASK_COMM_LEN ) + __field(pid_t, owner_pid ) + __field(int, owner_prio ) + __field(int, remote_cpu ) + ), + + TP_fast_assign( + strscpy(__entry->next_comm, next->comm, TASK_COMM_LEN); + __entry->next_pid = next->pid; + __entry->next_prio = next->prio; /* XXX SCHED_DEADLINE */ + strscpy(__entry->owner_comm, owner->comm, TASK_COMM_LEN); + __entry->owner_pid = owner->pid; + __entry->owner_prio = owner->prio; /* XXX SCHED_DEADLINE */ + __entry->remote_cpu = task_cpu(owner); + ), + + TP_printk("next=%s pid=%d prio=%d owner=%s pid=%d prio=%d remote_cpu=%d", + __entry->next_comm, __entry->next_pid, __entry->next_prio, + __entry->owner_comm, __entry->owner_pid, __entry->owner_prio, + __entry->remote_cpu) +); + +/** + * sched_pe_task_is_migrating - called when mutex owner is in migrating state + * @p: pointer to struct task_struct + */ +TRACE_EVENT(sched_pe_owner_is_migrating, + + TP_PROTO(struct task_struct *owner, struct task_struct *waiter), + + TP_ARGS(owner, waiter), + + TP_STRUCT__entry( + __array(char, owner_comm, TASK_COMM_LEN ) + __field(pid_t, owner_pid ) + __field(int, owner_prio ) + __array(char, waiter_comm, TASK_COMM_LEN ) + __field(pid_t, waiter_pid ) + __field(int, waiter_prio ) + ), + + TP_fast_assign( + strscpy(__entry->owner_comm, owner->comm, TASK_COMM_LEN); + __entry->owner_pid = owner->pid; + __entry->owner_prio = owner->prio; /* XXX SCHED_DEADLINE */ + strscpy(__entry->waiter_comm, waiter->comm, TASK_COMM_LEN); + __entry->waiter_pid = waiter->pid; + __entry->waiter_prio = waiter->prio; /* XXX SCHED_DEADLINE */ + ), + + TP_printk("owner comm=%s pid=%d prio=%d waiter comm=%s pid=%d prio=%d", + __entry->owner_comm, __entry->owner_pid, __entry->owner_prio, + __entry->waiter_comm, __entry->waiter_pid, __entry->waiter_prio) +); +#endif /* CONFIG_SCHED_PROXY_EXEC */ + +/** + * sched_pe_cross_remote_cpu - called when dependency chain crosses remote CPU + * @p: pointer to struct task_struct + */ +TRACE_EVENT(sched_pe_return_migration, + + TP_PROTO(struct task_struct *task, int target_cpu), + + TP_ARGS(task, target_cpu), + + TP_STRUCT__entry( + __array(char, comm, TASK_COMM_LEN ) + __field(pid_t, pid ) + __field(int, prio ) + __field(int, target_cpu ) + ), + + TP_fast_assign( + strscpy(__entry->comm, task->comm, TASK_COMM_LEN); + __entry->pid = task->pid; + __entry->prio = task->prio; /* XXX SCHED_DEADLINE */ + __entry->target_cpu = target_cpu; + ), + + TP_printk("task=%s pid=%d prio=%d target_cpu=%d", + __entry->comm, __entry->pid, __entry->prio, + __entry->target_cpu) +); + + +TRACE_EVENT(sched_start_task_selection, + + TP_PROTO(struct task_struct *prev, int cpu, bool is_blocked), + + TP_ARGS(prev, cpu, is_blocked), + + TP_STRUCT__entry( + __array(char, comm, TASK_COMM_LEN ) + __field(pid_t, pid ) + __field(int, prio ) + __field(bool, is_blocked ) + ), + + TP_fast_assign( + strscpy(__entry->comm, prev->comm, TASK_COMM_LEN); + __entry->pid = prev->pid; + __entry->prio = prev->prio; /* XXX SCHED_DEADLINE */ + __entry->is_blocked = is_blocked; + ), + + TP_printk("prev=%s pid=%d prio=%d is_blocked: %i", + __entry->comm, __entry->pid, __entry->prio, __entry->is_blocked) +); + +TRACE_EVENT(sched_finish_task_selection, + + TP_PROTO(struct task_struct *donor, struct task_struct *next, int cpu), + + TP_ARGS(donor, next, cpu), + + TP_STRUCT__entry( + __array(char, donor_comm, TASK_COMM_LEN ) + __field(pid_t, donor_pid ) + __field(int, donor_prio ) + __array(char, next_comm, TASK_COMM_LEN ) + __field(pid_t, next_pid ) + __field(int, next_prio ) + __field(int, cpu ) + ), + + TP_fast_assign( + strscpy(__entry->donor_comm, donor->comm, TASK_COMM_LEN); + __entry->donor_pid = donor->pid; + __entry->donor_prio = donor->prio; /* XXX SCHED_DEADLINE */ + strscpy(__entry->next_comm, next->comm, TASK_COMM_LEN); + __entry->next_pid = next->pid; + __entry->next_prio = next->prio; /* XXX SCHED_DEADLINE */ + __entry->cpu = cpu; + ), + + TP_printk("donor=%s pid=%d prio=%d next=%s pid=%d prio=%d cpu=%d", + __entry->donor_comm, __entry->donor_pid, __entry->donor_prio, + __entry->next_comm, __entry->next_pid, __entry->next_prio, + __entry->cpu) +); + /* * Following tracepoints are not exported in tracefs and provide hooking * mechanisms only for testing and debugging purposes. diff --git a/kernel/sched/core.c b/kernel/sched/core.c index 6d182c3cc86f..8a98ae4421fe 100644 --- a/kernel/sched/core.c +++ b/kernel/sched/core.c @@ -3937,6 +3937,7 @@ static void activate_blocked_waiters(struct rq *target_rq, raw_spin_unlock_irqrestore(&owner->blocked_lock, flags); do_activate_blocked_waiter(target_rq, p, en_flags); + trace_sched_pe_activate_blocked_entity(owner, p); raw_spin_lock_irqsave(&p->blocked_lock, flags); if (list_empty(&p->blocked_activation_node)) { @@ -4101,8 +4102,10 @@ static int ttwu_runnable(struct task_struct *p, int wake_flags) */ wakeup_preempt(rq, p, wake_flags); } - if (proxy_needs_return(rq, p)) + if (proxy_needs_return(rq, p)) { + trace_sched_pe_return_migration(p, p->wake_cpu); goto out; + } ttwu_do_wakeup(p); ret = 1; } @@ -7093,6 +7096,7 @@ static void proxy_enqueue_on_owner(struct rq *rq, struct task_struct *owner, * ttwu_activate() will pick them up and place them on whatever rq * @owner will run next. */ + trace_sched_pe_enqueue_sleeping_task(owner, p); WARN_ON(p == owner); WARN_ON(!p->on_rq); WARN_ON(p->sleeping_owner); @@ -7185,6 +7189,8 @@ find_proxy_task(struct rq *rq, struct task_struct *donor, struct rq_flags *rf) owner_cpu = task_cpu(owner); if (owner_cpu != this_cpu) { + trace_sched_pe_migration(donor, owner); + /* * @owner can disappear, simply migrate to @owner_cpu and leave that CPU * to sort things out. @@ -7199,6 +7205,8 @@ find_proxy_task(struct rq *rq, struct task_struct *donor, struct rq_flags *rf) } if (task_on_rq_migrating(owner)) { + trace_sched_pe_owner_is_migrating(owner, p); + /* * One of the chain of mutex owners is currently migrating to this * CPU, but has not yet been enqueued because we are holding the @@ -7336,6 +7344,7 @@ needs_return: return proxy_resched_idle(rq); p->blocked_on_state = BO_RUNNABLE; + trace_sched_pe_return_migration(p, p->wake_cpu); proxy_migrate_task(rq, rf, p, p->wake_cpu); return NULL; @@ -7486,6 +7495,8 @@ static void __sched notrace __schedule(int sched_mode) } prev_not_proxied = !prev->blocked_donor; + + trace_sched_start_task_selection(prev, cpu, task_is_blocked(prev)); pick_again: next = pick_next_task(rq, rq->donor, &rf); rq_set_donor(rq, next); @@ -7500,6 +7511,7 @@ pick_again: if (next == rq->idle) preserve_need_resched = true; } + trace_sched_finish_task_selection(rq->donor, next, cpu); picked: if (!preserve_need_resched) clear_tsk_need_resched(prev);