lists.openwall.net   lists  /  announce  owl-users  owl-dev  john-users  john-dev  passwdqc-users  yescrypt  popa3d-users  /  oss-security  kernel-hardening  musl  sabotage  tlsify  passwords  /  crypt-dev  xvendor  /  Bugtraq  Full-Disclosure  linux-kernel  linux-netdev  linux-ext4  linux-hardening  linux-cve-announce  PHC 
Open Source and information security mailing list archives
 
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [day] [month] [year] [list]
Message-ID: <202502061435.62604a8d-lkp@intel.com>
Date: Thu, 6 Feb 2025 15:00:58 +0800
From: kernel test robot <oliver.sang@...el.com>
To: Jeff Layton <jlayton@...nel.org>
CC: <oe-lkp@...ts.linux.dev>, <lkp@...el.com>, <linux-kernel@...r.kernel.org>,
	Chuck Lever <chuck.lever@...cle.com>, <linux-nfs@...r.kernel.org>,
	<oliver.sang@...el.com>
Subject: [linus:master] [nfsd]  7e13f4f8d2:  postmark.transactions 10.4%
 regression



Hello,

kernel test robot noticed a 10.4% regression of postmark.transactions on:


commit: 7e13f4f8d27dc02fb88666f603c53ca749d56f92 ("nfsd: handle delegated timestamps in SETATTR")
https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master

[test failed on linus/master      bdd4f86c97e60b748027bdf6f6a3729c8a12da15]
[test failed on linux-next/master df4b2bbff898227db0c14264ac7edd634e79f755]

testcase: postmark
config: x86_64-rhel-9.4
compiler: gcc-12
test machine: 4 threads 1 sockets Intel(R) Core(TM) i3-3220 CPU @ 3.30GHz (Ivy Bridge) with 8G memory
parameters:

	disk: 1HDD
	fs: xfs
	fs1: nfsv4
	number: 1000n
	trans: 30000s
	subdirs: 100d
	cpufreq_governor: performance




If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <oliver.sang@...el.com>
| Closes: https://lore.kernel.org/oe-lkp/202502061435.62604a8d-lkp@intel.com


Details are as below:
-------------------------------------------------------------------------------------------------->


The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20250206/202502061435.62604a8d-lkp@intel.com

=========================================================================================
compiler/cpufreq_governor/disk/fs1/fs/kconfig/number/rootfs/subdirs/tbox_group/testcase/trans:
  gcc-12/performance/1HDD/nfsv4/xfs/x86_64-rhel-9.4/1000n/debian-12-x86_64-20240206.cgz/100d/lkp-ivb-d04/postmark/30000s

commit: 
  6ae30d6eb2 ("nfsd: add support for delegated timestamps")
  7e13f4f8d2 ("nfsd: handle delegated timestamps in SETATTR")

6ae30d6eb26bce02 7e13f4f8d27dc02fb88666f603c 
---------------- --------------------------- 
         %stddev     %change         %stddev
             \          |                \  
     16.93            -1.5       15.46        mpstat.cpu.all.iowait%
      3253           +13.8%       3702 ±  4%  uptime.idle
      0.70           -11.7%       0.62 ±  2%  vmstat.procs.b
      4265            -6.1%       4004 ±  3%  vmstat.system.cs
     80.56            +2.0%      82.16        iostat.cpu.idle
     16.90            -8.7%      15.43        iostat.cpu.iowait
      1.60            -4.1%       1.53 ±  2%  iostat.cpu.system
      8974            +5.0%       9424        proc-vmstat.nr_shmem
   1446157            +6.3%    1537480 ±  2%  proc-vmstat.numa_hit
   1446157            +6.3%    1537478 ±  2%  proc-vmstat.numa_local
   1736096            +5.6%    1834173 ±  2%  proc-vmstat.pgalloc_normal
   1429310           +11.5%    1594111 ±  3%  proc-vmstat.pgfault
   1834412            +5.2%    1929590 ±  2%  proc-vmstat.pgfree
    659217            +5.2%     693777        proc-vmstat.pgpgout
     74887           +12.5%      84235 ±  4%  proc-vmstat.pgreuse
      0.74 ± 10%     -23.7%       0.56 ± 17%  sched_debug.cfs_rq:/.h_nr_running.avg
    360.38 ±  5%      +9.0%     392.67 ±  4%  sched_debug.cfs_rq:/.load_avg.stddev
      0.48 ± 17%     -26.1%       0.36 ± 13%  sched_debug.cfs_rq:/.nr_running.avg
    417.13 ±  5%     -14.4%     356.95 ±  4%  sched_debug.cfs_rq:/.runnable_avg.avg
    382.46 ±  6%     -15.4%     323.57 ± 12%  sched_debug.cfs_rq:/.runnable_avg.stddev
    499.84 ±  7%     +39.8%     698.95 ± 22%  sched_debug.cpu.clock_task.stddev
      0.73 ± 12%     -23.4%       0.56 ± 17%  sched_debug.cpu.nr_running.avg
      2791 ±  2%      -8.0%       2567 ±  4%  sched_debug.cpu.nr_uninterruptible.max
      0.02 ±  6%     +13.0%       0.02 ±  5%  perf-sched.sch_delay.avg.ms.schedule_timeout.__wait_for_common.__synchronize_srcu.part.0
      0.03 ± 10%     +36.0%       0.04 ±  6%  perf-sched.sch_delay.avg.ms.schedule_timeout.kcompactd.kthread.ret_from_fork
      0.01 ± 39%     -90.9%       0.00 ±173%  perf-sched.sch_delay.avg.ms.syscall_exit_to_user_mode.do_syscall_64.entry_SYSCALL_64_after_hwframe.[unknown]
      0.05           -18.8%       0.04 ± 12%  perf-sched.sch_delay.max.ms.rpc_wait_bit_killable.__wait_on_bit.out_of_line_wait_on_bit.nfs4_run_open_task
      0.01 ± 61%     -93.6%       0.00 ±173%  perf-sched.sch_delay.max.ms.syscall_exit_to_user_mode.do_syscall_64.entry_SYSCALL_64_after_hwframe.[unknown]
    619.85 ±  4%     -10.2%     556.79 ± 10%  perf-sched.wait_and_delay.avg.ms.schedule_hrtimeout_range.do_poll.constprop.0.do_sys_poll
      1642 ± 23%     +51.7%       2490 ± 19%  perf-sched.wait_and_delay.max.ms.smpboot_thread_fn.kthread.ret_from_fork.ret_from_fork_asm
    619.83 ±  4%     -10.2%     556.76 ± 10%  perf-sched.wait_time.avg.ms.schedule_hrtimeout_range.do_poll.constprop.0.do_sys_poll
      0.20 ±  4%     +10.4%       0.22 ±  6%  perf-sched.wait_time.max.ms.rpc_wait_bit_killable.__wait_on_bit.out_of_line_wait_on_bit.nfs4_run_open_task
      1642 ± 23%     +51.7%       2490 ± 19%  perf-sched.wait_time.max.ms.smpboot_thread_fn.kthread.ret_from_fork.ret_from_fork_asm
     16.14           -10.4%      14.46        postmark.creation_mixed_trans
    256446           -10.8%     228826 ±  3%  postmark.data_read
    271043           -10.8%     241851 ±  3%  postmark.data_written
     16.30           -10.4%      14.61        postmark.deletion_mixed_trans
     16.03           -10.4%      14.36        postmark.files_appended
     16.34           -10.8%      14.58 ±  3%  postmark.files_created
     16.34           -10.8%      14.58 ±  3%  postmark.files_deleted
     16.28           -10.4%      14.58        postmark.files_read
    977.64           +12.2%       1096 ±  3%  postmark.time.elapsed_time
    977.64           +12.2%       1096 ±  3%  postmark.time.elapsed_time.max
     32.45           -10.4%      29.07        postmark.transactions
      9596 ±  3%     -51.9%       4617 ±  4%  nfsstat.Client.nfs.v4.delegreturn
     10.45           -49.4%       5.28        nfsstat.Client.nfs.v4.delegreturn.percent
      0.01 ±  3%     -13.8%       0.01 ±  3%  nfsstat.Client.nfs.v4.exchange_id.percent
      0.01 ±  3%     -13.8%       0.01 ±  3%  nfsstat.Client.nfs.v4.getattr.percent
      0.01 ±  3%     -13.8%       0.01 ±  3%  nfsstat.Client.nfs.v4.pathconf.percent
     76622 ±  3%     -10.5%      68577 ±  4%  nfsstat.Client.rpc.authrefrsh
     76621 ±  3%     -10.5%      68577 ±  4%  nfsstat.Client.rpc.calls
     76621 ±  3%     -10.5%      68576 ±  4%  nfsstat.Server.nfs.v4.compound
     76615 ±  3%     -10.5%      68570 ±  4%  nfsstat.Server.nfs.v4.operations.putfh
     76618 ±  3%     -10.5%      68573 ±  4%  nfsstat.Server.nfs.v4.operations.sequence
     76622 ±  3%     -10.5%      68577 ±  4%  nfsstat.Server.packet.packets
     76622 ±  3%     -10.5%      68577 ±  4%  nfsstat.Server.packet.tcp
     76622 ±  3%     -10.5%      68577 ±  4%  nfsstat.Server.reply.cache.nocache
     76622 ±  3%     -10.5%      68577 ±  4%  nfsstat.Server.rpc.calls
      7.92            +4.5%       8.28        perf-stat.i.MPKI
     11.06            +0.2       11.25        perf-stat.i.branch-miss-rate%
      9.69            +0.2        9.92        perf-stat.i.cache-miss-rate%
   7752348            -2.7%    7540156 ±  2%  perf-stat.i.cache-references
      4273            -6.2%       4010 ±  3%  perf-stat.i.context-switches
      3.20            +1.5%       3.25        perf-stat.i.cpi
    140.79            -6.5%     131.59 ±  3%  perf-stat.i.cpu-migrations
    454.52            -2.5%     443.37        perf-stat.i.cycles-between-cache-misses
      0.34            -1.6%       0.33        perf-stat.i.ipc
      0.78           -16.6%       0.65 ±  5%  perf-stat.i.metric.K/sec
      8.13            +0.1        8.26        perf-stat.overall.branch-miss-rate%
      9.46            +0.2        9.65        perf-stat.overall.cache-miss-rate%
    538.98            -3.7%     519.07        perf-stat.overall.cycles-between-cache-misses
   7744340            -2.7%    7533176 ±  2%  perf-stat.ps.cache-references
      4268            -6.2%       4006 ±  3%  perf-stat.ps.context-switches
    140.64            -6.5%     131.47 ±  3%  perf-stat.ps.cpu-migrations
      7.02 ±  6%      -1.8        5.26 ± 23%  perf-profile.calltrace.cycles-pp.nfsd.kthread.ret_from_fork.ret_from_fork_asm
      6.97 ±  5%      -1.7        5.24 ± 23%  perf-profile.calltrace.cycles-pp.svc_recv.nfsd.kthread.ret_from_fork.ret_from_fork_asm
      6.21 ±  7%      -1.7        4.49 ± 22%  perf-profile.calltrace.cycles-pp.svc_handle_xprt.svc_recv.nfsd.kthread.ret_from_fork
      4.18 ±  6%      -1.2        2.97 ± 25%  perf-profile.calltrace.cycles-pp.svc_process.svc_handle_xprt.svc_recv.nfsd.kthread
      4.17 ±  5%      -1.2        2.97 ± 25%  perf-profile.calltrace.cycles-pp.svc_process_common.svc_process.svc_handle_xprt.svc_recv.nfsd
      3.64 ±  5%      -1.0        2.66 ± 26%  perf-profile.calltrace.cycles-pp.nfsd4_proc_compound.nfsd_dispatch.svc_process_common.svc_process.svc_handle_xprt
      1.06 ± 24%      -0.5        0.53 ± 61%  perf-profile.calltrace.cycles-pp.xfs_file_fsync.xfs_file_buffered_write.do_iter_readv_writev.vfs_iter_write.nfsd_vfs_write
     46.56 ±  2%      +2.0       48.60 ±  2%  perf-profile.calltrace.cycles-pp.cpuidle_enter.cpuidle_idle_call.do_idle.cpu_startup_entry.start_secondary
     53.42 ±  2%      +2.2       55.59 ±  2%  perf-profile.calltrace.cycles-pp.cpu_startup_entry.start_secondary.common_startup_64
     53.42 ±  2%      +2.2       55.60 ±  2%  perf-profile.calltrace.cycles-pp.start_secondary.common_startup_64
     53.34 ±  2%      +2.2       55.53 ±  2%  perf-profile.calltrace.cycles-pp.do_idle.cpu_startup_entry.start_secondary.common_startup_64
     49.91 ±  2%      +2.3       52.24 ±  2%  perf-profile.calltrace.cycles-pp.cpuidle_idle_call.do_idle.cpu_startup_entry.start_secondary.common_startup_64
      7.02 ±  6%      -1.8        5.26 ± 23%  perf-profile.children.cycles-pp.nfsd
      6.97 ±  5%      -1.7        5.24 ± 23%  perf-profile.children.cycles-pp.svc_recv
      6.21 ±  7%      -1.7        4.49 ± 22%  perf-profile.children.cycles-pp.svc_handle_xprt
      4.18 ±  6%      -1.2        2.97 ± 25%  perf-profile.children.cycles-pp.svc_process
      4.17 ±  5%      -1.2        2.97 ± 25%  perf-profile.children.cycles-pp.svc_process_common
      3.64 ±  5%      -1.0        2.68 ± 25%  perf-profile.children.cycles-pp.nfsd4_proc_compound
      1.49 ± 15%      -0.6        0.88 ± 20%  perf-profile.children.cycles-pp.sched_balance_rq
      0.96 ±  7%      -0.4        0.52 ± 28%  perf-profile.children.cycles-pp.sched_balance_find_src_group
      1.88 ± 14%      -0.4        1.45 ± 12%  perf-profile.children.cycles-pp.__pick_next_task
      1.06 ± 24%      -0.4        0.63 ± 28%  perf-profile.children.cycles-pp.xfs_file_fsync
      0.76 ± 32%      -0.4        0.36 ± 21%  perf-profile.children.cycles-pp.sched_balance_newidle
      0.83 ± 14%      -0.4        0.45 ± 32%  perf-profile.children.cycles-pp.update_sd_lb_stats
      0.78 ± 24%      -0.3        0.50 ± 35%  perf-profile.children.cycles-pp.file_write_and_wait_range
      0.97 ±  6%      -0.3        0.70 ± 16%  perf-profile.children.cycles-pp.update_load_avg
      0.65 ± 23%      -0.2        0.40 ± 16%  perf-profile.children.cycles-pp.nfsd4_open
      0.81 ± 15%      -0.2        0.56 ± 33%  perf-profile.children.cycles-pp.__filemap_fdatawrite_range
      0.81 ± 15%      -0.2        0.56 ± 33%  perf-profile.children.cycles-pp.filemap_fdatawrite_wbc
      0.50 ± 30%      -0.2        0.27 ± 45%  perf-profile.children.cycles-pp.update_sg_lb_stats
      0.78 ± 15%      -0.2        0.58 ± 31%  perf-profile.children.cycles-pp.do_writepages
      0.48 ± 14%      -0.2        0.29 ± 28%  perf-profile.children.cycles-pp.vfs_unlink
      0.34 ±  9%      -0.2        0.16 ± 44%  perf-profile.children.cycles-pp.nfs_file_release
      0.50 ± 14%      -0.2        0.34 ± 26%  perf-profile.children.cycles-pp.nfsd4_remove
      0.50 ± 14%      -0.2        0.34 ± 26%  perf-profile.children.cycles-pp.nfsd_unlink
      0.52 ±  9%      -0.2        0.36 ± 21%  perf-profile.children.cycles-pp.svc_tcp_recvfrom
      0.30 ± 18%      -0.2        0.15 ± 40%  perf-profile.children.cycles-pp.__put_nfs_open_context
      0.21 ± 19%      -0.2        0.06 ± 77%  perf-profile.children.cycles-pp.xfs_remove
      0.21 ± 19%      -0.2        0.06 ± 77%  perf-profile.children.cycles-pp.xfs_vn_unlink
      0.43 ± 26%      -0.1        0.29 ± 25%  perf-profile.children.cycles-pp.__common_interrupt
      0.18 ± 45%      -0.1        0.04 ±110%  perf-profile.children.cycles-pp.rpc_exit_task
      0.17 ± 38%      -0.1        0.03 ±105%  perf-profile.children.cycles-pp.__filemap_fdatawait_range
      0.28 ± 22%      -0.1        0.14 ± 39%  perf-profile.children.cycles-pp.nfs4_do_close
      0.27 ± 11%      -0.1        0.14 ± 58%  perf-profile.children.cycles-pp.xfs_generic_create
      0.17 ± 53%      -0.1        0.05 ±122%  perf-profile.children.cycles-pp.vms_complete_munmap_vmas
      0.21 ± 39%      -0.1        0.09 ± 64%  perf-profile.children.cycles-pp.native_queued_spin_lock_slowpath
      0.30 ± 10%      -0.1        0.18 ± 12%  perf-profile.children.cycles-pp.svc_tcp_read_marker
      0.32 ± 11%      -0.1        0.21 ± 22%  perf-profile.children.cycles-pp.svc_tcp_sock_recv_cmsg
      0.27 ± 11%      -0.1        0.15 ± 61%  perf-profile.children.cycles-pp.dentry_create
      0.21 ± 28%      -0.1        0.10 ± 74%  perf-profile.children.cycles-pp.nfsd4_encode_operation
      0.27 ± 11%      -0.1        0.15 ± 61%  perf-profile.children.cycles-pp.vfs_create
      0.18 ± 24%      -0.1        0.06 ± 59%  perf-profile.children.cycles-pp.autoremove_wake_function
      0.30 ± 11%      -0.1        0.20 ± 23%  perf-profile.children.cycles-pp.task_contending
      0.17 ± 23%      -0.1        0.06 ± 59%  perf-profile.children.cycles-pp.wakeup_preempt
      0.14 ± 31%      -0.1        0.04 ±110%  perf-profile.children.cycles-pp.down_write
      0.19 ± 21%      -0.1        0.09 ± 63%  perf-profile.children.cycles-pp.call_decode
      0.14 ± 14%      -0.1        0.06 ±100%  perf-profile.children.cycles-pp.tick_program_event
      0.15 ± 22%      -0.1        0.08 ± 58%  perf-profile.children.cycles-pp.dev_hard_start_xmit
      0.02 ±173%      +0.1        0.09 ± 11%  perf-profile.children.cycles-pp.complete
      0.00            +0.1        0.08 ± 38%  perf-profile.children.cycles-pp.timekeeping_max_deferment
      0.11 ± 15%      +0.1        0.20 ± 22%  perf-profile.children.cycles-pp.rpc_wake_up_queued_task
      0.02 ±173%      +0.1        0.13 ± 56%  perf-profile.children.cycles-pp.tick_check_oneshot_broadcast_this_cpu
      0.02 ±173%      +0.1        0.14 ± 39%  perf-profile.children.cycles-pp.swake_up_one
      0.03 ±173%      +0.1        0.16 ± 30%  perf-profile.children.cycles-pp.tmigr_quick_check
      0.13 ± 89%      +0.2        0.28 ± 30%  perf-profile.children.cycles-pp.x86_pmu_disable
      0.21 ± 14%      +0.2        0.36 ± 24%  perf-profile.children.cycles-pp.__mmap_prepare
      0.04 ±100%      +0.2        0.20 ± 34%  perf-profile.children.cycles-pp.folio_alloc_mpol_noprof
      0.05 ±103%      +0.2        0.21 ± 29%  perf-profile.children.cycles-pp.vma_alloc_folio_noprof
      0.13 ± 25%      +0.2        0.30 ± 26%  perf-profile.children.cycles-pp.vms_gather_munmap_vmas
     53.42 ±  2%      +2.2       55.60 ±  2%  perf-profile.children.cycles-pp.start_secondary
      0.21 ± 39%      -0.1        0.09 ± 64%  perf-profile.self.cycles-pp.native_queued_spin_lock_slowpath
      0.12 ± 23%      -0.1        0.04 ± 63%  perf-profile.self.cycles-pp.local_clock_noinstr
      0.21 ± 15%      -0.1        0.14 ± 26%  perf-profile.self.cycles-pp.__switch_to_asm
      0.00            +0.1        0.08 ± 23%  perf-profile.self.cycles-pp.nfsd_setuser
      0.00            +0.1        0.08 ± 23%  perf-profile.self.cycles-pp.ttwu_queue_wakelist
      0.08 ± 61%      +0.1        0.16 ± 12%  perf-profile.self.cycles-pp.cpuidle_enter
      0.02 ±173%      +0.1        0.11 ± 22%  perf-profile.self.cycles-pp.tmigr_quick_check
      0.00            +0.1        0.10 ± 49%  perf-profile.self.cycles-pp.hrtimer_update_next_event
      0.02 ±173%      +0.1        0.13 ± 56%  perf-profile.self.cycles-pp.tick_check_oneshot_broadcast_this_cpu
      0.07 ± 62%      +0.1        0.18 ± 39%  perf-profile.self.cycles-pp.ktime_get_update_offsets_now
      0.15 ± 39%      +0.1        0.28 ± 22%  perf-profile.self.cycles-pp.sched_tick




Disclaimer:
Results have been estimated based on internal Intel analysis and are provided
for informational purposes only. Any difference in system hardware or software
design or configuration may affect actual performance.


-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki


Powered by blists - more mailing lists

Powered by Openwall GNU/*/Linux Powered by OpenVZ