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?
_______________________________________________
linux-snps-arc mailing list
[email protected]
http://lists.infradead.org/mailman/listinfo/linux-snps-arc
On Tue, 2018-03-13 at 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
_______________________________________________
linux-snps-arc mailing list
[email protected]
http://lists.infradead.org/mailman/listinfo/linux-snps-arc
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
_______________________________________________
linux-snps-arc mailing list
[email protected]
http://lists.infradead.org/mailman/listinfo/linux-snps-arc
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
_______________________________________________
linux-snps-arc mailing list
[email protected]
http://lists.infradead.org/mailman/listinfo/linux-snps-arc
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
Hi Vineet,
On Thu, 2018-03-15 at 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
On 15/03/18 19:21, Alexey Brodkin wrote:
> Hi Vineet,
>
> On Thu, 2018-03-15 at 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.
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
>
_______________________________________________
linux-snps-arc mailing list
[email protected]
http://lists.infradead.org/mailman/listinfo/linux-snps-arc
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
_______________________________________________
linux-snps-arc mailing list
[email protected]
http://lists.infradead.org/mailman/listinfo/linux-snps-arc
_______________________________________________
linux-snps-arc mailing list
[email protected]
http://lists.infradead.org/mailman/listinfo/linux-snps-arc
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.
_______________________________________________
linux-snps-arc mailing list
[email protected]
http://lists.infradead.org/mailman/listinfo/linux-snps-arc