On Wed, Aug 10, 2016 at 11:24:16AM -0700, Linus Torvalds wrote: > On Tue, Aug 9, 2016 at 7:33 AM, kernel test robot wrote: > > > > FYI, we noticed a -13.6% regression of aim7.jobs-per-min due to commit: > > 68a9f5e7007c ("xfs: implement iomap based buffered write path") > > > > in testcase: aim7 > > on test machine: 48 threads Ivytown Ivy Bridge-EP with 64G memory > > with following parameters: > > > > disk: 1BRD_48G > > fs: xfs > > test: disk_wrt > > load: 3000 > > cpufreq_governor: performance > > Christop, Dave, was this expected? No. I would have expected the performance to go the other way - there is less overhead in the write() path now than there was previously, and all my numbers go the other way (5-10% improvements) in throughput. > From looking at the numbers, it looks like much more IO going on (and > this less CPU load).. I read the numbers the other way, but to me the numbers do not indicate anything about IO load. > > 37.23 ± 0% +15.6% 43.04 ± 0% aim7.time.elapsed_time > > 37.23 ± 0% +15.6% 43.04 ± 0% aim7.time.elapsed_time.max > > 6424 ± 1% +31.3% 8432 ± 1% aim7.time.involuntary_context_switches > > 4003 ± 0% +28.1% 5129 ± 1% proc-vmstat.nr_active_file > > 979.25 ± 0% +63.7% 1602 ± 1% proc-vmstat.pgactivate > > 4699 ± 3% +162.6% 12340 ± 73% proc-vmstat.pgpgout > > 50.23 ± 19% -27.3% 36.50 ± 17% sched_debug.cpu.cpu_load[1].avg > > 466.50 ± 29% -51.8% 225.00 ± 73% sched_debug.cpu.cpu_load[1].max > > 77.78 ± 33% -50.6% 38.40 ± 57% sched_debug.cpu.cpu_load[1].stddev > > 300.50 ± 33% -52.9% 141.50 ± 48% sched_debug.cpu.cpu_load[2].max > > 1836 ± 10% +65.5% 3039 ± 8% slabinfo.scsi_data_buffer.active_objs > > 1836 ± 10% +65.5% 3039 ± 8% slabinfo.scsi_data_buffer.num_objs > > 431.75 ± 10% +65.6% 715.00 ± 8% slabinfo.xfs_efd_item.active_objs > > 431.75 ± 10% +65.6% 715.00 ± 8% slabinfo.xfs_efd_item.num_objs > > but what do I know. Those profiles from the robot are pretty hard to > make sense of. Yup, I can't infer anything from most of the stats present. The only thing that stood out is that there's clearly a significant reduction in context switches: 429058 ± 0% -20.0% 343371 ± 0% aim7.time.voluntary_context_switches .... 972882 ± 0% -17.4% 803990 ± 0% perf-stat.context-switches and a significant increase in system CPU time: 376.31 ± 0% +28.5% 483.48 ± 0% aim7.time.system_time .... 1.452e+12 ± 6% +29.5% 1.879e+12 ± 4% perf-stat.instructions 42168 ± 16% +27.5% 53751 ± 6% perf-stat.instructions-per-iTLB-miss It looks to me like the extra system time is running more loops in the same code footprint, not because we are executing a bigger or different footprint of code. That, to me, says there's a change in lock contention behaviour in the workload (which we know aim7 is good at exposing). i.e. the iomap change shifted contention from a sleeping lock to a spinning lock, or maybe we now trigger optimistic spinning behaviour on a lock we previously didn't spin on at all. We really need instruction level perf profiles to understand this - I don't have a machine with this many cpu cores available locally, so I'm not sure I'm going to be able to make any progress tracking it down in the short term. Maybe the lkp team has more in-depth cpu usage profiles they can share? Cheers, Dave. -- Dave Chinner david@fromorbit.com