LinuxLists.cc - [linus:master] [NFSD] 39d432fc76: fsmark.files_per

2023-08-24 11:33:25

Subject: [linus:master] [NFSD] 39d432fc76: fsmark.files_per_sec -100.0% regression

hi, Chuck Lever,

Fengwei (CCed) helped and doubt below part:
- nfsd4_end_grace(nn);
+ trace_nfsd_end_grace(n
and confirmed if adding back:
nfsd4_end_grace(nn);

the regression is
FYI.

Hello,

kernel test robot

commit: 39d432fc76301cf0a0
Details are as below:
--------------------------

The kernel config
us review this astonishing finding by fsmark tests,
etns(file));
gone and files_per_sec restore to 61.93.
noticed a -100.0% regression of fsmark.files_per_sec on:
c454022117601994ca9397 ("NFSD: trace nfsctl operations")
el.org/cgit/linux/kernel/git/torvalds/linux.git">https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master
threads 2 sockets Intel(R) Xeon(R) Gold 6346 CPU @ 3.10GHz (Ice Lake) with 256G memory
the commit also has significant impact on the following tests:
-------------------------------------------------------------------------------------+
| fsmark: fsmark.files_per_sec -100.0% regression |
| 64 threads 2 sockets Intel(R) Xeon(R) Gold 6346 CPU @ 3.10GHz (Ice Lake) with 256G memory |
| cpufreq_governor=performance |
| debug-setup=no-monitor |
|
|
|
|
|
| nr_directories=16d |
| nr_files_per_directory=256fpd |
|
| sync_method=NoSync |
|
-------------------------------------------------------------------------------------+
in a separate patch/commit (i.e. not just a new version of
kindly add following tags
test robot <[email protected]>
//lore.kernel.org/oe-lkp/202308241229.68396422-oliver.sang@intel.com">https://lore.kernel.org/oe-lkp/[email protected]
------------------------------------------------------------------------>
and materials to reproduce are available at:
.01.org/0day-ci/archive/20230824/202308241229.68396422-oliver.sang@intel.com">https://download.01.org/0day-ci/archive/20230824/[email protected]
===============================================================
disk/filesize/fs2/fs/iterations/kconfig/nr_directories/nr_files_per_directory/nr_threads/rootfs/sync_method/tbox_group/test_size/testcase:
16MB/nfsv4/btrfs/1x/x86_64-rhel-8.3/16d/256fpd/32t/debian-11.1-x86_64-20220510.cgz/NoSync/lkp-icl-2sp7/20G/fsmark
Clean up nfsctl_transaction_write()")
trace nfsctl operations")
39d432fc76301cf0a0c45402211
---------------------------
%stddev
\
4.75 ? 45% perf-c2c.DRAM.local
47.81 ? 16% boot-time.dhcp
3.46 ? 31% boot-time.smp_boot
+12542.8% 1.839e+11 ? 20% cpuidle..time
+6257.5% 1.916e+08 ? 20% cpuidle..usage
3129 ? 18% uptime.boot
189897 ? 19% uptime.idle
94.75 iostat.cpu.idle
2.85 ? 56% iostat.cpu.iowait
2.37 iostat.cpu.system
0.03 ? 15% iostat.cpu.user
+37.6% 9873307 ? 6% numa-numastat.node0.local_node
+37.5% 9914765 ? 6% numa-numastat.node0.numa_hit
+29.1% 8981736 ? 4% numa-numastat.node1.local_node
+28.8% 9006618 ? 4% numa-numastat.node1.numa_hit
+7050.4% 6.256e+08 ? 18% fsmark.app_overhead
0.00 fsmark.files_per_sec
2951 ? 20% fsmark.time.elapsed_time
2951 ? 20% fsmark.time.elapsed_time.max
1.00 fsmark.time.percent_of_cpu_this_job_got
94.75 mpstat.cpu.all.idle%
2.86 ? 56% mpstat.cpu.all.iowait%
2.20 mpstat.cpu.all.irq%
0.07 ? 3% mpstat.cpu.all.soft%
0.09 ? 12% mpstat.cpu.all.sys%
0.03 ? 15% mpstat.cpu.all.usr%
94.50 vmstat.cpu.id
2.25 ? 79% vmstat.cpu.wa
7461 ? 21% vmstat.io.bo
1.50 ? 74% vmstat.procs.b
0.00 vmstat.procs.r
8688 ? 8% vmstat.system.cs
-9.1% 64225 vmstat.system.in
97246 ? 9% meminfo.Active
76266 ? 6% meminfo.Active(anon)
20978 ? 24% meminfo.Active(file)
227542 meminfo.AnonHugePages
-24.1% 301733 meminfo.AnonPages
-19.5% 525838 meminfo.Committed_AS
89789 ? 4% meminfo.Dirty
-23.5% 307192 meminfo.Inactive(anon)
29548 meminfo.Mapped
4950 meminfo.PageTables
82421 ? 6% meminfo.Shmem
+25.1% 406488 ? 2% meminfo.Writeback
15195 ? 36% numa-meminfo.node0.Active(anon)
12450 ? 30% numa-meminfo.node0.Active(file)
184526 ? 25% numa-meminfo.node0.AnonHugePages
48963 ? 8% numa-meminfo.node0.Dirty
19573 ? 31% numa-meminfo.node0.Shmem
69601 ? 9% numa-meminfo.node1.Active
61072 ? 5% numa-meminfo.node1.Active(anon)
8528 ? 46% numa-meminfo.node1.Active(file)
59692 ? 75% numa-meminfo.node1.AnonPages
40835 ? 14% numa-meminfo.node1.Dirty
61274 ? 73% numa-meminfo.node1.Inactive(anon)
1973 ? 21% numa-meminfo.node1.PageTables
62849 ? 5% numa-meminfo.node1.Shmem
29.25 turbostat.Avg_MHz
3.23 turbostat.Busy%
-69.7% 909.25 turbostat.Bzy_MHz
491105 ? 18% turbostat.C1
0.01 ? 57% turbostat.C1%
+679.9% 6624934 ? 48% turbostat.C1E
3.02 ? 53% turbostat.C1E%
+17084.8% 1.835e+08 ? 20% turbostat.C6
94.19 turbostat.C6%
96.76 turbostat.CPU%c1
0.01 ? 34% turbostat.CPU%c6
0.09 turbostat.IPC
+10114.2% 1.898e+08 ? 20% turbostat.IRQ
0.01 ?100% turbostat.POLL%
-23.3% 118.17 turbostat.PkgWatt
53.29 turbostat.RAMWatt
3798 ? 36% numa-vmstat.node0.nr_active_anon
3112 ? 30% numa-vmstat.node0.nr_active_file
89.75 ? 25% numa-vmstat.node0.nr_anon_transparent_hugepages
12194 ? 8% numa-vmstat.node0.nr_dirty
4893 ? 31% numa-vmstat.node0.nr_shmem
3798 ? 36% numa-vmstat.node0.nr_zone_active_anon
3112 ? 30% numa-vmstat.node0.nr_zone_active_file
14783 ? 10% numa-vmstat.node0.nr_zone_write_pending
+37.5% 9914914 ? 6% numa-vmstat.node0.numa_hit
+37.6% 9873455 ? 6% numa-vmstat.node0.numa_local
15268 ? 5% numa-vmstat.node1.nr_active_anon
2132 ? 46% numa-vmstat.node1.nr_active_file
14923 ? 75% numa-vmstat.node1.nr_anon_pages
10204 ? 14% numa-vmstat.node1.nr_dirty
15318 ? 73% numa-vmstat.node1.nr_inactive_anon
-37.3% 492.75 ? 21% numa-vmstat.node1.nr_page_table_pages
15712 ? 5% numa-vmstat.node1.nr_shmem
15268 ? 5% numa-vmstat.node1.nr_zone_active_anon
2132 ? 46% numa-vmstat.node1.nr_zone_active_file
15318 ? 73% numa-vmstat.node1.nr_zone_inactive_anon
12864 ? 19% numa-vmstat.node1.nr_zone_write_pending
+28.8% 9006790 ? 4% numa-vmstat.node1.numa_hit
+29.1% 8981908 ? 4% numa-vmstat.node1.numa_local
19066 ? 6% proc-vmstat.nr_active_anon
5244 ? 24% proc-vmstat.nr_active_file
75431 proc-vmstat.nr_anon_pages
110.75 proc-vmstat.nr_anon_transparent_hugepages
22410 ? 4% proc-vmstat.nr_dirty
76796 proc-vmstat.nr_inactive_anon
-6.6% 14560 proc-vmstat.nr_kernel_stack
7386 proc-vmstat.nr_mapped
1236 proc-vmstat.nr_page_table_pages
20605 ? 6% proc-vmstat.nr_shmem
+24.9% 101605 ? 2% proc-vmstat.nr_writeback
19066 ? 6% proc-vmstat.nr_zone_active_anon
5244 ? 24% proc-vmstat.nr_zone_active_file
76796 proc-vmstat.nr_zone_inactive_anon
27641 ? 12% proc-vmstat.nr_zone_write_pending
5569 ? 13% proc-vmstat.numa_hint_faults
3065 ? 77% proc-vmstat.numa_hint_faults_local
+33.2% 18923999 ? 5% proc-vmstat.numa_hit
+33.4% 18857658 ? 5% proc-vmstat.numa_local
4366 ? 82% proc-vmstat.numa_pages_migrated
39487 ? 15% proc-vmstat.numa_pte_updates
21048 ? 5% proc-vmstat.pgactivate
+26.2% 23897622 ? 4% proc-vmstat.pgalloc_normal
6188094 ? 19% proc-vmstat.pgfault
+37.7% 18558535 ? 5% proc-vmstat.pgfree
4366 ? 82% proc-vmstat.pgmigrate_success
298318 ? 19% proc-vmstat.pgreuse
+3336.2% 21894720 ? 20% proc-vmstat.unevictable_pgs_scanned
0.05 sched_debug.cfs_rq:/.h_nr_running.avg
0.22 sched_debug.cfs_rq:/.h_nr_running.stddev
31261 ? 2% sched_debug.cfs_rq:/.load.avg
30.67 ? 14% sched_debug.cfs_rq:/.load_avg.avg
-20.8% 834.32 ? 3% sched_debug.cfs_rq:/.load_avg.max
-48.8% 140.77 ? 7% sched_debug.cfs_rq:/.load_avg.stddev
22072 ? 17% sched_debug.cfs_rq:/.min_vruntime.avg
56195 ? 15% sched_debug.cfs_rq:/.min_vruntime.max
11216 ? 14% sched_debug.cfs_rq:/.min_vruntime.min
8663 ? 13% sched_debug.cfs_rq:/.min_vruntime.stddev
0.05 sched_debug.cfs_rq:/.nr_running.avg
0.22 sched_debug.cfs_rq:/.nr_running.stddev
4.53 ? 76% sched_debug.cfs_rq:/.removed.load_avg.avg
-87.2% 131.45 ?119% sched_debug.cfs_rq:/.removed.load_avg.max
22.40 ?101% sched_debug.cfs_rq:/.removed.load_avg.stddev
2.00 ? 84% sched_debug.cfs_rq:/.removed.runnable_avg.avg
66.39 ?118% sched_debug.cfs_rq:/.removed.runnable_avg.max
10.66 ?106% sched_debug.cfs_rq:/.removed.runnable_avg.stddev
2.00 ? 84% sched_debug.cfs_rq:/.removed.util_avg.avg
66.39 ?118% sched_debug.cfs_rq:/.removed.util_avg.max
10.66 ?106% sched_debug.cfs_rq:/.removed.util_avg.stddev
30.55 ? 10% sched_debug.cfs_rq:/.runnable_avg.avg
-65.3% 573.91 sched_debug.cfs_rq:/.runnable_avg.max
98.67 ? 4% sched_debug.cfs_rq:/.runnable_avg.stddev
8663 ? 13% sched_debug.cfs_rq:/.spread0.stddev
30.54 ? 10% sched_debug.cfs_rq:/.util_avg.avg
-65.2% 573.90 sched_debug.cfs_rq:/.util_avg.max
98.65 ? 4% sched_debug.cfs_rq:/.util_avg.stddev
2.57 ? 23% sched_debug.cfs_rq:/.util_est_enqueued.avg
73.92 ? 11% sched_debug.cfs_rq:/.util_est_enqueued.max
11.82 ? 13% sched_debug.cfs_rq:/.util_est_enqueued.stddev
+25.1% 966950 sched_debug.cpu.avg_idle.avg
383238 ? 36% sched_debug.cpu.avg_idle.min
-62.7% 106134 ? 15% sched_debug.cpu.avg_idle.stddev
1637565 ? 18% sched_debug.cpu.clock.avg
1637568 ? 18% sched_debug.cpu.clock.max
1637561 ? 18% sched_debug.cpu.clock.min
1.98 ? 3% sched_debug.cpu.clock.stddev
1603047 ? 18% sched_debug.cpu.clock_task.avg
1605532 ? 18% sched_debug.cpu.clock_task.max
1578791 ? 18% sched_debug.cpu.clock_task.min
3269 ? 31% sched_debug.cpu.clock_task.stddev
41168 ? 18% sched_debug.cpu.curr->pid.max
5166 ? 17% sched_debug.cpu.curr->pid.stddev
0.00 ? 4% sched_debug.cpu.next_balance.stddev
0.03 ? 4% sched_debug.cpu.nr_running.avg
0.15 ? 2% sched_debug.cpu.nr_running.stddev
201964 ? 20% sched_debug.cpu.nr_switches.avg
696661 ? 25% sched_debug.cpu.nr_switches.max
43305 ? 29% sched_debug.cpu.nr_switches.min
121580 ? 15% sched_debug.cpu.nr_switches.stddev
1637561 ? 18% sched_debug.cpu_clk
1636836 ? 18% sched_debug.ktime
1620032 ? 18% sched_debug.sched_clk
3.74 perf-stat.i.MPKI
-94.8% 96458674 ? 5% perf-stat.i.branch-instructions
0.80 perf-stat.i.branch-miss-rate%
-95.7% 961876 ? 9% perf-stat.i.branch-misses
8.66 perf-stat.i.cache-miss-rate%
-99.1% 801389 ? 18% perf-stat.i.cache-misses
-98.3% 2538095 ? 10% perf-stat.i.cache-references
8685 ? 8% perf-stat.i.context-switches
2.33 perf-stat.i.cpi
-95.2% 1.081e+09 ? 3% perf-stat.i.cpu-cycles
74.16 perf-stat.i.cpu-migrations
10071 ? 2% perf-stat.i.cycles-between-cache-misses
0.09 ? 23% perf-stat.i.dTLB-load-miss-rate%
-86.2% 101019 ? 22% perf-stat.i.dTLB-load-misses
-94.3% 1.281e+08 ? 4% perf-stat.i.dTLB-loads
0.04 ? 13% perf-stat.i.dTLB-store-miss-rate%
23688 ? 11% perf-stat.i.dTLB-store-misses
-93.2% 67811239 ? 3% perf-stat.i.dTLB-stores
-94.6% 4.866e+08 ? 4% perf-stat.i.instructions
0.01 ? 42% perf-stat.i.major-faults
0.02 ? 3% perf-stat.i.metric.GHz
-34.7% 802.68 perf-stat.i.metric.K/sec
3.81 ? 5% perf-stat.i.metric.M/sec
1998 perf-stat.i.minor-faults
94.08 perf-stat.i.node-load-miss-rate%
-99.0% 176907 ? 14% perf-stat.i.node-load-misses
-99.1% 144408 ? 22% perf-stat.i.node-loads
31.45 ? 27% perf-stat.i.node-store-miss-rate%
49478 ? 9% perf-stat.i.node-store-misses
-99.1% 320605 ? 19% perf-stat.i.node-stores
1998 perf-stat.i.page-faults
5.21 ? 5% perf-stat.overall.MPKI
1.00 ? 4% perf-stat.overall.branch-miss-rate%
31.34 ? 8% perf-stat.overall.cache-miss-rate%
2.22 perf-stat.overall.cpi
1385 ? 15% perf-stat.overall.cycles-between-cache-misses
0.08 ? 22% perf-stat.overall.dTLB-load-miss-rate%
0.03 ? 12% perf-stat.overall.dTLB-store-miss-rate%
0.45 perf-stat.overall.ipc
-94.5% 96442481 ? 5% perf-stat.ps.branch-instructions
-95.5% 961854 ? 9% perf-stat.ps.branch-misses
-99.1% 801893 ? 18% perf-stat.ps.cache-misses
-98.2% 2538635 ? 10% perf-stat.ps.cache-references
8683 ? 8% perf-stat.ps.context-switches
+4.3% 63977 perf-stat.ps.cpu-clock
-95.0% 1.081e+09 ? 3% perf-stat.ps.cpu-cycles
74.14 perf-stat.ps.cpu-migrations
-85.6% 100987 ? 22% perf-stat.ps.dTLB-load-misses
-94.1% 1.281e+08 ? 4% perf-stat.ps.dTLB-loads
23681 ? 11% perf-stat.ps.dTLB-store-misses
-92.9% 67795911 ? 3% perf-stat.ps.dTLB-stores
-94.4% 4.866e+08 ? 4% perf-stat.ps.instructions
0.01 ? 42% perf-stat.ps.major-faults
1998 perf-stat.ps.minor-faults
-99.0% 177005 ? 14% perf-stat.ps.node-load-misses
-99.1% 144476 ? 22% perf-stat.ps.node-loads
49511 ? 10% perf-stat.ps.node-store-misses
-99.1% 320794 ? 19% perf-stat.ps.node-stores
1998 perf-stat.ps.page-faults
+4.3% 63977 perf-stat.ps.task-clock
+589.5% 1.424e+12 ? 16% perf-stat.total.instructions
0.02 ? 20% perf-sched.sch_delay.avg.ms.devkmsg_read.vfs_read.ksys_read.do_syscall_64
0.01 ? 14% perf-sched.sch_delay.avg.ms.do_nanosleep.hrtimer_nanosleep.common_nsleep.__x64_sys_clock_nanosleep
0.05 ? 3% perf-sched.sch_delay.avg.ms.irq_thread.kthread.ret_from_fork
0.00 ? 19% perf-sched.sch_delay.avg.ms.pipe_read.vfs_read.ksys_read.do_syscall_64
0.02 ? 7% perf-sched.sch_delay.avg.ms.worker_thread.kthread.ret_from_fork
0.01 ? 13% perf-sched.sch_delay.max.ms.__x64_sys_pause.do_syscall_64.entry_SYSCALL_64_after_hwframe.[unknown]
0.07 perf-sched.sch_delay.max.ms.irq_thread.kthread.ret_from_fork
0.02 ? 12% perf-sched.sch_delay.max.ms.schedule_hrtimeout_range_clock.do_poll.constprop.0.do_sys_poll
0.03 ? 25% perf-sched.sch_delay.max.ms.smpboot_thread_fn.kthread.ret_from_fork
0.01 perf-sched.total_sch_delay.average.ms
3.20 ? 12% perf-sched.total_sch_delay.max.ms
34.20 ? 5% perf-sched.total_wait_and_delay.average.ms
20478 ? 4% perf-sched.total_wait_and_delay.count.ms
4992 perf-sched.total_wait_and_delay.max.ms
34.20 ? 5% perf-sched.total_wait_time.average.ms
4992 perf-sched.total_wait_time.max.ms
23.43 perf-sched.wait_and_delay.avg.ms.__cond_resched.__wait_for_common.affine_move_task.__set_cpus_allowed_ptr.__sched_setaffinity
0.00 perf-sched.wait_and_delay.avg.ms.devkmsg_read.vfs_read.ksys_read.do_syscall_64
250.13 ? 3% perf-sched.wait_and_delay.avg.ms.do_task_dead.do_exit.do_group_exit.__x64_sys_exit_group.do_syscall_64
+46.7% 101.87 perf-sched.wait_and_delay.avg.ms.irq_thread.kthread.ret_from_fork
40.63 ? 2% perf-sched.wait_and_delay.avg.ms.pipe_read.vfs_read.ksys_read.do_syscall_64
377.57 perf-sched.wait_and_delay.avg.ms.schedule_hrtimeout_range_clock.ep_poll.do_epoll_wait.__x64_sys_epoll_wait
29.42 ? 6% perf-sched.wait_and_delay.avg.ms.schedule_timeout.rcu_gp_fqs_loop.rcu_gp_kthread.kthread
667.82 perf-sched.wait_and_delay.avg.ms.smpboot_thread_fn.kthread.ret_from_fork
412.11 ? 4% perf-sched.wait_and_delay.avg.ms.worker_thread.kthread.ret_from_fork
+56.7% 384.00 perf-sched.wait_and_delay.count.__cond_resched.__wait_for_common.affine_move_task.__set_cpus_allowed_ptr.__sched_setaffinity
0.00 perf-sched.wait_and_delay.count.devkmsg_read.vfs_read.ksys_read.do_syscall_64
-75.6% 124.00 perf-sched.wait_and_delay.count.do_task_dead.do_exit.do_group_exit.__x64_sys_exit_group.do_syscall_64
-72.7% 123.00 perf-sched.wait_and_delay.count.do_wait.kernel_wait4.__do_sys_wait4.do_syscall_64
48.00 perf-sched.wait_and_delay.count.irq_thread.kthread.ret_from_fork
1776 ? 2% perf-sched.wait_and_delay.count.pipe_read.vfs_read.ksys_read.do_syscall_64
162.75 ? 6% perf-sched.wait_and_delay.count.schedule_timeout.rcu_gp_fqs_loop.rcu_gp_kthread.kthread
+71.9% 520.50 perf-sched.wait_and_delay.count.smpboot_thread_fn.kthread.ret_from_fork
366.75 ? 4% perf-sched.wait_and_delay.count.worker_thread.kthread.ret_from_fork
4992 perf-sched.wait_and_delay.max.ms.__cond_resched.__wait_for_common.affine_move_task.__set_cpus_allowed_ptr.__sched_setaffinity
0.00 perf-sched.wait_and_delay.max.ms.devkmsg_read.vfs_read.ksys_read.do_syscall_64
1514 ? 31% perf-sched.wait_and_delay.max.ms.do_task_dead.do_exit.do_group_exit.__x64_sys_exit_group.do_syscall_64
1005 perf-sched.wait_and_delay.max.ms.pipe_read.vfs_read.ksys_read.do_syscall_64
+70.7% 499.98 perf-sched.wait_and_delay.max.ms.schedule_hrtimeout_range_clock.ep_poll.do_epoll_wait.__x64_sys_epoll_wait
340.75 ? 18% perf-sched.wait_and_delay.max.ms.schedule_timeout.rcu_gp_fqs_loop.rcu_gp_kthread.kthread
2752 ? 29% perf-sched.wait_and_delay.max.ms.smpboot_thread_fn.kthread.ret_from_fork
2443 ? 13% perf-sched.wait_and_delay.max.ms.worker_thread.kthread.ret_from_fork
23.43 perf-sched.wait_time.avg.ms.__cond_resched.__wait_for_common.affine_move_task.__set_cpus_allowed_ptr.__sched_setaffinity
1.82 ? 12% perf-sched.wait_time.avg.ms.devkmsg_read.vfs_read.ksys_read.do_syscall_64
766.71 ? 7% perf-sched.wait_time.avg.ms.do_nanosleep.hrtimer_nanosleep.common_nsleep.__x64_sys_clock_nanosleep
250.12 ? 3% perf-sched.wait_time.avg.ms.do_task_dead.do_exit.do_group_exit.__x64_sys_exit_group.do_syscall_64
0.00 perf-sched.wait_time.avg.ms.do_task_dead.do_exit.do_group_exit.get_signal.arch_do_signal_or_restart
+46.6% 101.82 perf-sched.wait_time.avg.ms.irq_thread.kthread.ret_from_fork
40.62 ? 2% perf-sched.wait_time.avg.ms.pipe_read.vfs_read.ksys_read.do_syscall_64
377.56 perf-sched.wait_time.avg.ms.schedule_hrtimeout_range_clock.ep_poll.do_epoll_wait.__x64_sys_epoll_wait
0.49 ? 7% perf-sched.wait_time.avg.ms.schedule_timeout.__wait_for_common.wait_for_completion_state.kernel_clone
29.41 ? 6% perf-sched.wait_time.avg.ms.schedule_timeout.rcu_gp_fqs_loop.rcu_gp_kthread.kthread
667.81 perf-sched.wait_time.avg.ms.smpboot_thread_fn.kthread.ret_from_fork
412.09 ? 4% perf-sched.wait_time.avg.ms.worker_thread.kthread.ret_from_fork
4992 perf-sched.wait_time.max.ms.__cond_resched.__wait_for_common.affine_move_task.__set_cpus_allowed_ptr.__sched_setaffinity
3.65 ? 12% perf-sched.wait_time.max.ms.devkmsg_read.vfs_read.ksys_read.do_syscall_64
1000 perf-sched.wait_time.max.ms.do_nanosleep.hrtimer_nanosleep.common_nsleep.__x64_sys_clock_nanosleep
1514 ? 31% perf-sched.wait_time.max.ms.do_task_dead.do_exit.do_group_exit.__x64_sys_exit_group.do_syscall_64
0.00 perf-sched.wait_time.max.ms.do_task_dead.do_exit.do_group_exit.get_signal.arch_do_signal_or_restart
1005 perf-sched.wait_time.max.ms.pipe_read.vfs_read.ksys_read.do_syscall_64
+70.7% 499.97 perf-sched.wait_time.max.ms.schedule_hrtimeout_range_clock.ep_poll.do_epoll_wait.__x64_sys_epoll_wait
1.09 ? 12% perf-sched.wait_time.max.ms.schedule_timeout.__wait_for_common.wait_for_completion_state.kernel_clone
340.74 ? 18% perf-sched.wait_time.max.ms.schedule_timeout.rcu_gp_fqs_loop.rcu_gp_kthread.kthread
2752 ? 29% perf-sched.wait_time.max.ms.smpboot_thread_fn.kthread.ret_from_fork
2443 ? 13% perf-sched.wait_time.max.ms.worker_thread.kthread.ret_from_fork
1.29 ? 9% perf-profile.calltrace.cycles-pp.do_syscall_64.entry_SYSCALL_64_after_hwframe
1.29 ? 8% perf-profile.calltrace.cycles-pp.entry_SYSCALL_64_after_hwframe
0.16 ?173% perf-profile.calltrace.cycles-pp.exit_mmap.__mmput.exit_mm.do_exit.do_group_exit
0.00 perf-profile.calltrace.cycles-pp.unmap_vmas.exit_mmap.__mmput.exit_mm.do_exit
0.00 perf-profile.calltrace.cycles-pp.unmap_page_range.unmap_vmas.exit_mmap.__mmput.exit_mm
0.00 perf-profile.calltrace.cycles-pp.zap_pmd_range.unmap_page_range.unmap_vmas.exit_mmap.__mmput
0.00 perf-profile.calltrace.cycles-pp.zap_pte_range.zap_pmd_range.unmap_page_range.unmap_vmas.exit_mmap
0.00 perf-profile.calltrace.cycles-pp.do_group_exit.get_signal.arch_do_signal_or_restart.exit_to_user_mode_loop.exit_to_user_mode_prepare
0.00 perf-profile.calltrace.cycles-pp.do_exit.do_group_exit.get_signal.arch_do_signal_or_restart.exit_to_user_mode_loop
0.00 perf-profile.calltrace.cycles-pp.exit_mm.do_exit.do_group_exit.get_signal.arch_do_signal_or_restart
0.00 perf-profile.calltrace.cycles-pp.__mmput.exit_mm.do_exit.do_group_exit.get_signal
0.00 perf-profile.calltrace.cycles-pp.exit_to_user_mode_loop.exit_to_user_mode_prepare.syscall_exit_to_user_mode.do_syscall_64.entry_SYSCALL_64_after_hwframe
0.00 perf-profile.calltrace.cycles-pp.syscall_exit_to_user_mode.do_syscall_64.entry_SYSCALL_64_after_hwframe
0.00 perf-profile.calltrace.cycles-pp.exit_to_user_mode_prepare.syscall_exit_to_user_mode.do_syscall_64.entry_SYSCALL_64_after_hwframe
0.00 perf-profile.calltrace.cycles-pp.arch_do_signal_or_restart.exit_to_user_mode_loop.exit_to_user_mode_prepare.syscall_exit_to_user_mode.do_syscall_64
0.00 perf-profile.calltrace.cycles-pp.get_signal.arch_do_signal_or_restart.exit_to_user_mode_loop.exit_to_user_mode_prepare.syscall_exit_to_user_mode
0.00 perf-profile.calltrace.cycles-pp.page_remove_rmap.zap_pte_range.zap_pmd_range.unmap_page_range.unmap_vmas
0.15 ?173% perf-profile.calltrace.cycles-pp.__libc_start_main
0.15 ?173% perf-profile.calltrace.cycles-pp.main.__libc_start_main
0.15 ?173% perf-profile.calltrace.cycles-pp.run_builtin.main.__libc_start_main
0.18 ?173% perf-profile.calltrace.cycles-pp.do_exit.do_group_exit.__x64_sys_exit_group.do_syscall_64.entry_SYSCALL_64_after_hwframe
0.19 ?173% perf-profile.calltrace.cycles-pp.__x64_sys_exit_group.do_syscall_64.entry_SYSCALL_64_after_hwframe
0.19 ?173% perf-profile.calltrace.cycles-pp.do_group_exit.__x64_sys_exit_group.do_syscall_64.entry_SYSCALL_64_after_hwframe
0.00 perf-profile.calltrace.cycles-pp.entry_SYSCALL_64_after_hwframe.__libc_write.writen.record__pushfn.perf_mmap__push
0.00 perf-profile.calltrace.cycles-pp.do_syscall_64.entry_SYSCALL_64_after_hwframe.__libc_write.writen.record__pushfn
0.00 perf-profile.calltrace.cycles-pp.__generic_file_write_iter.generic_file_write_iter.vfs_write.ksys_write.do_syscall_64
0.00 perf-profile.calltrace.cycles-pp.ksys_write.do_syscall_64.entry_SYSCALL_64_after_hwframe.__libc_write.writen
0.00 perf-profile.calltrace.cycles-pp.generic_file_write_iter.vfs_write.ksys_write.do_syscall_64.entry_SYSCALL_64_after_hwframe
0.00 perf-profile.calltrace.cycles-pp.generic_perform_write.__generic_file_write_iter.generic_file_write_iter.vfs_write.ksys_write
0.00 perf-profile.calltrace.cycles-pp.vfs_write.ksys_write.do_syscall_64.entry_SYSCALL_64_after_hwframe.__libc_write
0.00 perf-profile.calltrace.cycles-pp.record__pushfn.perf_mmap__push.record__mmap_read_evlist.__cmd_record.cmd_record
0.00 perf-profile.calltrace.cycles-pp.writen.record__pushfn.perf_mmap__push.record__mmap_read_evlist.__cmd_record
0.00 perf-profile.calltrace.cycles-pp.__libc_write.writen.record__pushfn.perf_mmap__push.record__mmap_read_evlist
0.00 perf-profile.calltrace.cycles-pp.cmd_record.run_builtin.main.__libc_start_main
0.00 perf-profile.calltrace.cycles-pp.__cmd_record.cmd_record.run_builtin.main.__libc_start_main
0.00 perf-profile.calltrace.cycles-pp.record__mmap_read_evlist.__cmd_record.cmd_record.run_builtin.main
0.00 perf-profile.calltrace.cycles-pp.do_mmap.vm_mmap_pgoff.ksys_mmap_pgoff.do_syscall_64.entry_SYSCALL_64_after_hwframe
0.00 perf-profile.calltrace.cycles-pp.mmap_region.do_mmap.vm_mmap_pgoff.ksys_mmap_pgoff.do_syscall_64
0.00 perf-profile.calltrace.cycles-pp.perf_mmap__push.record__mmap_read_evlist.__cmd_record.cmd_record.run_builtin
0.00 perf-profile.calltrace.cycles-pp.entry_SYSCALL_64_after_hwframe.__mmap
0.00 perf-profile.calltrace.cycles-pp.do_syscall_64.entry_SYSCALL_64_after_hwframe.__mmap
0.00 perf-profile.calltrace.cycles-pp.ksys_mmap_pgoff.do_syscall_64.entry_SYSCALL_64_after_hwframe.__mmap
0.00 perf-profile.calltrace.cycles-pp.vm_mmap_pgoff.ksys_mmap_pgoff.do_syscall_64.entry_SYSCALL_64_after_hwframe.__mmap
0.00 perf-profile.calltrace.cycles-pp.__mmap
0.52 ? 3% perf-profile.calltrace.cycles-pp.__run_timers.run_timer_softirq.__do_softirq.__irq_exit_rcu.sysvec_apic_timer_interrupt
0.52 ? 3% perf-profile.calltrace.cycles-pp.run_timer_softirq.__do_softirq.__irq_exit_rcu.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt
0.59 ? 9% perf-profile.calltrace.cycles-pp.hrtimer_next_event_without.tick_nohz_get_sleep_length.menu_select.cpuidle_idle_call.do_idle
0.71 ? 15% perf-profile.calltrace.cycles-pp._raw_spin_trylock.rebalance_domains.__do_softirq.__irq_exit_rcu.sysvec_apic_timer_interrupt
0.77 ? 25% perf-profile.calltrace.cycles-pp.update_rq_clock_task.scheduler_tick.update_process_times.tick_sched_handle.tick_sched_timer
0.79 ? 12% perf-profile.calltrace.cycles-pp.update_blocked_averages.run_rebalance_domains.__do_softirq.__irq_exit_rcu.sysvec_apic_timer_interrupt
0.80 ? 23% perf-profile.calltrace.cycles-pp.__break_lease.do_dentry_open.dentry_open.__nfsd_open.nfsd_file_do_acquire
0.80 ? 24% perf-profile.calltrace.cycles-pp.__nfsd_open.nfsd_file_do_acquire.nfsd4_commit.nfsd4_proc_compound.nfsd_dispatch
0.80 ? 24% perf-profile.calltrace.cycles-pp.dentry_open.__nfsd_open.nfsd_file_do_acquire.nfsd4_commit.nfsd4_proc_compound
0.80 ? 24% perf-profile.calltrace.cycles-pp.do_dentry_open.dentry_open.__nfsd_open.nfsd_file_do_acquire.nfsd4_commit
0.80 ? 24% perf-profile.calltrace.cycles-pp.nfsd.kthread.ret_from_fork
0.80 ? 24% perf-profile.calltrace.cycles-pp.svc_process.nfsd.kthread.ret_from_fork
0.80 ? 24% perf-profile.calltrace.cycles-pp.svc_process_common.svc_process.nfsd.kthread.ret_from_fork
0.80 ? 24% perf-profile.calltrace.cycles-pp.nfsd_dispatch.svc_process_common.svc_process.nfsd.kthread
0.80 ? 24% perf-profile.calltrace.cycles-pp.nfsd4_proc_compound.nfsd_dispatch.svc_process_common.svc_process.nfsd
0.80 ? 24% perf-profile.calltrace.cycles-pp.nfsd4_commit.nfsd4_proc_compound.nfsd_dispatch.svc_process_common.svc_process
0.80 ? 24% perf-profile.calltrace.cycles-pp.nfsd_file_do_acquire.nfsd4_commit.nfsd4_proc_compound.nfsd_dispatch.svc_process_common
0.81 ? 12% perf-profile.calltrace.cycles-pp.cpuidle_governor_latency_req.menu_select.cpuidle_idle_call.do_idle.cpu_startup_entry
0.84 ? 12% perf-profile.calltrace.cycles-pp.run_rebalance_domains.__do_softirq.__irq_exit_rcu.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt
0.86 ? 8% perf-profile.calltrace.cycles-pp.update_sg_lb_stats.update_sd_lb_stats.find_busiest_group.load_balance.rebalance_domains
1.10 ? 20% perf-profile.calltrace.cycles-pp.tick_nohz_next_event.tick_nohz_get_sleep_length.menu_select.cpuidle_idle_call.do_idle
1.11 ? 2% perf-profile.calltrace.cycles-pp.update_sd_lb_stats.find_busiest_group.load_balance.rebalance_domains.__do_softirq
1.18 ? 5% perf-profile.calltrace.cycles-pp.find_busiest_group.load_balance.rebalance_domains.__do_softirq.__irq_exit_rcu
1.27 ? 28% perf-profile.calltrace.cycles-pp.tick_sched_do_timer.tick_sched_timer.__hrtimer_run_queues.hrtimer_interrupt.__sysvec_apic_timer_interrupt
1.38 ? 49% perf-profile.calltrace.cycles-pp.tick_irq_enter.irq_enter_rcu.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state
1.44 ? 46% perf-profile.calltrace.cycles-pp.irq_enter_rcu.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state.cpuidle_enter
1.45 ? 14% perf-profile.calltrace.cycles-pp.__intel_pmu_enable_all.perf_rotate_context.perf_mux_hrtimer_handler.__hrtimer_run_queues.hrtimer_interrupt
1.51 ? 12% perf-profile.calltrace.cycles-pp.cpuidle_enter.cpuidle_idle_call.do_idle.cpu_startup_entry.rest_init
1.56 perf-profile.calltrace.cycles-pp.load_balance.rebalance_domains.__do_softirq.__irq_exit_rcu.sysvec_apic_timer_interrupt
1.59 ? 12% perf-profile.calltrace.cycles-pp.cpuidle_idle_call.do_idle.cpu_startup_entry.rest_init.arch_call_rest_init
1.59 ? 5% perf-profile.calltrace.cycles-pp.lapic_next_deadline.clockevents_program_event.hrtimer_interrupt.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt
1.61 ? 13% perf-profile.calltrace.cycles-pp.do_idle.cpu_startup_entry.rest_init.arch_call_rest_init.start_kernel
1.62 ? 12% perf-profile.calltrace.cycles-pp.cpu_startup_entry.rest_init.arch_call_rest_init.start_kernel.x86_64_start_reservations
1.62 ? 12% perf-profile.calltrace.cycles-pp.x86_64_start_kernel.secondary_startup_64_no_verify
1.62 ? 12% perf-profile.calltrace.cycles-pp.x86_64_start_reservations.x86_64_start_kernel.secondary_startup_64_no_verify
1.62 ? 12% perf-profile.calltrace.cycles-pp.start_kernel.x86_64_start_reservations.x86_64_start_kernel.secondary_startup_64_no_verify
1.62 ? 12% perf-profile.calltrace.cycles-pp.arch_call_rest_init.start_kernel.x86_64_start_reservations.x86_64_start_kernel.secondary_startup_64_no_verify
1.62 ? 12% perf-profile.calltrace.cycles-pp.rest_init.arch_call_rest_init.start_kernel.x86_64_start_reservations.x86_64_start_kernel
1.72 ? 8% perf-profile.calltrace.cycles-pp.ret_from_fork
1.72 ? 8% perf-profile.calltrace.cycles-pp.kthread.ret_from_fork
1.86 ? 10% perf-profile.calltrace.cycles-pp.perf_rotate_context.perf_mux_hrtimer_handler.__hrtimer_run_queues.hrtimer_interrupt.__sysvec_apic_timer_interrupt
1.97 ? 11% perf-profile.calltrace.cycles-pp.tick_nohz_get_sleep_length.menu_select.cpuidle_idle_call.do_idle.cpu_startup_entry
2.22 ? 4% perf-profile.calltrace.cycles-pp.clockevents_program_event.hrtimer_interrupt.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt
2.56 ? 5% perf-profile.calltrace.cycles-pp.rebalance_domains.__do_softirq.__irq_exit_rcu.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt
2.85 ? 7% perf-profile.calltrace.cycles-pp.perf_mux_hrtimer_handler.__hrtimer_run_queues.hrtimer_interrupt.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt
3.10 ? 8% perf-profile.calltrace.cycles-pp.arch_scale_freq_tick.scheduler_tick.update_process_times.tick_sched_handle.tick_sched_timer
4.40 ? 6% perf-profile.calltrace.cycles-pp.menu_select.cpuidle_idle_call.do_idle.cpu_startup_entry.start_secondary
4.62 ? 5% perf-profile.calltrace.cycles-pp.__do_softirq.__irq_exit_rcu.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state
5.61 ? 11% perf-profile.calltrace.cycles-pp.scheduler_tick.update_process_times.tick_sched_handle.tick_sched_timer.__hrtimer_run_queues
5.51 ? 4% perf-profile.calltrace.cycles-pp.__irq_exit_rcu.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state.cpuidle_enter
7.96 ? 9% perf-profile.calltrace.cycles-pp.update_process_times.tick_sched_handle.tick_sched_timer.__hrtimer_run_queues.hrtimer_interrupt
8.22 ? 9% perf-profile.calltrace.cycles-pp.tick_sched_handle.tick_sched_timer.__hrtimer_run_queues.hrtimer_interrupt.__sysvec_apic_timer_interrupt
10.93 ? 6% perf-profile.calltrace.cycles-pp.tick_sched_timer.__hrtimer_run_queues.hrtimer_interrupt.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt
15.87 ? 4% perf-profile.calltrace.cycles-pp.__hrtimer_run_queues.hrtimer_interrupt.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt
22.07 ? 4% perf-profile.calltrace.cycles-pp.hrtimer_interrupt.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state
22.22 ? 4% perf-profile.calltrace.cycles-pp.__sysvec_apic_timer_interrupt.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state.cpuidle_enter
31.04 ? 5% perf-profile.calltrace.cycles-pp.sysvec_apic_timer_interrupt.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call
39.74 perf-profile.calltrace.cycles-pp.asm_sysvec_apic_timer_interrupt.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call.do_idle
42.16 perf-profile.calltrace.cycles-pp.intel_idle.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call.do_idle
82.34 perf-profile.calltrace.cycles-pp.cpuidle_enter_state.cpuidle_enter.cpuidle_idle_call.do_idle.cpu_startup_entry
83.24 perf-profile.calltrace.cycles-pp.cpuidle_enter.cpuidle_idle_call.do_idle.cpu_startup_entry.start_secondary
90.16 perf-profile.calltrace.cycles-pp.do_idle.cpu_startup_entry.start_secondary.secondary_startup_64_no_verify
90.37 perf-profile.calltrace.cycles-pp.cpu_startup_entry.start_secondary.secondary_startup_64_no_verify
90.38 perf-profile.calltrace.cycles-pp.start_secondary.secondary_startup_64_no_verify
88.95 perf-profile.calltrace.cycles-pp.cpuidle_idle_call.do_idle.cpu_startup_entry.start_secondary.secondary_startup_64_no_verify
92.00 perf-profile.calltrace.cycles-pp.secondary_startup_64_no_verify
3.92 ? 2% perf-profile.children.cycles-pp.do_syscall_64
3.94 ? 2% perf-profile.children.cycles-pp.entry_SYSCALL_64_after_hwframe
0.29 ? 33% perf-profile.children.cycles-pp.zap_pte_range
0.31 ? 36% perf-profile.children.cycles-pp.unmap_page_range
0.31 ? 36% perf-profile.children.cycles-pp.zap_pmd_range
0.33 ? 29% perf-profile.children.cycles-pp.unmap_vmas
0.00 perf-profile.children.cycles-pp.arch_do_signal_or_restart
0.00 perf-profile.children.cycles-pp.get_signal
0.01 ?173% perf-profile.children.cycles-pp.record__mmap_read_evlist
0.01 ?173% perf-profile.children.cycles-pp.generic_perform_write
0.01 ?173% perf-profile.children.cycles-pp.perf_mmap__push
0.01 ?173% perf-profile.children.cycles-pp.record__pushfn
0.01 ?173% perf-profile.children.cycles-pp.writen
0.01 ?173% perf-profile.children.cycles-pp.__libc_write
0.02 ?173% perf-profile.children.cycles-pp.__generic_file_write_iter
0.02 ?173% perf-profile.children.cycles-pp.generic_file_write_iter
0.06 ? 17% perf-profile.children.cycles-pp.unlink_anon_vmas
0.06 ? 31% perf-profile.children.cycles-pp.__get_user_pages
0.07 ? 28% perf-profile.children.cycles-pp.cpuidle_not_available
0.07 ? 28% perf-profile.children.cycles-pp.__lookup_slow
0.07 ? 26% perf-profile.children.cycles-pp.check_move_unevictable_folios
0.07 ? 26% perf-profile.children.cycles-pp.check_move_unevictable_pages
0.07 ? 14% perf-profile.children.cycles-pp.__percpu_counter_init
0.07 ? 26% perf-profile.children.cycles-pp.get_arg_page
0.07 ? 26% perf-profile.children.cycles-pp.get_user_pages_remote
0.08 ? 26% perf-profile.children.cycles-pp.drm_gem_shmem_put_pages_locked
0.08 ? 26% perf-profile.children.cycles-pp.drm_gem_put_pages
0.08 ? 26% perf-profile.children.cycles-pp.drm_gem_check_release_pagevec
0.08 ? 23% perf-profile.children.cycles-pp.hrtimer_run_queues
0.08 ? 45% perf-profile.children.cycles-pp.__x64_sys_mprotect
0.08 ? 45% perf-profile.children.cycles-pp.do_mprotect_pkey
0.09 ? 33% perf-profile.children.cycles-pp.lookup_fast
0.09 ? 29% perf-profile.children.cycles-pp.rcu_do_batch
0.09 ? 32% perf-profile.children.cycles-pp.can_stop_idle_tick
0.09 ? 32% perf-profile.children.cycles-pp.__vmalloc_node_range
0.09 ? 32% perf-profile.children.cycles-pp.alloc_thread_stack_node
0.09 ? 20% perf-profile.children.cycles-pp.perf_read
0.10 ? 26% perf-profile.children.cycles-pp.perf_evsel__read
0.10 ? 21% perf-profile.children.cycles-pp.menu_reflect
0.10 ? 21% perf-profile.children.cycles-pp.alloc_bprm
0.10 ? 12% perf-profile.children.cycles-pp.vma_interval_tree_insert
0.10 ? 27% perf-profile.children.cycles-pp.nohz_balancer_kick
0.10 ? 18% perf-profile.children.cycles-pp.mm_init
0.10 ? 14% perf-profile.children.cycles-pp.note_gp_changes
0.11 ? 21% perf-profile.children.cycles-pp.cpuidle_reflect
0.11 ? 9% perf-profile.children.cycles-pp.dup_task_struct
0.11 ? 52% perf-profile.children.cycles-pp.find_idlest_cpu
0.11 ? 52% perf-profile.children.cycles-pp.find_idlest_group
0.12 ? 11% perf-profile.children.cycles-pp.drm_gem_vunmap_unlocked
0.12 ? 11% perf-profile.children.cycles-pp.drm_gem_vunmap
0.12 ? 11% perf-profile.children.cycles-pp.drm_gem_shmem_vunmap
0.12 ? 38% perf-profile.children.cycles-pp.irq_work_run_list
0.12 ? 13% perf-profile.children.cycles-pp.__switch_to_asm
0.13 ? 11% perf-profile.children.cycles-pp.pipe_read
0.14 ? 8% perf-profile.children.cycles-pp.exec_mmap
0.14 ? 44% perf-profile.children.cycles-pp.tsc_verify_tsc_adjust
0.14 ? 14% perf-profile.children.cycles-pp.irqentry_exit
0.14 ? 14% perf-profile.children.cycles-pp.walk_component
0.14 ? 39% perf-profile.children.cycles-pp.pick_next_task_fair
0.15 ? 25% perf-profile.children.cycles-pp.smpboot_thread_fn
0.15 ? 51% perf-profile.children.cycles-pp.update_wall_time
0.15 ? 51% perf-profile.children.cycles-pp.timekeeping_advance
0.16 ? 47% perf-profile.children.cycles-pp.copy_strings
0.16 ? 16% perf-profile.children.cycles-pp.ct_kernel_exit
0.16 ? 40% perf-profile.children.cycles-pp.select_task_rq_fair
0.16 ? 33% perf-profile.children.cycles-pp.perf_event_task_tick
0.16 ? 4% perf-profile.children.cycles-pp.__libc_read
0.16 ? 28% perf-profile.children.cycles-pp.__x64_sys_vfork
0.16 ? 19% perf-profile.children.cycles-pp.intel_idle_irq
0.16 ? 22% perf-profile.children.cycles-pp.___perf_sw_event
0.16 ? 28% perf-profile.children.cycles-pp.update_rt_rq_load_avg
0.16 ? 39% perf-profile.children.cycles-pp.arch_cpu_idle_enter
0.16 ? 16% perf-profile.children.cycles-pp._find_next_and_bit
0.16 ? 24% perf-profile.children.cycles-pp.evsel__read_counter
0.17 ? 13% perf-profile.children.cycles-pp.irqtime_account_process_tick
0.17 ? 49% perf-profile.children.cycles-pp.shmem_read_folio_gfp
0.17 ? 33% perf-profile.children.cycles-pp.rb_erase
0.18 ? 31% perf-profile.children.cycles-pp.drm_atomic_commit
0.18 ? 31% perf-profile.children.cycles-pp.drm_atomic_helper_commit
0.18 ? 16% perf-profile.children.cycles-pp.hrtimer_forward
0.18 ? 4% perf-profile.children.cycles-pp.readn
0.18 ? 30% perf-profile.children.cycles-pp.sched_clock
0.18 ? 27% perf-profile.children.cycles-pp.drm_atomic_helper_dirtyfb
0.19 ? 28% perf-profile.children.cycles-pp.check_cpu_stall
0.19 ? 30% perf-profile.children.cycles-pp.begin_new_exec
0.19 ? 20% perf-profile.children.cycles-pp.tick_nohz_tick_stopped
0.19 ? 19% perf-profile.children.cycles-pp.__vfork
0.20 ? 34% perf-profile.children.cycles-pp.drm_gem_shmem_get_pages
0.20 ? 34% perf-profile.children.cycles-pp.drm_gem_shmem_get_pages_locked
0.20 ? 34% perf-profile.children.cycles-pp.drm_gem_get_pages
0.20 ? 34% perf-profile.children.cycles-pp.shmem_read_mapping_page_gfp
0.20 ? 18% perf-profile.children.cycles-pp.rb_next
0.20 ? 39% perf-profile.children.cycles-pp.drm_gem_vmap_unlocked
0.20 ? 39% perf-profile.children.cycles-pp.drm_gem_vmap
0.20 ? 39% perf-profile.children.cycles-pp.drm_gem_shmem_object_vmap
0.20 ? 39% perf-profile.children.cycles-pp.drm_gem_shmem_vmap_locked
0.21 ? 45% perf-profile.children.cycles-pp.run_posix_cpu_timers
0.21 ? 20% perf-profile.children.cycles-pp.tick_program_event
0.22 ?102% perf-profile.children.cycles-pp.tick_check_oneshot_broadcast_this_cpu
0.23 ? 23% perf-profile.children.cycles-pp.ttwu_do_activate
0.23 ? 25% perf-profile.children.cycles-pp.arch_cpu_idle_exit
0.24 ? 15% perf-profile.children.cycles-pp.rb_insert_color
0.24 ? 45% perf-profile.children.cycles-pp.irqentry_enter
0.26 ? 7% perf-profile.children.cycles-pp._raw_spin_unlock_irqrestore
0.27 ? 16% perf-profile.children.cycles-pp.rcu_core
0.29 ? 9% perf-profile.children.cycles-pp.error_entry
0.31 ? 15% perf-profile.children.cycles-pp.call_cpuidle
0.33 ? 22% perf-profile.children.cycles-pp.drm_fb_helper_damage_work
0.33 ? 22% perf-profile.children.cycles-pp.drm_fbdev_generic_helper_fb_dirty
0.33 ? 27% perf-profile.children.cycles-pp.sched_clock_idle_wakeup_event
0.33 ? 18% perf-profile.children.cycles-pp.ct_kernel_exit_state
0.35 ? 47% perf-profile.children.cycles-pp.ct_kernel_enter
0.35 ? 17% perf-profile.children.cycles-pp.hrtimer_update_next_event
0.37 ? 16% perf-profile.children.cycles-pp.idle_cpu
0.40 ? 30% perf-profile.children.cycles-pp.hrtimer_get_next_event
0.40 ? 15% perf-profile.children.cycles-pp.irq_work_tick
0.40 ? 20% perf-profile.children.cycles-pp.timerqueue_del
0.43 ? 10% perf-profile.children.cycles-pp.call_timer_fn
0.44 ? 7% perf-profile.children.cycles-pp.read_counters
0.44 ? 45% perf-profile.children.cycles-pp.ct_idle_exit
0.48 ? 8% perf-profile.children.cycles-pp.cmd_stat
0.48 ? 8% perf-profile.children.cycles-pp.dispatch_events
0.48 ? 8% perf-profile.children.cycles-pp.process_interval
0.50 ? 18% perf-profile.children.cycles-pp.process_one_work
0.51 ? 23% perf-profile.children.cycles-pp.__hrtimer_next_event_base
0.51 ? 10% perf-profile.children.cycles-pp._raw_spin_lock_irq
0.52 ? 3% perf-profile.children.cycles-pp.run_timer_softirq
0.52 ? 27% perf-profile.children.cycles-pp.schedule_timeout
0.53 ? 16% perf-profile.children.cycles-pp.worker_thread
0.53 ? 28% perf-profile.children.cycles-pp.timerqueue_add
0.56 ? 18% perf-profile.children.cycles-pp.schedule
0.58 ? 3% perf-profile.children.cycles-pp.__run_timers
0.58 ? 18% perf-profile.children.cycles-pp.get_cpu_device
0.59 ? 14% perf-profile.children.cycles-pp.tick_nohz_irq_exit
0.60 ? 16% perf-profile.children.cycles-pp.update_rq_clock
0.62 ? 61% perf-profile.children.cycles-pp.calc_global_load_tick
0.66 ? 21% perf-profile.children.cycles-pp.enqueue_hrtimer
0.66 ? 17% perf-profile.children.cycles-pp.local_clock
0.68 ? 7% perf-profile.children.cycles-pp.hrtimer_next_event_without
0.70 ? 24% perf-profile.children.cycles-pp.get_next_timer_interrupt
0.74 ? 15% perf-profile.children.cycles-pp._raw_spin_trylock
0.75 ? 29% perf-profile.children.cycles-pp.update_irq_load_avg
0.80 ? 24% perf-profile.children.cycles-pp.__nfsd_open
0.80 ? 24% perf-profile.children.cycles-pp.dentry_open
0.80 ? 24% perf-profile.children.cycles-pp.__break_lease
0.80 ? 24% perf-profile.children.cycles-pp.nfsd
0.80 ? 24% perf-profile.children.cycles-pp.svc_process
0.80 ? 24% perf-profile.children.cycles-pp.svc_process_common
0.80 ? 24% perf-profile.children.cycles-pp.nfsd_dispatch
0.80 ? 24% perf-profile.children.cycles-pp.nfsd4_proc_compound
0.80 ? 24% perf-profile.children.cycles-pp.nfsd4_commit
0.80 ? 24% perf-profile.children.cycles-pp.nfsd_file_do_acquire
0.81 ? 13% perf-profile.children.cycles-pp.update_blocked_averages
0.82 ? 25% perf-profile.children.cycles-pp.do_dentry_open
0.84 ? 12% perf-profile.children.cycles-pp.run_rebalance_domains
0.89 ? 15% perf-profile.children.cycles-pp.cpuidle_governor_latency_req
0.98 ? 8% perf-profile.children.cycles-pp.update_sg_lb_stats
0.98 ? 24% perf-profile.children.cycles-pp.update_rq_clock_task
1.08 ? 9% perf-profile.children.cycles-pp.irqtime_account_irq
1.16 ? 17% perf-profile.children.cycles-pp.tick_nohz_next_event
1.17 ? 14% perf-profile.children.cycles-pp._raw_spin_lock_irqsave
1.25 ? 2% perf-profile.children.cycles-pp.update_sd_lb_stats
1.31 ? 2% perf-profile.children.cycles-pp.find_busiest_group
1.35 ? 28% perf-profile.children.cycles-pp.tick_sched_do_timer
1.46 ? 48% perf-profile.children.cycles-pp.tick_irq_enter
1.46 ? 3% perf-profile.children.cycles-pp.sched_clock_cpu
1.51 ? 12% perf-profile.children.cycles-pp.__intel_pmu_enable_all
1.53 ? 42% perf-profile.children.cycles-pp.irq_enter_rcu
1.62 ? 12% perf-profile.children.cycles-pp.x86_64_start_kernel
1.62 ? 12% perf-profile.children.cycles-pp.x86_64_start_reservations
1.62 ? 12% perf-profile.children.cycles-pp.start_kernel
1.62 ? 12% perf-profile.children.cycles-pp.arch_call_rest_init
1.62 ? 12% perf-profile.children.cycles-pp.rest_init
1.70 ? 7% perf-profile.children.cycles-pp.native_sched_clock
1.70 ? 3% perf-profile.children.cycles-pp.load_balance
1.71 ? 5% perf-profile.children.cycles-pp.lapic_next_deadline
1.72 ? 8% perf-profile.children.cycles-pp.kthread
1.76 ? 7% perf-profile.children.cycles-pp.ret_from_fork
1.95 ? 16% perf-profile.children.cycles-pp.read_tsc
1.98 ? 9% perf-profile.children.cycles-pp.perf_rotate_context
2.04 ? 11% perf-profile.children.cycles-pp.tick_nohz_get_sleep_length
2.30 ? 5% perf-profile.children.cycles-pp.clockevents_program_event
2.60 ? 6% perf-profile.children.cycles-pp.rebalance_domains
2.99 ? 7% perf-profile.children.cycles-pp.perf_mux_hrtimer_handler
3.18 ? 7% perf-profile.children.cycles-pp.arch_scale_freq_tick
3.92 ? 31% perf-profile.children.cycles-pp.ktime_get
4.53 ? 6% perf-profile.children.cycles-pp.menu_select
4.71 ? 6% perf-profile.children.cycles-pp.__do_softirq
5.86 ? 11% perf-profile.children.cycles-pp.scheduler_tick
5.64 ? 4% perf-profile.children.cycles-pp.__irq_exit_rcu
8.15 ? 9% perf-profile.children.cycles-pp.update_process_times
8.35 ? 9% perf-profile.children.cycles-pp.tick_sched_handle
11.21 ? 6% perf-profile.children.cycles-pp.tick_sched_timer
16.30 ? 3% perf-profile.children.cycles-pp.__hrtimer_run_queues
22.55 ? 4% perf-profile.children.cycles-pp.hrtimer_interrupt
22.66 ? 4% perf-profile.children.cycles-pp.__sysvec_apic_timer_interrupt
31.28 ? 4% perf-profile.children.cycles-pp.sysvec_apic_timer_interrupt
35.97 ? 2% perf-profile.children.cycles-pp.asm_sysvec_apic_timer_interrupt
42.16 perf-profile.children.cycles-pp.intel_idle
84.34 perf-profile.children.cycles-pp.cpuidle_enter_state
84.78 perf-profile.children.cycles-pp.cpuidle_enter
90.38 perf-profile.children.cycles-pp.start_secondary
92.00 perf-profile.children.cycles-pp.secondary_startup_64_no_verify
92.00 perf-profile.children.cycles-pp.cpu_startup_entry
92.00 perf-profile.children.cycles-pp.do_idle
90.65 perf-profile.children.cycles-pp.cpuidle_idle_call
0.06 ? 20% perf-profile.self.cycles-pp.shmem_get_folio_gfp
0.07 ? 19% perf-profile.self.cycles-pp.tick_irq_enter
0.07 ? 26% perf-profile.self.cycles-pp.check_move_unevictable_folios
0.07 ? 33% perf-profile.self.cycles-pp.perf_event_task_tick
0.08 ? 19% perf-profile.self.cycles-pp.hrtimer_run_queues
0.08 ? 14% perf-profile.self.cycles-pp.irqentry_exit
0.08 ? 21% perf-profile.self.cycles-pp.hrtimer_get_next_event
0.08 ? 26% perf-profile.self.cycles-pp.can_stop_idle_tick
0.09 ? 29% perf-profile.self.cycles-pp.irqentry_enter
0.09 ? 43% perf-profile.self.cycles-pp.update_blocked_averages
0.10 ? 12% perf-profile.self.cycles-pp.vma_interval_tree_insert
0.10 ? 34% perf-profile.self.cycles-pp.irq_work_run_list
0.10 ? 43% perf-profile.self.cycles-pp.ct_kernel_exit
0.10 ? 41% perf-profile.self.cycles-pp.__sysvec_apic_timer_interrupt
0.11 ? 13% perf-profile.self.cycles-pp.tick_sched_timer
0.11 ? 42% perf-profile.self.cycles-pp.filemap_map_pages
0.12 ? 26% perf-profile.self.cycles-pp.rb_erase
0.12 ? 56% perf-profile.self.cycles-pp.tsc_verify_tsc_adjust
0.12 ? 13% perf-profile.self.cycles-pp.__switch_to_asm
0.13 ? 21% perf-profile.self.cycles-pp.hrtimer_update_next_event
0.13 ? 36% perf-profile.self.cycles-pp.hrtimer_forward
0.13 ? 25% perf-profile.self.cycles-pp.rb_next
0.13 ? 42% perf-profile.self.cycles-pp.update_rq_clock
0.14 ? 34% perf-profile.self.cycles-pp.sysvec_apic_timer_interrupt
0.14 ? 23% perf-profile.self.cycles-pp.enqueue_hrtimer
0.14 ? 32% perf-profile.self.cycles-pp.tick_nohz_get_sleep_length
0.14 ? 15% perf-profile.self.cycles-pp.rcu_sched_clock_irq
0.15 ? 40% perf-profile.self.cycles-pp.clockevents_program_event
0.15 ? 23% perf-profile.self.cycles-pp.tick_nohz_tick_stopped
0.15 ? 21% perf-profile.self.cycles-pp.___perf_sw_event
0.16 ? 14% perf-profile.self.cycles-pp.irqtime_account_process_tick
0.16 ? 19% perf-profile.self.cycles-pp._find_next_and_bit
0.16 ? 23% perf-profile.self.cycles-pp._raw_spin_unlock_irqrestore
0.16 ? 25% perf-profile.self.cycles-pp.update_rt_rq_load_avg
0.16 ? 19% perf-profile.self.cycles-pp.intel_idle_irq
0.16 ? 17% perf-profile.self.cycles-pp.hrtimer_next_event_without
0.18 ? 45% perf-profile.self.cycles-pp.timerqueue_del
0.18 ? 27% perf-profile.self.cycles-pp.check_cpu_stall
0.18 ? 36% perf-profile.self.cycles-pp.update_sd_lb_stats
0.19 ? 44% perf-profile.self.cycles-pp.run_posix_cpu_timers
0.19 ? 18% perf-profile.self.cycles-pp.perf_mux_hrtimer_handler
0.20 ? 47% perf-profile.self.cycles-pp.__do_softirq
0.20 ? 23% perf-profile.self.cycles-pp.tick_program_event
0.20 ? 26% perf-profile.self.cycles-pp.rb_insert_color
0.20 ? 8% perf-profile.self.cycles-pp.sched_clock_cpu
0.21 ? 41% perf-profile.self.cycles-pp.get_next_timer_interrupt
0.21 ? 60% perf-profile.self.cycles-pp.ct_kernel_enter
0.22 ?102% perf-profile.self.cycles-pp.tick_check_oneshot_broadcast_this_cpu
0.25 ? 26% perf-profile.self.cycles-pp.update_rq_clock_task
0.25 ? 26% perf-profile.self.cycles-pp.__irq_exit_rcu
0.26 ? 38% perf-profile.self.cycles-pp.rebalance_domains
0.26 ? 33% perf-profile.self.cycles-pp.cpuidle_governor_latency_req
0.26 ? 25% perf-profile.self.cycles-pp.perf_rotate_context
0.28 ? 20% perf-profile.self.cycles-pp.tick_nohz_next_event
0.29 ? 9% perf-profile.self.cycles-pp.error_entry
0.29 ? 38% perf-profile.self.cycles-pp.hrtimer_interrupt
0.30 ? 18% perf-profile.self.cycles-pp.call_cpuidle
0.30 ? 16% perf-profile.self.cycles-pp.load_balance
0.31 ? 22% perf-profile.self.cycles-pp.ct_kernel_exit_state
0.32 ? 20% perf-profile.self.cycles-pp.irqtime_account_irq
0.32 ? 31% perf-profile.self.cycles-pp.timerqueue_add
0.32 ? 28% perf-profile.self.cycles-pp.sched_clock_idle_wakeup_event
0.35 ? 20% perf-profile.self.cycles-pp.scheduler_tick
0.36 ? 16% perf-profile.self.cycles-pp.idle_cpu
0.38 ? 17% perf-profile.self.cycles-pp.irq_work_tick
0.39 ? 20% perf-profile.self.cycles-pp.cpuidle_enter
0.40 ? 18% perf-profile.self.cycles-pp.__hrtimer_next_event_base
0.45 ? 36% perf-profile.self.cycles-pp.do_idle
0.50 ? 7% perf-profile.self.cycles-pp._raw_spin_lock_irq
0.51 ? 18% perf-profile.self.cycles-pp.__hrtimer_run_queues
0.53 ? 17% perf-profile.self.cycles-pp.get_cpu_device
0.54 ? 8% perf-profile.self.cycles-pp.update_process_times
0.56 ? 27% perf-profile.self.cycles-pp.asm_sysvec_apic_timer_interrupt
0.62 ? 61% perf-profile.self.cycles-pp.calc_global_load_tick
0.69 ? 16% perf-profile.self.cycles-pp.cpuidle_idle_call
0.73 ? 14% perf-profile.self.cycles-pp._raw_spin_trylock
0.73 ? 29% perf-profile.self.cycles-pp.update_irq_load_avg
0.74 ? 9% perf-profile.self.cycles-pp.update_sg_lb_stats
1.10 ? 14% perf-profile.self.cycles-pp._raw_spin_lock_irqsave
1.18 ? 31% perf-profile.self.cycles-pp.tick_sched_do_timer
1.45 ? 9% perf-profile.self.cycles-pp.menu_select
1.51 ? 12% perf-profile.self.cycles-pp.__intel_pmu_enable_all
1.63 ? 9% perf-profile.self.cycles-pp.native_sched_clock
1.70 ? 4% perf-profile.self.cycles-pp.lapic_next_deadline
1.93 ? 16% perf-profile.self.cycles-pp.read_tsc
2.30 ? 52% perf-profile.self.cycles-pp.ktime_get
3.18 ? 7% perf-profile.self.cycles-pp.arch_scale_freq_tick
5.84 ? 9% perf-profile.self.cycles-pp.cpuidle_enter_state
42.16 perf-profile.self.cycles-pp.intel_idle
*************************************************************************
threads 2 sockets Intel(R) Xeon(R) Gold 6346 CPU @ 3.10GHz (Ice Lake) with 256G memory
===============================================================
debug-setup/disk/filesize/fs2/fs/iterations/kconfig/nr_directories/nr_files_per_directory/nr_threads/rootfs/sync_method/tbox_group/test_size/testcase:
nitor/1SSD/16MB/nfsv4/btrfs/1x/x86_64-rhel-8.3/16d/256fpd/32t/debian-11.1-x86_64-20220510.cgz/NoSync/lkp-icl-2sp7/20G/fsmark
Clean up nfsctl_transaction_write()")
trace nfsctl operations")
39d432fc76301cf0a0c45402211
---------------------------
%stddev
\
+7979.7% 6.05e+08 ? 47% fsmark.app_overhead
0.00 fsmark.files_per_sec
3564 ? 5% fsmark.time.elapsed_time
3564 ? 5% fsmark.time.elapsed_time.max
1.00 fsmark.time.percent_of_cpu_this_job_got
48.94 ? 4% fsmark.time.system_time
+2.9% 1007574 ? 2% fsmark.time.voluntary_context_switches
estimated based on internal Intel analysis and are provided
purposes only. Any difference in system hardware or software
may affect actual performance.
om/intel/lkp-tests/wiki">https://github.com/intel/lkp-tests/wiki

2023-08-24 18:53:49

by Jeff Layton

[permalink] [raw]

Subject: Re: [linus:master] [NFSD] 39d432fc76: fsmark.files_per_sec -100.0% regression

On Thu, 2023-08-24 at 10:12 -0400, Benjamin Coddington wrote:
> On 24 Aug 2023, at 9:23, Chuck Lever wrote:
>
> > On Thu, Aug 24, 2023 at 01:59:06PM +0800, kernel test robot wrote:
> > >
> > >
> > > hi, Chuck Lever,
> > >
> > > Fengwei (CCed) helped us review this astonishing finding by fsmark tests,
> > > and doubt below part:
> > > - nfsd4_end_grace(nn);
> > > + trace_nfsd_end_grace(netns(file));
> > >
> > > and confirmed if adding back:
> > > nfsd4_end_grace(nn);
> > >
> > > the regression is gone and files_per_sec restore to 61.93.
> >
> > As always, thanks for the report. However, this result is not
> > plausible. "end_grace" happens only once after a server reboot.
> >
> > Can you confirm that the NFS server kernel is not crashing
> > during the test?
>
> Does the removal of nfsd4_end_grace() here disable the ability of nfsdcltrack to
> terminate the grace period early on a first start of the server?
>
>

Yes. That should be the only effect (which is why we didn't notice it).
--
Jeff Layton <[email protected]>