[PATCH v2 0/5] perf sched: Minor optimizations for resource initialization

From: Yang Jihong
Date: Tue Feb 06 2024 - 03:39:01 EST

Next message: Yang Jihong: "[PATCH v2 2/5] perf sched: Fix memory leak in perf_sched__map()"
Previous message: Yang Jihong: "[PATCH v2 4/5] perf sched: Move curr_pid and cpu_last_switched initialization to perf_sched__{lat|map|replay}()"
Next in thread: Yang Jihong: "[PATCH v2 5/5] perf thread_map: Free strlist on normal path in thread_map__new_by_tid_str()"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

start_work_mutex, work_done_wait_mutex, curr_thread, curr_pid, and
cpu_last_switched are initialized together in cmd_sched(),
but for different perf sched subcommands, some actions are unnecessary,
especially perf sched record.
This series of patches initialize only required resources for different
subcommands.

Simple functional testing:

# perf sched record perf bench sched messaging
# Running 'sched/messaging' benchmark:
# 20 sender and receiver processes per group
# 10 groups == 400 processes run

Total time: 0.204 [sec]
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 14.868 MB perf.data (133947 samples) ]

# perf sched latency

-------------------------------------------------------------------------------------------------------------------------------------------
Task | Runtime ms | Switches | Avg delay ms | Max delay ms | Max delay start | Max delay end |
-------------------------------------------------------------------------------------------------------------------------------------------
qemu-system-x86:(3) | 2.753 ms | 10 | avg: 0.963 ms | max: 8.526 ms | max start: 457541.695704 s | max end: 457541.704230 s
sched-messaging:(401) | 2995.481 ms | 36312 | avg: 0.944 ms | max: 111.551 ms | max start: 457541.645349 s | max end: 457541.756900 s
rcu_sched:14 | 0.402 ms | 32 | avg: 0.266 ms | max: 7.996 ms | max start: 457541.581363 s | max end: 457541.589359 s
sshd:48125 | 0.461 ms | 2 | avg: 0.033 ms | max: 0.036 ms | max start: 457541.584374 s | max end: 457541.584410 s
perf:112408 | 2.321 ms | 2 | avg: 0.031 ms | max: 0.032 ms | max start: 457541.846874 s | max end: 457541.846906 s
<SNIP>
ksoftirqd/1:22 | 0.704 ms | 3 | avg: 0.005 ms | max: 0.005 ms | max start: 457541.845388 s | max end: 457541.845393 s
kworker/15:0-mm:61886 | 0.227 ms | 21 | avg: 0.005 ms | max: 0.006 ms | max start: 457541.739187 s | max end: 457541.739193 s
kworker/13:1-ev:92643 | 0.249 ms | 22 | avg: 0.005 ms | max: 0.006 ms | max start: 457541.768695 s | max end: 457541.768701 s
kworker/12:1-ev:61202 | 0.418 ms | 40 | avg: 0.005 ms | max: 0.007 ms | max start: 457541.739679 s | max end: 457541.739687 s
-----------------------------------------------------------------------------------------------------------------
TOTAL: | 3007.424 ms | 36776 |
---------------------------------------------------

# echo $?
0

# perf sched map
*A0 457541.580856 secs A0 => migration/0:15
*. 457541.580886 secs . => swapper:0
. *B0 457541.581018 secs B0 => migration/1:21
. *. 457541.581050 secs
. . *C0 457541.581147 secs C0 => migration/2:27
. . *. 457541.581174 secs
. . . *D0 457541.581259 secs D0 => migration/3:33
<SNIP>
E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 *E7 . . . . 457541.847783 secs
E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 *E7 . . . 457541.847873 secs
E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 *E7 . . 457541.847954 secs
E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 *E7 . 457541.848034 secs
E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 E7 *E7 457541.848108 secs
# echo $?
0

# perf sched replay
run measurement overhead: 108 nsecs
sleep measurement overhead: 65244 nsecs
the run test took 1000002 nsecs
the sleep test took 1079677 nsecs
nr_run_events: 40700
nr_sleep_events: 41415
nr_wakeup_events: 31601
target-less wakeups: 15
multi-target wakeups: 805
task 0 ( swapper: 0), nr_events: 7307
task 1 ( swapper: 1), nr_events: 1
task 2 ( swapper: 2), nr_events: 1
<SNIP>
task 713 ( sched-messaging: 112809), nr_events: 987
task 714 ( sched-messaging: 112810), nr_events: 2706
------------------------------------------------------------
#1 : 1298.443, ravg: 1298.44, cpu: 8281.74 / 8281.74
#2 : 1316.426, ravg: 1300.24, cpu: 7577.61 / 8211.32
#3 : 1323.864, ravg: 1302.60, cpu: 7932.48 / 8183.44
#4 : 1329.423, ravg: 1305.29, cpu: 7646.17 / 8129.71
#5 : 1321.419, ravg: 1306.90, cpu: 7669.90 / 8083.73
#6 : 1322.082, ravg: 1308.42, cpu: 7755.66 / 8050.92
#7 : 1324.330, ravg: 1310.01, cpu: 7361.51 / 7981.98
#8 : 1312.489, ravg: 1310.26, cpu: 7170.11 / 7900.80
#9 : 1312.002, ravg: 1310.43, cpu: 7176.40 / 7828.36
#10 : 1311.737, ravg: 1310.56, cpu: 7121.14 / 7757.63
# echo $?
0

# perf sched script
perf 112408 [000] 457541.580826: sched:sched_stat_runtime: comm=perf pid=112408 runtime=53050 [ns] vruntime=621244222333 [ns]
perf 112408 [000] 457541.580831: sched:sched_waking: comm=migration/0 pid=15 prio=0 target_cpu=000
perf 112408 [000] 457541.580853: sched:sched_stat_runtime: comm=perf pid=112408 runtime=24379 [ns] vruntime=621244246712 [ns]
perf 112408 [000] 457541.580856: sched:sched_switch: prev_comm=perf prev_pid=112408 prev_prio=120 prev_state=R+ ==> next_comm=migration/0 next_pid=15 next_prio=0
<SNIP>
swapper 0 [012] 457541.847873: sched:sched_switch: prev_comm=swapper/12 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=112408 next_prio=120
swapper 0 [013] 457541.847954: sched:sched_switch: prev_comm=swapper/13 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=112408 next_prio=120
swapper 0 [014] 457541.848034: sched:sched_switch: prev_comm=swapper/14 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=112408 next_prio=120
swapper 0 [015] 457541.848108: sched:sched_switch: prev_comm=swapper/15 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=112408 next_prio=120
# echo $?
0

# perf sched timehist
Samples do not have callchains.
time cpu task name wait time sch delay run time
[tid/pid] (msec) (msec) (msec)
--------------- ------ ------------------------------ --------- --------- ---------
457541.580856 [0000] perf[112408] 0.000 0.000 0.000
457541.580886 [0000] migration/0[15] 0.000 0.024 0.029
457541.581018 [0001] perf[112408] 0.000 0.000 0.000
457541.581050 [0001] migration/1[21] 0.000 0.006 0.032
457541.581147 [0002] perf[112408] 0.000 0.000 0.000
457541.581174 [0002] migration/2[27] 0.000 0.005 0.026
<SNIP>
457541.847623 [0009] <idle> 0.010 0.000 1.489
457541.847704 [0010] <idle> 0.012 0.000 1.777
457541.847783 [0011] <idle> 0.233 0.000 1.213
457541.847873 [0012] <idle> 0.008 0.000 24.188
457541.847954 [0013] <idle> 0.009 0.000 1.734
457541.848034 [0014] <idle> 0.009 0.000 2.969
457541.848108 [0015] <idle> 0.220 0.000 1.205
# echo $?
0

Changes since v1:
- Change goto labels name to out_put_xxx in perf_sched__map().
- Use zfree to replace free.
- Add fixes tag and reviewed-by tag for Arnaldo.

Yang Jihong (5):
perf sched: Move start_work_mutex and work_done_wait_mutex
initialization to perf_sched__replay()
perf sched: Fix memory leak in perf_sched__map()
perf sched: Move curr_thread initialization to perf_sched__map()
perf sched: Move curr_pid and cpu_last_switched initialization to
perf_sched__{lat|map|replay}()
perf thread_map: Free strlist on normal path in
thread_map__new_by_tid_str()

tools/perf/builtin-sched.c | 163 ++++++++++++++++++++++-------------
tools/perf/util/thread_map.c | 2 +-
2 files changed, 105 insertions(+), 60 deletions(-)

--
2.34.1

Next message: Yang Jihong: "[PATCH v2 2/5] perf sched: Fix memory leak in perf_sched__map()"
Previous message: Yang Jihong: "[PATCH v2 4/5] perf sched: Move curr_pid and cpu_last_switched initialization to perf_sched__{lat|map|replay}()"
Next in thread: Yang Jihong: "[PATCH v2 5/5] perf thread_map: Free strlist on normal path in thread_map__new_by_tid_str()"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]