tracing: A couple of last minute fixes before pushing to 5.13
Subsystems (2)
Steven Rostedt
maintainercover tracing: A couple of last minute fixes before pushing to 5.13
git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
for-next
Head SHA1: aafe104aa9096827a429bc1358f8260ee565b7cc
Steven Rostedt (VMware) (2):
tracing: Map all PIDs to command lines
tracing: Restructure trace_clock_global() to never block
----
kernel/trace/trace.c | 41 +++++++++++++++-------------------------- kernel/trace/trace_clock.c | 44 ++++++++++++++++++++++++++++++-------------- 2 files changed, 45 insertions(+), 40 deletions(-)
Steven Rostedt
maintainerPATCH 1/2 tracing: Map all PIDs to command lines
From: "Steven Rostedt (VMware)" <[email protected]>
The default max PID is set by PID_MAX_DEFAULT, and the tracing infrastructure uses this number to map PIDs to the comm names of the tasks, such output of the trace can show names from the recorded PIDs in the ring buffer. This mapping is also exported to user space via the "saved_cmdlines" file in the tracefs directory.
But currently the mapping expects the PIDs to be less than PID_MAX_DEFAULT, which is the default maximum and not the real maximum. Recently, systemd will increases the maximum value of a PID on the system, and when tasks are traced that have a PID higher than PID_MAX_DEFAULT, its comm is not recorded. This leads to the entire trace to have "<...>" as the comm name, which is pretty useless.
Instead, keep the array mapping the size of PID_MAX_DEFAULT, but instead of just mapping the index to the comm, map a mask of the PID (PID_MAX_DEFAULT - 1) to the comm, and find the full PID from the map_cmdline_to_pid array (that already exists).
This bug goes back to the beginning of ftrace, but hasn't been an issue until user space started increasing the maximum value of PIDs.
--- kernel/trace/trace.c | 41 +++++++++++++++-------------------------- 1 file changed, 15 insertions(+), 26 deletions(-)
kernel/trace/trace.c +15 -26
@@ -2390,14 +2390,13 @@ static void tracing_stop_tr(struct trace_array *tr)static int trace_save_cmdline (struct task_struct *tsk) { -unsigned pid, idx; +unsigned tpid, idx;/* treat recording of idle task as a success */ if (!tsk->pid)return 1 ; -if (unlikely (tsk->pid >PID_MAX_DEFAULT )) -return 0 ; + tpid = tsk->pid & (PID_MAX_DEFAULT -1 );/* * It's not the end of the world if we don't get
@@ -2408,26 +2407,15 @@ static int trace_save_cmdline(struct task_struct *tsk)if (!arch_spin_trylock (&trace_cmdline_lock))return 0 ; - idx = savedcmd->map_pid_to_cmdline[tsk->pid]; + idx = savedcmd->map_pid_to_cmdline[tpid];if (idx ==NO_CMDLINE_MAP ) { idx = (savedcmd->cmdline_idx +1 ) % savedcmd->cmdline_num; -/* -* Check whether the cmdline buffer at idx has a pid -* mapped. We are going to overwrite that entry so we -* need to clear the map_pid_to_cmdline. Otherwise we -* would read the new comm for the old pid. -*/ - pid = savedcmd->map_cmdline_to_pid[idx]; -if (pid !=NO_CMDLINE_MAP ) - savedcmd->map_pid_to_cmdline[pid] =NO_CMDLINE_MAP ; - - savedcmd->map_cmdline_to_pid[idx] = tsk->pid; - savedcmd->map_pid_to_cmdline[tsk->pid] = idx; - + savedcmd->map_pid_to_cmdline[tpid] = idx; savedcmd->cmdline_idx = idx; } + savedcmd->map_cmdline_to_pid[idx] = tsk->pid;set_cmdline (idx, tsk->comm);arch_spin_unlock (&trace_cmdline_lock);
@@ -2438,6 +2426,7 @@ static int trace_save_cmdline(struct task_struct *tsk)static void __trace_find_cmdline (int pid,char comm[]) {unsigned map; +int tpid;if (!pid) {strcpy (comm,"<idle>" );
@@ -2449,16 +2438,16 @@ static void __trace_find_cmdline(int pid, char comm[])return ; } -if (pid >PID_MAX_DEFAULT ) { -strcpy (comm,"<...>" ); -return ; + tpid = pid & (PID_MAX_DEFAULT -1 ); + map = savedcmd->map_pid_to_cmdline[tpid]; +if (map !=NO_CMDLINE_MAP ) { + tpid = savedcmd->map_cmdline_to_pid[map]; +if (tpid == pid) { +strlcpy (comm,get_saved_cmdlines (map),TASK_COMM_LEN ); +return ; + } } - - map = savedcmd->map_pid_to_cmdline[pid]; -if (map !=NO_CMDLINE_MAP ) -strlcpy (comm,get_saved_cmdlines (map),TASK_COMM_LEN ); -else -strcpy (comm,"<...>" ); +strcpy (comm,"<...>" ); }void trace_find_cmdline (int pid,char comm[])
Signature · 1 line
2.30.1
Steven Rostedt
maintainerPATCH 2/2 tracing: Restructure trace_clock_global() to never block
In reply to Steven RostedtFrom: "Steven Rostedt (VMware)" <[email protected]>
It was reported that a fix to the ring buffer recursion detection would cause a hung machine when performing suspend / resume testing. The following backtrace was extracted from debugging that case:
Call Trace: trace_clock_global+0x91/0xa0 __rb_reserve_next+0x237/0x460 ring_buffer_lock_reserve+0x12a/0x3f0 trace_buffer_lock_reserve+0x10/0x50 __trace_graph_return+0x1f/0x80 trace_graph_return+0xb7/0xf0 ? trace_clock_global+0x91/0xa0 ftrace_return_to_handler+0x8b/0xf0 ? pv_hash+0xa0/0xa0 return_to_handler+0x15/0x30 ? ftrace_graph_caller+0xa0/0xa0 ? trace_clock_global+0x91/0xa0 ? __rb_reserve_next+0x237/0x460 ? ring_buffer_lock_reserve+0x12a/0x3f0 ? trace_event_buffer_lock_reserve+0x3c/0x120 ? trace_event_buffer_reserve+0x6b/0xc0 ? trace_event_raw_event_device_pm_callback_start+0x125/0x2d0 ? dpm_run_callback+0x3b/0xc0 ? pm_ops_is_empty+0x50/0x50 ? platform_get_irq_byname_optional+0x90/0x90 ? trace_device_pm_callback_start+0x82/0xd0 ? dpm_run_callback+0x49/0xc0
With the following RIP:
RIP: 0010:native_queued_spin_lock_slowpath+0x69/0x200
Since the fix to the recursion detection would allow a single recursion to happen while tracing, this lead to the trace_clock_global() taking a spin lock and then trying to take it again:
ring_buffer_lock_reserve() {
trace_clock_global() {
arch_spin_lock() {
queued_spin_lock_slowpath() {
/* lock taken */
(something else gets traced by function graph tracer)
ring_buffer_lock_reserve() {
trace_clock_global() {
arch_spin_lock() {
queued_spin_lock_slowpath() {
/* DEAD LOCK! */Tracing should *never* block, as it can lead to strange lockups like the above.
Restructure the trace_clock_global() code to instead of simply taking a lock to update the recorded "prev_time" simply use it, as two events happening on two different CPUs that calls this at the same time, really doesn't matter which one goes first. Use a trylock to grab the lock for updating the prev_time, and if it fails, simply try again the next time. If it failed to be taken, that means something else is already updating it.
Bugzilla: https://bugzilla.kernel.org/show_bug.cgi?id=212761
--- kernel/trace/trace_clock.c | 44 ++++++++++++++++++++++++++------------ 1 file changed, 30 insertions(+), 14 deletions(-)
kernel/trace/trace_clock.c +30 -14
@@ -95,33 +95,49 @@ u64 notrace trace_clock_global(void) {unsigned long flags;int this_cpu; -u64 now; +u64 now, prev_time;raw_local_irq_save (flags); this_cpu =raw_smp_processor_id (); - now =sched_clock_cpu (this_cpu); +/* -* If in an NMI context then dont risk lockups and return the -* cpu_clock() time: +* The global clock "guarantees" that the events are ordered +* between CPUs. But if two events on two different CPUS call +* trace_clock_global at roughly the same time, it really does +* not matter which one gets the earlier time. Just make sure +* that the same CPU will always show a monotonic clock. +* +* Use a read memory barrier to get the latest written +* time that was recorded. */ -if (unlikely (in_nmi ())) - goto out; +smp_rmb (); + prev_time =READ_ONCE (trace_clock_struct.prev_time); + now =sched_clock_cpu (this_cpu); -arch_spin_lock (&trace_clock_struct.lock); +/* Make sure that now is always greater than prev_time */ +if ((s64)(now - prev_time) <0 ) + now = prev_time +1 ;/* -* TODO: if this happens often then maybe we should reset -* my_scd->clock to prev_time+1, to make sure -* we start ticking with the local clock from now on? +* If in an NMI context then dont risk lockups and simply return +* the current time. */ -if ((s64)(now - trace_clock_struct.prev_time) <0 ) - now = trace_clock_struct.prev_time +1 ; +if (unlikely (in_nmi ())) + goto out; - trace_clock_struct.prev_time = now; +/* Tracing can cause strange recursion, always use a try lock */ +if (arch_spin_trylock (&trace_clock_struct.lock)) { +/* Reread prev_time in case it was already updated */ + prev_time =READ_ONCE (trace_clock_struct.prev_time); +if ((s64)(now - prev_time) <0 ) + now = prev_time +1 ; -arch_spin_unlock (&trace_clock_struct.lock); + trace_clock_struct.prev_time = now; +/* The unlock acts as the wmb for the above rmb */ +arch_spin_unlock (&trace_clock_struct.lock); + } out:raw_local_irq_restore (flags);
Signature · 1 line
2.30.1