EXT4 IOPS degradation in 5.10 compared to 5.4

["Bhatnagar, Rishabh" <risbhat@amazon.com>]

Hi Theodore/Jan

We have been seeing a consistent 3% degradation in IOPS score between 
5.4 and 5.10 stable kernels while running fio tests.

I'm running test case on m6g.8xlarge AWS instances using arm64. The test 
involves:

1. Creating 100GB volume with IO1 500 iops. Attaching it to the instance.

2. Setup and mount fs:

|> mke2fs -m 1 -t ext4 -b 4096 -L /mnt /dev/nvme1n1 > mount -t ext4 -o 
noatime,nodiratime,data=ordered /dev/nvme1n1 /mnt|

3. Install fio package and run following test:

(running 16 threads doing random buffered 16kb writes on a file. 
ioengine=psync, runtime=60secs)

|#!/bin/bash jobs=16 blocksize="16k" filesize=1000000 if [[ -n $1 ]]; 
then jobs=$1; fi if [[ -n $2 ]]; then blocksize=$2; fi /usr/bin/fio 
--name=fio-test --directory=/mnt --rw=randwrite --ioengine=psync 
--buffered=1 --bs=${blocksize} \ --max-jobs=${jobs} --numjobs=${jobs} 
--runtime=30 --thread \ --filename=file0 --filesize=${filesize} \ 
--fsync=1 --group_reporting --create_only=1 > /dev/null sudo echo 1 > 
/proc/sys/vm/drop_caches set -x echo "Running with jobs=${jobs} 
filesize=${filesize} blocksize=${blocksize}" /usr/bin/fio 
--name=fio-test --directory=/mnt --rw=randwrite --ioengine=psync 
--buffered=1 --bs=${blocksize} \ --max-jobs=${jobs} --numjobs=${jobs} 
--runtime=60 --thread \ --filename=file0 --filesize=${filesize} \ 
--fsync=1 --group_reporting --time_based|

After doing some kernel bisecting between we were able to pinpoint this 
commit**that drops the iops score by 10~15 points (~3%).*
ext4: avoid unnecessary transaction starts during writeback 
(6b8ed62008a49751fc71fefd2a4f89202a7c2d4d)
*

We see higher iops/bw/total io after reverting the commit compared to 
base 5.10 kernel.
Although the average clat is higher after reverting the commit the 
higher bw drives the iops score higher as seen in below fio output.

*Fio output (5.10.162):/
write: io=431280KB, bw=7186.3KB/s, iops=449, runt= 60015msec/*
/clat (usec): min=6, //*max=25942, avg=267.76,*//stdev=1604.25//
//lat (usec): min=6, //*max=25943, avg=267.93,*//stdev=1604.25//
//clat percentiles (usec)://
//| 1.00th=[ 9], 5.00th=[ 10], 10.00th=[ 16], 20.00th=[ 24],//
//| 30.00th=[ 34], 40.00th=[ 45], 50.00th=[ 58], 60.00th=[ 70],//
//| 70.00th=[ 81], 80.00th=[ 94], 90.00th=[ 107], 95.00th=[ 114],//
//| 99.00th=[10048], 99.50th=[14016], 99.90th=[20096], 99.95th=[21888],//
//| 99.99th=[24448]//
//lat (usec) : 10=3.46%, 20=12.54%, 50=26.66%, 100=41.16%, 250=13.64%//
//lat (usec) : 500=0.02%, 750=0.03%, 1000=0.01%//
//lat (msec) : 2=0.23%, 4=0.50%, 10=0.73%, 20=0.91%, 50=0.12%//
//cpu : usr=0.02%, sys=0.42%, ctx=299540, majf=0, minf=0//
//IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, 
 >=64=0.0%//
//submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%//
//complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, 
 >=64=0.0%//
//issued : total=r=0/w=26955/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0//
//latency : target=0, window=0, percentile=100.00%, depth=1//
//Run status group 0 (all jobs)://
//WRITE: io=431280KB, aggrb=7186KB/s, minb=7186KB/s, maxb=7186KB/s, 
mint=60015msec, maxt=60015msec//
//Disk stats (read/write)://
//nvme1n1: ios=0/30627, merge=0/2125, ticks=0/410990, in_queue=410990, 
util=99.94%/

*Fio output (5.10.162 with revert):*
/*write: io=441920KB, bw=7363.7KB/s, iops=460, runt= 60014msec*/
/clat (usec): min=6, //*max=35768, avg=289.09, *//stdev=1736.62//
//lat (usec): min=6, //*max=35768, avg=289.28,*//stdev=1736.62//
//clat percentiles (usec)://
//| 1.00th=[ 8], 5.00th=[ 10], 10.00th=[ 16], 20.00th=[ 24],//
//| 30.00th=[ 36], 40.00th=[ 46], 50.00th=[ 59], 60.00th=[ 71],//
//| 70.00th=[ 83], 80.00th=[ 97], 90.00th=[ 110], 95.00th=[ 117],//
//| 99.00th=[10048], 99.50th=[14144], 99.90th=[21632], 99.95th=[25984],//
//| 99.99th=[28288]//
//lat (usec) : 10=4.13%, 20=11.67%, 50=26.59%, 100=39.57%, 250=15.28%//
//lat (usec) : 500=0.03%, 750=0.03%, 1000=0.03%//
//lat (msec) : 2=0.20%, 4=0.64%, 10=0.80%, 20=0.86%, 50=0.18%//
//cpu : usr=0.01%, sys=0.43%, ctx=313909, majf=0, minf=0//
//IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, 
 >=64=0.0%//
//submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%//
//complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, 
 >=64=0.0%//
//issued : total=r=0/w=27620/d=0, short=r=0/w=0/d=0, drop=r=0/w=0/d=0//
//latency : target=0, window=0, percentile=100.00%, depth=1//
//Run status group 0 (all jobs)://
//WRITE: io=441920KB, aggrb=7363KB/s, minb=7363KB/s, maxb=7363KB/s, 
mint=60014msec, maxt=60014msec//
//Disk stats (read/write)://
//nvme1n1: ios=0/31549, merge=0/2348, ticks=0/409221, in_queue=409221, 
util=99.88%/


Also i looked ext4_writepages latency which increases when the commit is 
reverted. (This makes sense since the commit avoids unnecessary 
transactions).

*./funclatency ext4_writepages -->(5.10.162)*
*avg = 7734912* nsecs, total: 134131121171 nsecs, *count: 17341*

*./funclatency ext4_writepages -->(5.10.162 with revert)*
*avg = 9036068* nsecs, total: 168956404886 nsecs, *count: 18698*


Looking at the journal transaction data I can see that the average 
transaction commit time decreases after reverting the commit.
This probably helps in the IOPS score.

*5.10.162:*
/*cat /proc/fs/jbd2/nvme1n1-8/info *//--> After 1st test iteration
//2143 transactions (2143 requested), each up to 8192 blocks//
//average: //
//0ms waiting for transaction//
//0ms request delay//
//0ms running transaction//
//0ms transaction was being locked//
//0ms flushing data (in ordered mode)//
//20ms logging transaction//
////*20731us average transaction commit time*//
//51 handles per transaction//
//1 blocks per transaction//
//3 logged blocks per transaction/

*/cat /proc/fs/jbd2/nvme1n1-8/info/*/--> After 2nd test iteration
//4292 transactions (4292 requested), each up to 8192 blocks//
//average: //
//0ms waiting for transaction//
//0ms request delay//
//0ms running transaction//
//0ms transaction was being locked//
//0ms flushing data (in ordered mode)//
//20ms logging transaction//
/ /*26470us average transaction commit time*//
//51 handles per transaction//
//1 blocks per transaction//
//3 logged blocks per transaction/

*5.10.162 with revert:*
/*cat /proc/fs/jbd2/nvme1n1-8/info*///--> After 1st test iteration///
2092 transactions (2091 requested), each up to 8192 blocks//
//average: //
//0ms waiting for transaction//
//0ms request delay//
//20ms running transaction//
//0ms transaction was being locked//
//0ms flushing data (in ordered mode)//
//20ms logging transaction//
////*15981us average transaction commit time*//
//67 handles per transaction//
//1 blocks per transaction//
//2 logged blocks per transaction//
/

*/cat /proc/fs/jbd2/nvme1n1-8/info/*//--> After 2nd test iteration///
4263 transactions (4262 requested), each up to 8192 blocks//
//average: //
//0ms waiting for transaction//
//0ms request delay//
//10ms running transaction//
//0ms transaction was being locked//
//0ms flushing data (in ordered mode)//
//20ms logging transaction//
////*19795us average transaction commit time*//
//65 handles per transaction//
//1 blocks per transaction//
//2 logged blocks per transaction/


Looking at the commit it seems we should be avoiding unnecessary journal 
transactions. This is reflected in the ext4_writepages latency.
But the transaction commit time seems to be increasing with this commit 
leading to reduced IOPS. (atleast that's my theory).
Can you help look into why this commit introduces this IOPS regression? 
Also any suggestions on running any more tests to isolate the issue are 
welcome.

Thanks
Rishabh