mmc: block: bonnie++ runs with errors on arc/hsdk board

mmc: block: bonnie++ runs with errors on arc/hsdk board

[Evgeniy Didin]

Hello Adrian,

I have discovered, that beggining with 4.16-rc1 bonnie++ benchmark
runs with errors on arc/hsdk board. After bisecting between 4.15 and 4.16-rc1,
I have found that errors started after?
commit 81196976ed94 (mmc: block: Add blk-mq support).

Error message is like:

| # bonnie++ -u root -r 256 -s 512 -x 1 -d??/mnt?
| Using uid:0, gid:0.
| Writing with putc()...random: crng init done
| done
| Writing intelligently...INFO: task kworker/u8:0:5 blocked for more than 10 seconds.
|??????Not tainted 4.15.0-rc3-00012-g81196976ed94-dirty #1
| "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
| kworker/u8:0????D????0?????5??????2 0x00000000
| Workqueue: writeback wb_workfn (flush-179:0)
|
| Stack Trace:
|??__switch_to+0x0/0xac
|??__schedule+0x1b8/0x738
|??io_schedule+0x5c/0xc0
|??bit_wait_io+0xc/0x48
|??out_of_line_wait_on_bit+0x78/0xc0
|??do_get_write_access+0x1aa/0x4cc
|??jbd2_journal_get_write_access+0x32/0x74
|??__ext4_journal_get_write_access+0x3a/0xac
|??ext4_mb_mark_diskspace_used+0x66/0x5b0
|??ext4_mb_new_blocks+0x1ee/0x830
|??ext4_ext_map_blocks+0x504/0xcac
|??ext4_map_blocks+0x262/0x5e8
|??mpage_map_and_submit_extent+0xb8/0x648
|??ext4_writepages+0x5ce/0x6b4
|??do_writepages+0x20/0x84
|??__writeback_single_inode+0x2a/0x154
|??wb_writeback+0x538/0xae0
|??wb_workfn+0x17c/0x334
|??process_one_work+0x1a6/0x350
|??worker_thread+0xf2/0x478
|??kthread+0x120/0x13c
|??ret_from_fork+0x18/0x1c

There are some details of hsdk_defconfig presented bellow:

SOFTLOCKUP_DETECTOR=y
DETECT_HUNG_TASK=y
DEFAULT_HUNG_TASK_TIMEOUT=10
MMC_DW=y
MMC_DW_PLTFM=y

I have also tested bonnie++ on Wandboard on v4.16-rc5 with the same
DEFAULT_HUNG_TASK_TIMEOUT=10, but there were no errors.

Even though it is not critical error and we see bonnie++ test proceeds to the end,
still it is strange, that some process is running in kernel space for a long time (at least 10sec).
What is strange, before metioned commit I can't reproduce this behaviour.

I am wondering is this expected behaviour??

Best regards,
Evgeniy Didin

mmc: block: bonnie++ runs with errors on arc/hsdk board

[Adrian Hunter]

On 13/03/18 14:04, Evgeniy Didin wrote:
> Hello Adrian,
> 
> I have discovered, that beggining with 4.16-rc1 bonnie++ benchmark
> runs with errors on arc/hsdk board. After bisecting between 4.15 and 4.16-rc1,
> I have found that errors started after?
> commit 81196976ed94 (mmc: block: Add blk-mq support).
> 
> Error message is like:
> 
> | # bonnie++ -u root -r 256 -s 512 -x 1 -d??/mnt?
> | Using uid:0, gid:0.
> | Writing with putc()...random: crng init done
> | done
> | Writing intelligently...INFO: task kworker/u8:0:5 blocked for more than 10 seconds.
> |??????Not tainted 4.15.0-rc3-00012-g81196976ed94-dirty #1
> | "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> | kworker/u8:0????D????0?????5??????2 0x00000000
> | Workqueue: writeback wb_workfn (flush-179:0)
> |
> | Stack Trace:
> |??__switch_to+0x0/0xac
> |??__schedule+0x1b8/0x738
> |??io_schedule+0x5c/0xc0
> |??bit_wait_io+0xc/0x48
> |??out_of_line_wait_on_bit+0x78/0xc0
> |??do_get_write_access+0x1aa/0x4cc
> |??jbd2_journal_get_write_access+0x32/0x74
> |??__ext4_journal_get_write_access+0x3a/0xac
> |??ext4_mb_mark_diskspace_used+0x66/0x5b0
> |??ext4_mb_new_blocks+0x1ee/0x830
> |??ext4_ext_map_blocks+0x504/0xcac
> |??ext4_map_blocks+0x262/0x5e8
> |??mpage_map_and_submit_extent+0xb8/0x648
> |??ext4_writepages+0x5ce/0x6b4
> |??do_writepages+0x20/0x84
> |??__writeback_single_inode+0x2a/0x154
> |??wb_writeback+0x538/0xae0
> |??wb_workfn+0x17c/0x334
> |??process_one_work+0x1a6/0x350
> |??worker_thread+0xf2/0x478
> |??kthread+0x120/0x13c
> |??ret_from_fork+0x18/0x1c
> 
> There are some details of hsdk_defconfig presented bellow:
> 
> SOFTLOCKUP_DETECTOR=y
> DETECT_HUNG_TASK=y
> DEFAULT_HUNG_TASK_TIMEOUT=10
> MMC_DW=y
> MMC_DW_PLTFM=y
> 
> I have also tested bonnie++ on Wandboard on v4.16-rc5 with the same
> DEFAULT_HUNG_TASK_TIMEOUT=10, but there were no errors.
> 
> Even though it is not critical error and we see bonnie++ test proceeds to the end,
> still it is strange, that some process is running in kernel space for a long time (at least 10sec).
> What is strange, before metioned commit I can't reproduce this behaviour.
> 
> I am wondering is this expected behaviour? 

Was the performance affected? i.e. the results from bonnie++

What mount options did you use?

mmc: block: bonnie++ runs with errors on arc/hsdk board

[Evgeniy Didin]

On Tue, 2018-03-13@16:05 +0200, Adrian Hunter wrote:
> On 13/03/18 14:04, Evgeniy Didin wrote:
> > Hello Adrian,
> > 
> > I have discovered, that beggining with 4.16-rc1 bonnie++ benchmark
> > runs with errors on arc/hsdk board. After bisecting between 4.15 and 4.16-rc1,
> > I have found that errors started after?
> > commit 81196976ed94 (mmc: block: Add blk-mq support).
> > 
> > Error message is like:
> > 
> > > # bonnie++ -u root -r 256 -s 512 -x 1 -d??/mnt?
> > > Using uid:0, gid:0.
> > > Writing with putc()...random: crng init done
> > > done
> > > Writing intelligently...INFO: task kworker/u8:0:5 blocked for more than 10 seconds.
> > > ??????Not tainted 4.15.0-rc3-00012-g81196976ed94-dirty #1
> > > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > > kworker/u8:0????D????0?????5??????2 0x00000000
> > > Workqueue: writeback wb_workfn (flush-179:0)
> > > 
> > > Stack Trace:
> > > ??__switch_to+0x0/0xac
> > > ??__schedule+0x1b8/0x738
> > > ??io_schedule+0x5c/0xc0
> > > ??bit_wait_io+0xc/0x48
> > > ??out_of_line_wait_on_bit+0x78/0xc0
> > > ??do_get_write_access+0x1aa/0x4cc
> > > ??jbd2_journal_get_write_access+0x32/0x74
> > > ??__ext4_journal_get_write_access+0x3a/0xac
> > > ??ext4_mb_mark_diskspace_used+0x66/0x5b0
> > > ??ext4_mb_new_blocks+0x1ee/0x830
> > > ??ext4_ext_map_blocks+0x504/0xcac
> > > ??ext4_map_blocks+0x262/0x5e8
> > > ??mpage_map_and_submit_extent+0xb8/0x648
> > > ??ext4_writepages+0x5ce/0x6b4
> > > ??do_writepages+0x20/0x84
> > > ??__writeback_single_inode+0x2a/0x154
> > > ??wb_writeback+0x538/0xae0
> > > ??wb_workfn+0x17c/0x334
> > > ??process_one_work+0x1a6/0x350
> > > ??worker_thread+0xf2/0x478
> > > ??kthread+0x120/0x13c
> > > ??ret_from_fork+0x18/0x1c
> > 
> > There are some details of hsdk_defconfig presented bellow:
> > 
> > SOFTLOCKUP_DETECTOR=y
> > DETECT_HUNG_TASK=y
> > DEFAULT_HUNG_TASK_TIMEOUT=10
> > MMC_DW=y
> > MMC_DW_PLTFM=y
> > 
> > I have also tested bonnie++ on Wandboard on v4.16-rc5 with the same
> > DEFAULT_HUNG_TASK_TIMEOUT=10, but there were no errors.
> > 
> > Even though it is not critical error and we see bonnie++ test proceeds to the end,
> > still it is strange, that some process is running in kernel space for a long time (at least 10sec).
> > What is strange, before metioned commit I can't reproduce this behaviour.
> > 
> > I am wondering is this expected behaviour??
> 
> Was the performance affected? i.e. the results from bonnie++
I have run bonnie++ several times before and after mentioned commit. Here is output:
--------------------------------------------------<8-------------------------------------------------------------------------
Before commit:
ARCLinux,512M,6442,50,7211,0,5333,0,12954,99,345638,100,+++++,+++,16,22322,100,+++++,+++,32735,99,22921,100,+++++,+++,32211,100
ARCLinux,512M,6611,51,7248,0,5162,0,12951,99,344763,99,+++++,+++,16,22649,99,+++++,+++,32723,99,22572,100,+++++,+++,31697,100
ARCLinux,512M,6597,52,7307,0,5368,0,12934,99,343987,99,+++++,+++,16,22775,100,+++++,+++,32713,99,22832,100,+++++,+++,31899,99
After commit:
ARCLinux,512M,4453,36,6474,1,5852,0,12940,99,344329,100,+++++,+++,16,22168,98,+++++,+++,32760,99,22755,100,+++++,+++,32205,100
ARCLinux,512M,5159,42,6944,1,5658,0,12945,99,344290,100,+++++,+++,16,22295,100,+++++,+++,32715,99,22888,99,+++++,+++,32007,99
ARCLinux,512M,5170,42,6840,2,5315,0,12946,99,343889,100,+++++,+++,16,22445,100,+++++,+++,32681,99,22967,100,+++++,+++,32117,99
--------------------------------------------------<8------------------------------------------------------------------------
              ^^^^?
If i understand correctly, in third column is shown "sequential output" per character speed (K/sec), which decreased.

> What mount options did you use?
I didn't use any options. Simply:
# mount /dev/mmcblk0p1 /mnt

Best regards,
Evgeniy Didin

mmc: block: bonnie++ runs with errors on arc/hsdk board

[Evgeniy Didin]

Hi Adrian,
> > 
> > Was the performance affected? i.e. the results from bonnie++
> 
> I have run bonnie++ several times before and after mentioned commit. Here is output:
> --------------------------------------------------<8-------------------------------------------------------------------------
> Before commit:
> ARCLinux,512M,6442,50,7211,0,5333,0,12954,99,345638,100,+++++,+++,16,22322,100,+++++,+++,32735,99,22921,100,+++++,+++,32211,100
> ARCLinux,512M,6611,51,7248,0,5162,0,12951,99,344763,99,+++++,+++,16,22649,99,+++++,+++,32723,99,22572,100,+++++,+++,31697,100
> ARCLinux,512M,6597,52,7307,0,5368,0,12934,99,343987,99,+++++,+++,16,22775,100,+++++,+++,32713,99,22832,100,+++++,+++,31899,99
> After commit:
> ARCLinux,512M,4453,36,6474,1,5852,0,12940,99,344329,100,+++++,+++,16,22168,98,+++++,+++,32760,99,22755,100,+++++,+++,32205,100
> ARCLinux,512M,5159,42,6944,1,5658,0,12945,99,344290,100,+++++,+++,16,22295,100,+++++,+++,32715,99,22888,99,+++++,+++,32007,99
> ARCLinux,512M,5170,42,6840,2,5315,0,12946,99,343889,100,+++++,+++,16,22445,100,+++++,+++,32681,99,22967,100,+++++,+++,32117,99
> --------------------------------------------------<8------------------------------------------------------------------------
> ??????????????^^^^?
> If i understand correctly, in third column is shown "sequential output" per character speed (K/sec), which decreased.
> 
> > What mount options did you use?
> 
> I didn't use any options. Simply:
> # mount /dev/mmcblk0p1 /mnt

Note that the file system on SDcard was ext4.?

Best regards,
Evgeniy Didin

mmc: block: bonnie++ runs with errors on arc/hsdk board

[Adrian Hunter]

On 14/03/18 14:32, Evgeniy Didin wrote:
> Hi Adrian,
>>>
>>> Was the performance affected? i.e. the results from bonnie++
>>
>> I have run bonnie++ several times before and after mentioned commit. Here is output:
>> --------------------------------------------------<8-------------------------------------------------------------------------
>> Before commit:
>> ARCLinux,512M,6442,50,7211,0,5333,0,12954,99,345638,100,+++++,+++,16,22322,100,+++++,+++,32735,99,22921,100,+++++,+++,32211,100
>> ARCLinux,512M,6611,51,7248,0,5162,0,12951,99,344763,99,+++++,+++,16,22649,99,+++++,+++,32723,99,22572,100,+++++,+++,31697,100
>> ARCLinux,512M,6597,52,7307,0,5368,0,12934,99,343987,99,+++++,+++,16,22775,100,+++++,+++,32713,99,22832,100,+++++,+++,31899,99
>> After commit:
>> ARCLinux,512M,4453,36,6474,1,5852,0,12940,99,344329,100,+++++,+++,16,22168,98,+++++,+++,32760,99,22755,100,+++++,+++,32205,100
>> ARCLinux,512M,5159,42,6944,1,5658,0,12945,99,344290,100,+++++,+++,16,22295,100,+++++,+++,32715,99,22888,99,+++++,+++,32007,99
>> ARCLinux,512M,5170,42,6840,2,5315,0,12946,99,343889,100,+++++,+++,16,22445,100,+++++,+++,32681,99,22967,100,+++++,+++,32117,99
>> --------------------------------------------------<8------------------------------------------------------------------------
>> ??????????????^^^^?
>> If i understand correctly, in third column is shown "sequential output" per character speed (K/sec), which decreased.
>>
>>> What mount options did you use?
>>
>> I didn't use any options. Simply:
>> # mount /dev/mmcblk0p1 /mnt
> 
> Note that the file system on SDcard was ext4.?

Please try:

	perf record -a -e mmc:* -- bonnie++ -u root -r 256 -s 512 -x 1 -d /mnt

and share the resulting perf.data file when you are able
to reproduce the hung task message.

You may want to add this patch first:

	https://marc.info/?l=linux-mmc&m=152110580324200

mmc: block: bonnie++ runs with errors on arc/hsdk board

[Evgeniy Didin]

Hi Adrian,

> On 14/03/18 14:32, Evgeniy Didin wrote:
> > Hi Adrian,
> > > > 
> > > > Was the performance affected? i.e. the results from bonnie++
> > > 
> > > I have run bonnie++ several times before and after mentioned commit. Here is output:
> > > --------------------------------------------------<8-------------------------------------------------------------------------
> > > Before commit:
> > > ARCLinux,512M,6442,50,7211,0,5333,0,12954,99,345638,100,+++++,+++,16,22322,100,+++++,+++,32735,99,22921,100,+++++,+++,32211,100
> > > ARCLinux,512M,6611,51,7248,0,5162,0,12951,99,344763,99,+++++,+++,16,22649,99,+++++,+++,32723,99,22572,100,+++++,+++,31697,100
> > > ARCLinux,512M,6597,52,7307,0,5368,0,12934,99,343987,99,+++++,+++,16,22775,100,+++++,+++,32713,99,22832,100,+++++,+++,31899,99
> > > After commit:
> > > ARCLinux,512M,4453,36,6474,1,5852,0,12940,99,344329,100,+++++,+++,16,22168,98,+++++,+++,32760,99,22755,100,+++++,+++,32205,100
> > > ARCLinux,512M,5159,42,6944,1,5658,0,12945,99,344290,100,+++++,+++,16,22295,100,+++++,+++,32715,99,22888,99,+++++,+++,32007,99
> > > ARCLinux,512M,5170,42,6840,2,5315,0,12946,99,343889,100,+++++,+++,16,22445,100,+++++,+++,32681,99,22967,100,+++++,+++,32117,99
> > > --------------------------------------------------<8------------------------------------------------------------------------
> > > ??????????????^^^^?
> > > If i understand correctly, in third column is shown "sequential output" per character speed (K/sec), which decreased.
> > > 
> > > > What mount options did you use?
> > > 
> > > I didn't use any options. Simply:
> > > # mount /dev/mmcblk0p1 /mnt
> > 
> > Note that the file system on SDcard was ext4.?
> 
> Please try:
> 
> 	perf record -a -e mmc:* -- bonnie++ -u root -r 256 -s 512 -x 1 -d /mnt
> and share the resulting perf.data file when you are able
> to reproduce the hung task message.
> 

I have applied the patch below and collected perf.data using command above, hung message also appeared. Is this the information you needed?
(perf.data is in attachments to this
message).
 
> You may want to add this patch first:
> 
> 	https://urldefense.proofpoint.com/v2/url?u=https-3A__marc.info_-3Fl-3Dlinux-2Dmmc-26m-3D152110580324200&d=DwIDaQ&c=DPL6_X_6JkXFx7AXWqB0tg&r=vQk-RIbjwN0zvlwiMSpq3LYUTNf7Gqc4
> ujhosYITtAw&m=LeVFmgzU0ydw-qHaAVh-kZI-v4mldnCycYxIGxqDexU&s=SyGvsVJBOzegO2Mz3hQ5j6CY8KrjLWJERVHfosSmKSs&e=

Best regards,
Evgeniy Didin
-------------- next part --------------
A non-text attachment was scrubbed...
Name: perf.data.gz
Type: application/gzip
Size: 648026 bytes
Desc: perf.data.gz
URL: <http://lists.infradead.org/pipermail/linux-snps-arc/attachments/20180315/63f64b87/attachment-0001.gz>

mmc: block: bonnie++ runs with errors on arc/hsdk board

[Adrian Hunter]

On 15/03/18 17:08, Evgeniy Didin wrote:
> Hi Adrian,
> 
>> On 14/03/18 14:32, Evgeniy Didin wrote:
>>> Hi Adrian,
>>>>>
>>>>> Was the performance affected? i.e. the results from bonnie++
>>>>
>>>> I have run bonnie++ several times before and after mentioned commit. Here is output:
>>>> --------------------------------------------------<8-------------------------------------------------------------------------
>>>> Before commit:
>>>> ARCLinux,512M,6442,50,7211,0,5333,0,12954,99,345638,100,+++++,+++,16,22322,100,+++++,+++,32735,99,22921,100,+++++,+++,32211,100
>>>> ARCLinux,512M,6611,51,7248,0,5162,0,12951,99,344763,99,+++++,+++,16,22649,99,+++++,+++,32723,99,22572,100,+++++,+++,31697,100
>>>> ARCLinux,512M,6597,52,7307,0,5368,0,12934,99,343987,99,+++++,+++,16,22775,100,+++++,+++,32713,99,22832,100,+++++,+++,31899,99
>>>> After commit:
>>>> ARCLinux,512M,4453,36,6474,1,5852,0,12940,99,344329,100,+++++,+++,16,22168,98,+++++,+++,32760,99,22755,100,+++++,+++,32205,100
>>>> ARCLinux,512M,5159,42,6944,1,5658,0,12945,99,344290,100,+++++,+++,16,22295,100,+++++,+++,32715,99,22888,99,+++++,+++,32007,99
>>>> ARCLinux,512M,5170,42,6840,2,5315,0,12946,99,343889,100,+++++,+++,16,22445,100,+++++,+++,32681,99,22967,100,+++++,+++,32117,99
>>>> --------------------------------------------------<8------------------------------------------------------------------------
>>>> ??????????????^^^^?
>>>> If i understand correctly, in third column is shown "sequential output" per character speed (K/sec), which decreased.
>>>>
>>>>> What mount options did you use?
>>>>
>>>> I didn't use any options. Simply:
>>>> # mount /dev/mmcblk0p1 /mnt
>>>
>>> Note that the file system on SDcard was ext4.?
>>
>> Please try:
>>
>> 	perf record -a -e mmc:* -- bonnie++ -u root -r 256 -s 512 -x 1 -d /mnt
>> and share the resulting perf.data file when you are able
>> to reproduce the hung task message.
>>
> 
> I have applied the patch below and collected perf.data using command above, hung message also appeared. Is this the information you needed?
> (perf.data is in attachments to this
> message).

Yes.  Unfortunately the clock used is not accurate enough to correctly order
the events across different CPUs, which makes it very hard to see delays
between requests.  You could try a different clock - refer the --clockid
option to perf record.

Nevertheless it shows there are no I/O errors which means the error recovery
can be ruled out as a problem.

The issue could be caused by the I/O scheduler.  Under blk-mq the default
scheduler is the mq-deadline scheduler whereas without blk-mq you would
probably have been using cfq by default.  You could try the bfq scheduler:

	echo bfq > /sys/block/mmcblk0/queue/scheduler

But you might need to add it to the kernel config i.e.

	CONFIG_IOSCHED_BFQ=y

Alternatively you could fiddle with the scheduler parameters:

With mq-deadline they are:

# grep -H . /sys/block/mmcblk0/queue/iosched/*
/sys/block/mmcblk0/queue/iosched/fifo_batch:16
/sys/block/mmcblk0/queue/iosched/front_merges:1
/sys/block/mmcblk0/queue/iosched/read_expire:500
/sys/block/mmcblk0/queue/iosched/write_expire:5000
/sys/block/mmcblk0/queue/iosched/writes_starved:2

You could try decreasing the write_expire and/or fifo_batch.

>  
>> You may want to add this patch first:
>>
>> 	https://urldefense.proofpoint.com/v2/url?u=https-3A__marc.info_-3Fl-3Dlinux-2Dmmc-26m-3D152110580324200&d=DwIDaQ&c=DPL6_X_6JkXFx7AXWqB0tg&r=vQk-RIbjwN0zvlwiMSpq3LYUTNf7Gqc4
>> ujhosYITtAw&m=LeVFmgzU0ydw-qHaAVh-kZI-v4mldnCycYxIGxqDexU&s=SyGvsVJBOzegO2Mz3hQ5j6CY8KrjLWJERVHfosSmKSs&e=
> 
> Best regards,
> Evgeniy Didin
> 

mmc: block: bonnie++ runs with errors on arc/hsdk board

[Evgeniy Didin]

Hello Adrian,

> Yes.??Unfortunately the clock used is not accurate enough to correctly order
> the events across different CPUs, which makes it very hard to see delays
> between requests.??You could try a different clock - refer the --clockid
> option to perf record.
> 
> Nevertheless it shows there are no I/O errors which means the error recovery
> can be ruled out as a problem.
> 
> The issue could be caused by the I/O scheduler.??Under blk-mq the default
> scheduler is the mq-deadline scheduler whereas without blk-mq you would
> probably have been using cfq by default.??You could try the bfq scheduler:
> 
> 	echo bfq > /sys/block/mmcblk0/queue/scheduler
> 
> But you might need to add it to the kernel config i.e.
> 
> 	CONFIG_IOSCHED_BFQ=y
> 
Switching from mq-deadline scheduler to bfq fixed the issue.
Also bonnie++ results have changed:
-----------------------------------------------<8----------------------------------------------------------------------------
bfq scheduler:
ARCLinux,512M,6463,87,7297,0,5450,0,9827,99,342952,99,+++++,+++,16,17525,100,+++++,+++,24329,99,17621,100,+++++,+++,24001,101

mq-deadline scheduler:
ARCLinux,512M,4453,36,6474,1,5852,0,12940,99,344329,100,+++++,+++,16,22168,98,+++++,+++,32760,99,22755,100,+++++,+++,32205,100
-----------------------------------------------<8----------------------------------------------------------------------------
As I see, the performance of sequential input per char and of file operations have decreased for ~25%.

Do you have any idea what could be a reason for such a long stalling in case of mq-deadline IOscheduler? I would expect if there is 
some long async operation, kernel should not be blocked. But what we see using mq-deadline is kernel blocked in bit_wait_io().
Do you think this is a valid behavior at least in case of mq-deadline IOscheduler?

> Alternatively you could fiddle with the scheduler parameters:
> 
> With mq-deadline they are:
> 
> # grep -H . /sys/block/mmcblk0/queue/iosched/*
> /sys/block/mmcblk0/queue/iosched/fifo_batch:16
> /sys/block/mmcblk0/queue/iosched/front_merges:1
> /sys/block/mmcblk0/queue/iosched/read_expire:500
> /sys/block/mmcblk0/queue/iosched/write_expire:5000
> /sys/block/mmcblk0/queue/iosched/writes_starved:2
> 
> You could try decreasing the write_expire and/or fifo_batch.
It seems that decreasing doesn't affect on this issue.

Best regards,
Evgeniy Didin

mmc: block: bonnie++ runs with errors on arc/hsdk board

[Adrian Hunter]

On 16/03/18 19:10, Evgeniy Didin wrote:
> Hello Adrian,
> 
>> Yes.??Unfortunately the clock used is not accurate enough to correctly order
>> the events across different CPUs, which makes it very hard to see delays
>> between requests.??You could try a different clock - refer the --clockid
>> option to perf record.
>>
>> Nevertheless it shows there are no I/O errors which means the error recovery
>> can be ruled out as a problem.
>>
>> The issue could be caused by the I/O scheduler.??Under blk-mq the default
>> scheduler is the mq-deadline scheduler whereas without blk-mq you would
>> probably have been using cfq by default.??You could try the bfq scheduler:
>>
>> 	echo bfq > /sys/block/mmcblk0/queue/scheduler
>>
>> But you might need to add it to the kernel config i.e.
>>
>> 	CONFIG_IOSCHED_BFQ=y
>>
> Switching from mq-deadline scheduler to bfq fixed the issue.
> Also bonnie++ results have changed:
> -----------------------------------------------<8----------------------------------------------------------------------------
> bfq scheduler:
> ARCLinux,512M,6463,87,7297,0,5450,0,9827,99,342952,99,+++++,+++,16,17525,100,+++++,+++,24329,99,17621,100,+++++,+++,24001,101
> 
> mq-deadline scheduler:
> ARCLinux,512M,4453,36,6474,1,5852,0,12940,99,344329,100,+++++,+++,16,22168,98,+++++,+++,32760,99,22755,100,+++++,+++,32205,100
> -----------------------------------------------<8----------------------------------------------------------------------------
> As I see, the performance of sequential input per char and of file
> operations have decreased for ~25%.

You may need to aggregate more runs, and also compare to BFQ with blk-mq
against CFQ without blk-mq.  If you think BFQ is under-performing, then
contact the BFQ maintainers.

> 
> Do you have any idea what could be a reason for such a long stalling in
> case of mq-deadline IOscheduler?

Write starvation.

>                                 I would expect if there is some long
> async operation, kernel should not be blocked.

The kernel is not blocked.  AFAICT it is the EXT4 journal that is
blocked waiting on a write.

>                                                But what we see using
> mq-deadline is kernel blocked in bit_wait_io(). Do you think this is a
> valid behavior at least in case of mq-deadline IOscheduler?

mq-deadline is designed to favour reads over writes, so in that sense some
amount of write-starvation is normal.

> 
>> Alternatively you could fiddle with the scheduler parameters:
>>
>> With mq-deadline they are:
>>
>> # grep -H . /sys/block/mmcblk0/queue/iosched/*
>> /sys/block/mmcblk0/queue/iosched/fifo_batch:16
>> /sys/block/mmcblk0/queue/iosched/front_merges:1
>> /sys/block/mmcblk0/queue/iosched/read_expire:500
>> /sys/block/mmcblk0/queue/iosched/write_expire:5000
>> /sys/block/mmcblk0/queue/iosched/writes_starved:2
>>
>> You could try decreasing the write_expire and/or fifo_batch.
> It seems that decreasing doesn't affect on this issue.

That is surprising.  You could also try writes_starved=1 or
writes_starved=0.

mmc: block: bonnie++ runs with errors on arc/hsdk board

[Vineet Gupta]

On 03/15/2018 02:27 AM, Adrian Hunter wrote:
> Please try:
> 
> 	perf record -a -e mmc:* -- bonnie++ -u root -r 256 -s 512 -x 1 -d /mnt
> 
> and share the resulting perf.data file when you are able
> to reproduce the hung task message.
> 
> You may want to add this patch first:
> 
> 	https://marc.info/?l=linux-mmc&m=152110580324200

While this SoC has perf counters, Unfortunately the overflow interrupts are not 
wired up. We can do perf stats but not sampling.

Peter was it you or Vince trying to use timer interrupts to emulate perf sampling 
on some ARM SoC ?

Thing is we have a spare hardware timer per core (TIMER1) which is not usabel for 
otherwise gtod function in SMP and could well be repurposed for perf needs.

-Vineet

mmc: block: bonnie++ runs with errors on arc/hsdk board

[Alexey Brodkin]

Hi Vineet,

On Thu, 2018-03-15@09:38 -0700, Vineet Gupta wrote:
> On 03/15/2018 02:27 AM, Adrian Hunter wrote:
> > Please try:
> > 
> > 	perf record -a -e mmc:* -- bonnie++ -u root -r 256 -s 512 -x 1 -d /mnt
> > 
> > and share the resulting perf.data file when you are able
> > to reproduce the hung task message.
> > 
> > You may want to add this patch first:
> > 
> > 	https://marc.info/?l=linux-mmc&m=152110580324200
> 
> While this SoC has perf counters, Unfortunately the overflow interrupts are not 
> wired up. We can do perf stats but not sampling.

I guess here Adrian was asking for pure software MMC-related events which are
orthogonal to CPU's perf interrupts.

Adrian?

-Alexey

mmc: block: bonnie++ runs with errors on arc/hsdk board

[Adrian Hunter]

On 15/03/18 19:21, Alexey Brodkin wrote:
> Hi Vineet,
> 
> On Thu, 2018-03-15@09:38 -0700, Vineet Gupta wrote:
>> On 03/15/2018 02:27 AM, Adrian Hunter wrote:
>>> Please try:
>>>
>>> 	perf record -a -e mmc:* -- bonnie++ -u root -r 256 -s 512 -x 1 -d /mnt
>>>
>>> and share the resulting perf.data file when you are able
>>> to reproduce the hung task message.
>>>
>>> You may want to add this patch first:
>>>
>>> 	https://marc.info/?l=linux-mmc&m=152110580324200
>>
>> While this SoC has perf counters, Unfortunately the overflow interrupts are not 
>> wired up. We can do perf stats but not sampling.
> 
> I guess here Adrian was asking for pure software MMC-related events which are
> orthogonal to CPU's perf interrupts.
> 
> Adrian?

Yes, these are mmc tracepoints which are software events.  The file is full
of them, so it certainly worked.