Re: Slow I/O on USB media after commit f664a3cc17b7d0a2bc3b3ab96181e1029b0ec0e6

[Ming Lei <ming.lei@redhat.com>]

On Tue, Nov 26, 2019 at 12:14:19PM +0100, Andrea Vai wrote:
> Il giorno mar, 26/11/2019 alle 17.15 +0800, Ming Lei ha scritto:
> > On Tue, Nov 26, 2019 at 08:46:07AM +0100, Andrea Vai wrote:
> > > Il giorno mar, 26/11/2019 alle 10.32 +0800, Ming Lei ha scritto:
> > > > On Mon, Nov 25, 2019 at 07:51:33PM +0100, Andrea Vai wrote:
> > > > > Il giorno lun, 25/11/2019 alle 23.15 +0800, Ming Lei ha
> > scritto:
> > > > > > On Mon, Nov 25, 2019 at 03:58:34PM +0100, Andrea Vai wrote:
> > > > > > 
> > > > > > [...]
> > > > > > 
> > > > > > > What to try next?
> > > > > > 
> > > > > > 1) cat /sys/kernel/debug/block/$DISK/hctx0/flags
> > > > > result:
> > > > > 
> > > > > alloc_policy=FIFO SHOULD_MERGE|2
> > > > > 
> > > > > > 
> > > > > > 
> > > > > > 2) echo 128 > /sys/block/$DISK/queue/nr_requests and run
> > your
> > > > copy
> > > > > > 1GB
> > > > > > test again.
> > > > > 
> > > > > done, and still fails. What to try next?
> > > > 
> > > > I just run 256M cp test
> > > 
> > > I would like to point out that 256MB is a filesize that usually
> > don't
> > > trigger the issue (don't know if it matters, sorry).
> > 
> > OK.
> > 
> > I tested 256M because IO timeout is often triggered in case of
> > qemu-ehci, and it is a long-term issue. When setting up the disk
> > via xhci-qemu, the max request size is increased to 1MB from 120KB,
> > and IO pattern changed too. When the disk is connected via uhci-
> > qemu,
> > the transfer is too slow(1MB/s) because max endpoint size is too
> > small.
> > 
> > However, I just waited 16min and collected all the 1GB IO log by
> > connecting disk over uhci-qemu, but the sector of each data IO
> > is still in order.
> > 
> > > 
> > > Another info I would provide is about another strange behavior I
> > > noticed: yesterday I ran the test two times (as usual with 1GB
> > > filesize) and took 2370s, 1786s, and a third test was going on
> > when I
> > > stopped it. Then I started another set of 100 trials and let them
> > run
> > > tonight, and the first 10 trials were around 1000s, then gradually
> > > decreased to ~300s, and finally settled around 200s with some
> > trials
> > > below 70-80s. This to say, times are extremely variable and for
> > the
> > > first time I noticed a sort of "performance increase" with time.
> > 
> > The 'cp' test is buffered IO, can you reproduce it every time by
> > running copy just after fresh mount on the USB disk?
> 
> yes, every time my test script (attached) mounts, copy, unmount (but I
> don't unplug and replug the pendrive each time). Is this enough?
> 
> > 
> > > 
> > > >  to one USB storage device on patched kernel,
> > > > and WRITE data IO is really in ascending order. The filesystem
> > is
> > > > ext4,
> > > > and mount without '-o sync'. From previous discussion, looks
> > that is
> > > > exactly your test setting. The order can be observed via the
> > > > following script:
> > > > 
> > > > #!/bin/sh
> > > > MAJ=$1
> > > > MIN=$2
> > > > MAJ=$(( $MAJ << 20 ))
> > > > DEV=$(( $MAJ | $MIN ))
> > > > /usr/share/bcc/tools/trace -t -C \
> > > >   't:block:block_rq_issue (args->dev == '$DEV') "%s %d %d",
> > args-
> > > > >rwbs, args->sector, args->nr_sector'
> > > > 
> > > > $MAJ & $MIN can be retrieved via lsblk for your USB storage
> > disk.
> 
> ok, so I try:
> 
> # lsblk /dev/sdf
> NAME   MAJ:MIN RM  SIZE RO TYPE MOUNTPOINT
> sdf      8:80   1 28,8G  0 disk 
> └─sdf1   8:81   1 28,8G  0 part 
> 
> so I ran your script (the second one, which you sent me in the next
> email message) with:
> 
> ./test_ming 8 80
> 
> but it fails to run (terminal output is in attached errors.txt).
> What am I doing wrong?
> 
> It's still not clear to me if I need to start the trace script and
> then the test, or the opposite (or doesn't matter). The above errors
> are in the former case (I didn't even start the test, actually)
> 
> Thanks,
> Andrea

> In file included from /virtual/main.c:2:
> In file included from /lib/modules/5.4.0+/build/include/linux/ptrace.h:6:
> In file included from /lib/modules/5.4.0+/build/include/linux/sched.h:14:
> In file included from /lib/modules/5.4.0+/build/include/linux/pid.h:5:
> In file included from /lib/modules/5.4.0+/build/include/linux/rculist.h:11:
> In file included from /lib/modules/5.4.0+/build/include/linux/rcupdate.h:26:
> In file included from /lib/modules/5.4.0+/build/include/linux/irqflags.h:16:
> In file included from /lib/modules/5.4.0+/build/arch/x86/include/asm/irqflags.h:9:
> In file included from /lib/modules/5.4.0+/build/arch/x86/include/asm/nospec-branch.h:314:
> /lib/modules/5.4.0+/build/arch/x86/include/asm/segment.h:254:2: error: expected '(' after 'asm'
>         alternative_io ("lsl %[seg],%[p]",
>         ^
> /lib/modules/5.4.0+/build/arch/x86/include/asm/alternative.h:240:2: note: expanded from macro 'alternative_io'
>         asm_inline volatile (ALTERNATIVE(oldinstr, newinstr, feature)   \
>         ^
> /lib/modules/5.4.0+/build/include/linux/compiler_types.h:210:24: note: expanded from macro 'asm_inline'
> #define asm_inline asm __inline
>                        ^
> In file included from /virtual/main.c:2:
> In file included from /lib/modules/5.4.0+/build/include/linux/ptrace.h:6:
> In file included from /lib/modules/5.4.0+/build/include/linux/sched.h:14:
> In file included from /lib/modules/5.4.0+/build/include/linux/pid.h:5:
> In file included from /lib/modules/5.4.0+/build/include/linux/rculist.h:11:
> In file included from /lib/modules/5.4.0+/build/include/linux/rcupdate.h:27:
> In file included from /lib/modules/5.4.0+/build/include/linux/preempt.h:78:
> In file included from /lib/modules/5.4.0+/build/arch/x86/include/asm/preempt.h:7:
> In file included from /lib/modules/5.4.0+/build/include/linux/thread_info.h:38:
> In file included from /lib/modules/5.4.0+/build/arch/x86/include/asm/thread_info.h:12:
> In file included from /lib/modules/5.4.0+/build/arch/x86/include/asm/page.h:12:
> /lib/modules/5.4.0+/build/arch/x86/include/asm/page_64.h:49:2: error: expected '(' after 'asm'
>         alternative_call_2(clear_page_orig,
>         ^
> /lib/modules/5.4.0+/build/arch/x86/include/asm/alternative.h:256:2: note: expanded from macro 'alternative_call_2'
>         asm_inline volatile (ALTERNATIVE_2("call %P[old]", "call %P[new1]", feature1,\
>         ^
> /lib/modules/5.4.0+/build/include/linux/compiler_types.h:210:24: note: expanded from macro 'asm_inline'
> #define asm_inline asm __inline


It can be workaround via the following change:

/lib/modules/5.4.0+/build/include/generated/autoconf.h:

//#define CONFIG_CC_HAS_ASM_INLINE 1


Thanks,
Ming