Adding more CC and re-attaching the reproducer and the 25s log.

On Wed, Feb 26, 2020 at 11:03 AM Michael Stapelberg
<michael+lkml@stapelberg.ch> wrote:
>
> Find attached two logs:
>
> fuse-1s.log shows the expected case
>
> fuse-25s.log shows the issue. Note that the log spans 2 days. I
> started the cp at 10:54:53.251395. Note how the first WRITE opcode is
> only received at 10:55:18.094578!

Observations:

- apparently memcpy is copying downwards (from largest address to
smallest address).  Not sure why, when I run the reproducer, it copies
upwards.
- there's a slow batch of reads of the first ~4MB of data, then a
quick writeback
- there's a quick read of the rest (~95MB) of data, then a quick
writeback of the same

Plots of the whole and closeups of slow and quick segments attached.
X axis is time, Y axis is offset.

Tejun, could this behavior be attributed to dirty throttling?  What
would be the best way to trace this?

Thanks,
Miklos


>
> Is there some sort of readahead going on that’s then being throttled somewhere?
>
> Thanks,
>
> On Mon, Feb 24, 2020 at 3:23 PM Miklos Szeredi <miklos@szeredi.hu> wrote:
> >
> > On Mon, Feb 24, 2020 at 3:18 PM Michael Stapelberg
> > <michael+lkml@stapelberg.ch> wrote:
> > >
> > > Sorry, to clarify: the hang is always in the memcpy call. I.e., the
> > > “Mapped” message is always printed, and it takes a long time until
> > > “memcpy done” is printed.
> >
> > Have you tried running the fuse daemon with debugging enabled?  Is
> > there any observable difference between the fast and the slow runs?
> >
> > Thanks,
> > Miklos