Re: Understanding blktrace; measuring extra writes on ext4 with open(...,O_DSNYC | O_TRUNC)

On Fri, Aug 2, 2024 at 3:36 PM Ojaswin Mujoo <[email protected]> wrote:
>
> On Fri, Aug 02, 2024 at 10:28:47AM +0200, Max Schulze wrote:
> > Hello,
> >
> > so I have an embedded application with limited flash write cycles. I am writing 2 blocks to disk 5 times a second (ext4, block size 1024).
> > The data written is binary and fixed size and to date I open the files with (O_CREAT | O_WRONLY | O_DSYNC | O_TRUNC).
> >
> > I set out to measure whether this O_TRUNC leads to an extra write (because I might be able to do without - data is fixed size) and understand the linux tooling around for inspection.
> >
> > I wrote a test script, that creates a 2MB ext4 file system on a separate block device, so I can trace with blktrace -d /dev/sdc
> >
> > If somebody please could have a look if the interpretation of the traces is correct and what the missing identifiers are.
> >
> >
> > Below is the output from blkparse for the moments where I write with open (DSYNC | TRUNC)
> >
> > >
> > >   8,32   2      152     8.831293895 22900  C RAM 2060 + 2 [0]             <-- previous _C_omplete
> > >   8,32  10        2     9.245982628 14449  D   N 0 [kworker/u40:2]        <-- D =issued
> > >   8,32   2      153     9.246369033 22900  C   N [0]                      <-- C_omplete
> > >   8,32   0      200     9.268019255 15706  A  RM 2062 + 2 <- (8,33) 14    <-- A = remap
> > >   8,32   0      201     9.268020922 15706  Q  RM 2062 + 2 [writerdt]      <-- Queued
> > >   8,32   0      202     9.268034745 15706  G  RM 2062 + 2 [writerdt]      <-- Get = allocate Req.
> > >   8,32   0      203     9.268051167 15706  I  RM 2062 + 2 [writerdt]      <-- I_nserted in Queue
> > >   8,32   0      204     9.268107127   161  D  RM 2062 + 2 [kworker/0:1H]  <-- D issued "R"ead
> > >   8,32   2      154     9.268704050 22900  C  RM 2062 + 2 [0]
> > >   8,32   0      205     9.268881750 15706  A  WS 2160 + 2 <- (8,33) 112
> > >   8,32   0      206     9.268882510 15706  Q  WS 2160 + 2 [writerdt]
> > >   8,32   0      207     9.268890935 15706  G  WS 2160 + 2 [writerdt]
> > >   8,32   0      208     9.268891685 15706  P   N [writerdt]
> > >   8,32   0      209     9.268892510 15706  U   N [writerdt] 1
> > >   8,32   0      210     9.268895672 15706  I  WS 2160 + 2 [writerdt]
> > >   8,32   0      211     9.268913234 15706  D  WS 2160 + 2 [writerdt]      <-- D issued "W"rite "S"ynchronous
> > >   8,32   2      155     9.271009859 22900  C  WS 2160 + 2 [0]
> > >   8,32   0      212     9.271041534 15706  A WSM 2126 + 2 <- (8,33) 78
> > >   8,32   0      213     9.271041910 15706  Q WSM 2126 + 2 [writerdt]
> > >   8,32   0      214     9.271051615 15706  G WSM 2126 + 2 [writerdt]
> > >   8,32   0      215     9.271053774 15706  I WSM 2126 + 2 [writerdt]
> > >   8,32   0      216     9.271075678   161  D WSM 2126 + 2 [kworker/0:1H]  <-- D issued "W"rite "S"ynchronous
> > >   8,32   2      156     9.273122709 22900  C WSM 2126 + 2 [0]
> > >   8,32   4       67    10.277429577 13420  A  WM 2050 + 2 <- (8,33) 2
> >
> >
> > -> What are M and N in the "rwbs" field? I could not find this in the manpage.
>
> Hey Max,
>
> I had the same confusion sometime back and had to dig in the kernel
> code. All the rwbs values the latest kernel supports can be found
> in this function [1].
>
> So 'M' is added for metadata requests eg when FS is reading some
> metadata blocks. 'N' is added when the request is neither
> read/write/discard etc. I'm not sure what kind of IO results in N though
> so maybe someone else might be able to add to this.
>
> [1]
> https://github.com/torvalds/linux/blob/master/kernel/trace/blktrace.c#L1875
>
> (I'll try to go through the trace you provided when i find some time and
> update here)
>
> Regards,
> ojaswin
>

I did a presentation on blktrace / blkparse at DevConf.US 2019, so
that presentation PDF might be useful [1].

The "N" is shown mainly for "queue plug" or "queue unplug" events:

P  N (queue was plugged)
U  N (queue was unplugged)
UT  N (queue was unplugged by timer)

[1] https://devconfus2019.sched.com/event/RknY/block-storage-tracing-in-the-linux-kernel


Thanks,

Bryan