Bug 211341 - Function traces dropped
Summary: Function traces dropped
Status: RESOLVED DUPLICATE of bug 211339
Alias: None
Product: Tracing/Profiling
Classification: Unclassified
Component: Ftrace (show other bugs)
Hardware: ARM Linux
: P1 normal
Assignee: Steven Rostedt
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2021-01-25 12:35 UTC by pierre.gondois
Modified: 2021-01-25 12:39 UTC (History)
0 users

See Also:
Kernel Version: v5.11-rc1
Subsystem:
Regression: No
Bisected commit-id:


Attachments

Description pierre.gondois 2021-01-25 12:35:50 UTC
Hello,
I added this function and called it from kernel/sched/fair.c:select_task_rq_fair (but it could be somewhere else):
void noinline MyFunc(void) {
trace_printk("TheTag\n");
return;
}

I then issued the following commands:
# /root/trace-cmd start -e cpu_frequency -e cpu_idle -e sched_overutilized -e sched_switch -e sched_wakeup -p function_graph -l MyFunc
Wait a bit ...
# /root/trace-cmd stop
# /root/trace-cmd extract -o /root/trace.dat

it gives me the following extracts:
<idle>-0     [003]  2308.555100: cpu_idle:             state=4294967295 cpu_id=3
<idle>-0     [003]  2308.555359: bputs:                MyFunc: TheTag
<idle>-0     [003]  2308.555457: sched_wakeup:         comm=kcompactd0 pid=53 prio=120 target_cpu=003

and
kworker/u12:2-1899  [003]  2307.953111: funcgraph_entry:                   |  MyFunc() {
kworker/u12:2-1899  [003]  2307.953114: bputs:                MyFunc: TheTag
kworker/u12:2-1899  [003]  2307.953116: funcgraph_exit:         6.900 us   |  }

As shown, it seems the function "MyFunc" is sometimes not traced.

Issuing the following commands:
# echo "MyFunc" > /sys/kernel/debug/tracing/set_ftrace_filter
# echo "function_graph" > /sys/kernel/debug/tracing/current_tracer
# echo 1 > /sys/kernel/debug/tracing/tracing_on
Wait a bit ...
# echo 0 > /sys/kernel/debug/tracing/tracing_on
# /root/trace-cmd extract -o /root/trace.dat

gives me the a similar output (available in trace2.dat attached):
<idle>-0     [002]  3057.671350: bputs:                MyFunc: TheTag
kworker/2:1H-90    [002]  3057.671606: funcgraph_entry:                   |  MyFunc() {
kworker/2:1H-90    [002]  3057.671609: bputs:                MyFunc: TheTag
kworker/2:1H-90    [002]  3057.671610: funcgraph_exit:         6.120 us   |  }
<idle>-0     [002]  3057.676063: bputs:                MyFunc: TheTag
kworker/2:1H-90    [002]  3057.678275: funcgraph_entry:                   |  MyFunc() {
kworker/2:1H-90    [002]  3057.678278: bputs:                MyFunc: TheTag
kworker/2:1H-90    [002]  3057.678280: funcgraph_exit:         6.120 us   |  }

As shown, the function "MyFunc" is sometimes not traced.
I am using trace-cmd built from git@github.com:rostedt/trace-cmd.git:b9bb3ae87e7c102013a5a717399281247d5be967
and a kernel based on v5.11-rc1 with patches that should not be related to the issue.

The "overrun" entries in per_cpu/cpuX/stats/ are set to 0, so no events should have been dropped.

Regards,
Pierre
Comment 1 pierre.gondois 2021-01-25 12:39:00 UTC
Sorry, I could not find the first ticket created.

*** This bug has been marked as a duplicate of bug 211339 ***

Note You need to log in before you can comment on or make changes to this bug.