bug#81269: dd (coreutils 9.7): incorrect elapsed time reporting causes impossible throughput (7.9 GB/s)

Sick Pigs <[email protected]> writes:

> I believe I have found a reproducible bug in GNU dd where the reported
> elapsed time
> (and therefore throughput) is incorrect, even though the actual data is
> written correctly. This leads to physically impossible speed reporting
> (e.g. 7.9 GB/s to a SATA SSD).
>
> System Information:
>
> OS:
> Linux nobara-pc 7.0.9-200.nobara.fc43.x86_64 #1 SMP PREEMPT_DYNAMIC
>
> dd version:
> dd (coreutils) 9.7
>
> Device:
> /dev/sda (SATA SSD, EDILOCA ES580E 240GB)
>
> Commands Run:
>
> 1) Write ISO to disk:
> sudo dd if=3Dimage.iso of=3D/dev/sda bs=3D4M conv=3Dfsync status=3Dprogre=
ss
>
> 627+1 records in
> 627+1 records out
> 2630580224 bytes copied, 0.33473 s, 7.9 GB/s
>
> 2) Independent timing verification:
> time sudo dd if=3Dimage.iso of=3D/dev/sda bs=3D4M conv=3Dfsync status=3Dn=
one
>
> real 0m5.782s
> user 0m0.004s
> sys 0m0.012s
>
> 3) Verification of correctness:
> cmp image.iso /dev/sda
> (no output, exit status 0)
>
> 4) Additional test:
> Using oflag=3Ddirect produces the same incorrect timing behavior.
>
> Kernel confirms write and partition table update:
> GPT warnings appear for /dev/sda after write, confirming device was
> modified.
>
> Expected Behaviour:
> The elapsed time reported by dd should match wall-clock time, or at least
> be consistent with external timing tools like `time`. Throughput should be
> consistent with actual device performance (~400=E2=80=93550 MB/s for cons=
umer SATA
> SSD).
>
> Actual Behaviour:
> dd reports elapsed time of ~0.33s, implying ~7.9 GB/s throughput, which is
> physically impossible for the hardware. However, external timing (`time`)
> shows the operation actually took ~5.8s, and the written data is correct.
>
> Additiuonal Notes:
>
> The issue appears to be purely in dd's internal timing/statistics
> reporting, not in the actual write operation itself, which completes
> correctly.
> I can reproduce this consistently with:
> - status=3Dprogress
> - conv=3Dfsync
> - coreutils 9.7
> - Linux kernel 7.0.9 (Nobara)

It sounds like fsync took ~5.5s on your system. Can you check that? You
can check with the following command:

    $ strace -tt -T dd if=3Dimage.iso of=3D/dev/sda bs=3D4M conv=3Dfsync \
        status=3Dprogress

Note that the output can get quite long. If you share it on list you can
just remove all of the lines aside from the fysnc and a few lines before
and after. E.g., using:

    $ strace -tt -T dd if=3Dimage.iso of=3D/dev/sda bs=3D4M conv=3Dfsync \
        status=3Dprogress 2>&1 > /dev/null | tail -n 20

I believe the behavior is expected, at least after the following commit:

    $ git log c4f9554ee923c27529cdb76b6f75051183f59c1a -n 1
    commit c4f9554ee923c27529cdb76b6f75051183f59c1a
    Author:     Paul Eggert <[email protected]>
    AuthorDate: Thu Jan 27 18:34:09 2022 -0800
    Commit:     Paul Eggert <[email protected]>
    CommitDate: Thu Jan 27 18:35:02 2022 -0800
=20=20=20=20
        dd: output final progress before syncing
=20=20=20=20=20=20=20=20
        Problem reported by Sworddragon (Bug#51482).
        * src/dd.c (reported_w_bytes): New var.
        (print_xfer_stats): Set it.
        (dd_copy): Print a final progress report if useful before
        synchronizing output data.

Before that change, if there was a final progress indication that had to
be printed it would occur after fdatasync/fsync. Since those system
calls can, and often do, take a long time you would see a tiny
throughput [1] [2].

I guess the current behavior is confusing as well, but I feel like it is
slightly less confusing then the behavior before that change.

Collin

[1] https://bugs.gnu.org/51345
[2] https://bugs.gnu.org/51482