feat: estimate the time remaining from bytes and observed rate

rsync reports each file's size with %l as it completes, which is all an
estimate needs: bytes done over time elapsed is the same arithmetic rsync would
do internally, and requires nothing it does not already print. The scan pass now
sums those sizes as well as counting files, so both a percentage and an estimate
have a real denominator.

The rate is measured over a trailing thirty seconds rather than the whole run,
so it follows a device that slows down instead of averaging the slowdown away --
which for a card reader that thermally throttles, or a USB link that renegotiates
after an hour, is the difference between a useful estimate and a reassuring one.

Below two seconds no rate is reported at all. The first handful of files arrive
microseconds apart, and dividing by that window produces a rate in the gigabytes
per second and an estimate of zero, which is worse than showing nothing.

Directory entries are excluded from the byte total as well as the file count.
rsync reports them with a 4096 inode size, which across six thousand album
directories is several megabytes of transfer that never happens.

README.md

@@ -166,15 +166,24 @@ remove the Rockbox install.
 Progress is a single line that rewrites itself:
 
 ```
-[ 12,345 / 49,600  24%] King Gizzard & the Lizard Wizard / PetroDragonic Apoc…
+[ 24%] 12,345/49,600  3.2 GiB/13.1 GiB  4.4 MiB/s  ETA 38m12s  King Gizzard / Petro…
 ```
 
+The estimate comes from rsync's `%l`, which gives each file's size as it
+completes. Bytes done over time elapsed is the same arithmetic rsync would do,
+and needs nothing it does not already print. The rate is measured over a
+trailing thirty seconds rather than the whole run, so it follows a device that
+slows down instead of averaging the slowdown away — and it is suppressed
+entirely for the first two seconds, where the window is microseconds wide and
+would report gigabytes per second.
+
 rsync says nothing at all while it builds its file list, which on fifty
 thousand files over USB is minutes of apparent hang, and its own `progress2`
 percentage is computed against a list it has not finished discovering. So the
-script counts first — a second pass over the tree, which is what a percentage
+script counts first — files and bytes both, a second pass over the tree, which
-that means something costs — and renders the rest itself. Piped to a log it
+is what a percentage and an estimate that mean something cost — and renders the
-prints a plain line every thirty seconds instead, with no carriage returns.
+rest itself. Piped to a log it prints a plain line every thirty seconds
+instead, with no carriage returns, and a summary at the end either way.
 
 The unmount is the point of doing this in a script. FAT32 has no journal and
 the device is reached through disk mode, so an interrupted write is corruption

tests/test_rsync_progress.py

@@ -19,9 +19,13 @@ class Terminal(io.StringIO):
         return True
 
 
-def run(lines, total=0, out=None):
+def run(lines, total=0, out=None, bytes_expected=0):
     out = out or NotATerminal()
-    rsync_progress.main(["--total", str(total)], stream=io.StringIO(lines), out=out)
+    rsync_progress.main(
+        ["--total", str(total), "--bytes", str(bytes_expected)],
+        stream=io.StringIO(lines),
+        out=out,
+    )
     return out.getvalue()
 
 
@@ -40,15 +44,15 @@ def test_directories_are_not_counted():
     """rsync reports them too, and counting them puts the percentage past 100."""
     output = run("Artist/\nArtist/Album/\nArtist/Album/track.mp3\n", total=1)
 
-    assert "1 / 1" in output
+    assert "1/1" in output
     assert "100%" in output
 
 
 def test_the_percentage_tracks_the_total():
     output = run("".join(f"A/B/{i}.mp3\n" for i in range(5)), total=10)
 
-    assert "5 / 10" in output
+    assert "5/10" in output
-    assert " 50%" in output
+    assert "50%" in output
 
 
 def test_without_a_total_it_counts_instead_of_guessing():
@@ -64,7 +68,7 @@ def test_a_final_line_is_always_printed():
     output = run("A/B/one.mp3\n", total=1)
 
     assert output.endswith("\n")
-    assert "1 / 1" in output
+    assert "1/1" in output
 
 
 def test_nothing_transferred_still_reports():
@@ -102,3 +106,75 @@ def test_long_labels_are_trimmed_from_the_left(text, width, expected):
     if len(text) > width:
         assert trimmed.startswith("…")
         assert text.endswith(trimmed.lstrip("…"))
+
+
+def test_the_size_and_path_are_parsed():
+    assert rsync_progress.parse("5000 Artist/Album/Track.mp3\n") == (
+        5000,
+        "Artist/Album/Track.mp3",
+    )
+
+
+def test_a_filename_containing_spaces_survives():
+    """Splitting on every space would lose most of the library."""
+    assert rsync_progress.parse("1234 Artist/An Album/A Track With Spaces.mp3") == (
+        1234,
+        "Artist/An Album/A Track With Spaces.mp3",
+    )
+
+
+def test_a_bare_path_is_tolerated():
+    """In case this is fed --out-format='%n' by something older."""
+    assert rsync_progress.parse("Artist/Album/Track.mp3") == (0, "Artist/Album/Track.mp3")
+
+
+def test_directory_sizes_do_not_inflate_the_total():
+    """rsync reports directories with a 4096 inode size, which is several
+    megabytes of nothing across six thousand albums."""
+    output = run("4096 Artist/\n4096 Artist/Album/\n5000 Artist/Album/t.mp3\n", total=1)
+
+    assert "4.9 KiB" in output
+    assert "12" not in output.split("Artist")[0]
+
+
+def test_a_rate_is_not_reported_until_it_means_something():
+    """The first files arrive microseconds apart and would give a rate in the
+    gigabytes per second and an ETA of zero."""
+    rate = rsync_progress.Rate()
+    rate.add(100.0, 0)
+    rate.add(100.5, 5_000_000)
+
+    assert rate.per_second() == 0.0
+
+
+def test_a_rate_over_a_long_enough_window_is_reported():
+    rate = rsync_progress.Rate()
+    rate.add(100.0, 0)
+    rate.add(110.0, 10_000_000)
+
+    assert rate.per_second() == pytest.approx(1_000_000)
+
+
+def test_the_window_forgets_the_distant_past():
+    """So the estimate follows a device that slows down rather than averaging
+    the slowdown away."""
+    rate = rsync_progress.Rate(window=30.0)
+    for second in range(0, 100, 10):
+        rate.add(float(second), second * 1_000_000)
+    rate.add(200.0, 100_000_000)
+
+    assert rate.samples[0][0] >= 90.0
+
+
+@pytest.mark.parametrize(
+    ("seconds", "expected"),
+    [(0, "0s"), (45, "45s"), (60, "1m00s"), (1092, "18m12s"), (7500, "2h05m")],
+)
+def test_durations_read_without_arithmetic(seconds, expected):
+    assert rsync_progress.human_duration(seconds) == expected
+
+
+def test_a_summary_is_printed_at_the_end():
+    output = run("5000000 A/B/one.mp3\n", total=1, bytes_expected=5000000)
+
+    assert "copied 4.8 MiB in" in output

tools/rsync_progress.py

@@ -1,7 +1,10 @@
 #!/usr/bin/env python3
 """Render rsync's per-file output as a single updating status line.
 
-Fed the paths rsync reports with --out-format='%n', one per line. Prints one
+Fed the size and path rsync reports with --out-format='%l %n', one per line.
+The size is what makes an estimate possible: rsync's own rate is not exposed
+per file, but bytes completed over time elapsed is the same arithmetic and
+needs nothing rsync does not already print. Prints one
 line that rewrites itself, showing how far through the transfer is and which
 album is currently going across, rather than either scrolling fifty thousand
 filenames past or -- as rsync does while it builds its file list -- saying
@@ -12,11 +15,76 @@ not fill up with carriage returns.
 """
 
 import argparse
+import collections
 import os
 import shutil
 import sys
 import time
 
+# The estimate is taken over a trailing window rather than the whole run, so it
+# follows a device that slows down instead of averaging the slowdown away.
+RATE_WINDOW_SECONDS = 30.0
+
+# Below this the window is too narrow to divide by: the first few files arrive
+# in microseconds and produce a rate in the gigabytes per second, and an ETA of
+# nothing at all. Better to show neither until the figure means something.
+RATE_MINIMUM_SPAN_SECONDS = 2.0
+
+
+def parse(line):
+    """Return (bytes, path) for one line of rsync output.
+
+    Tolerates a bare path, in case someone runs this against --out-format='%n'.
+    """
+    line = line.rstrip("\n")
+    size, separator, path = line.partition(" ")
+    if separator and size.isdigit():
+        return int(size), path
+    return 0, line
+
+
+def human_bytes(count):
+    size = float(count)
+    for unit in ("B", "KiB", "MiB", "GiB", "TiB"):
+        if size < 1024 or unit == "TiB":
+            return f"{size:.1f} {unit}"
+        size /= 1024
+
+
+def human_duration(seconds):
+    """Return a duration nobody has to do arithmetic on."""
+    seconds = int(seconds)
+    if seconds < 60:
+        return f"{seconds}s"
+    if seconds < 3600:
+        return f"{seconds // 60}m{seconds % 60:02d}s"
+    return f"{seconds // 3600}h{(seconds % 3600) // 60:02d}m"
+
+
+class Rate:
+    """Bytes per second over a trailing window."""
+
+    def __init__(self, window=RATE_WINDOW_SECONDS):
+        self.window = window
+        self.samples = collections.deque()
+
+    def add(self, when, total_bytes):
+        self.samples.append((when, total_bytes))
+        while len(self.samples) > 2 and when - self.samples[0][0] > self.window:
+            self.samples.popleft()
+
+    def per_second(self):
+        if len(self.samples) < 2:
+            return 0.0
+        (first_time, first_bytes), (last_time, last_bytes) = (
+            self.samples[0],
+            self.samples[-1],
+        )
+        elapsed = last_time - first_time
+        if elapsed < RATE_MINIMUM_SPAN_SECONDS:
+            return 0.0
+        return (last_bytes - first_bytes) / elapsed
+
 
 def album_of(path):
     """Return "Artist / Album" for a mirror-relative path."""
@@ -35,18 +103,29 @@ def fit(text, width):
     return "…" + text[-(width - 1) :]
 
 
-def render(done, total, label, width):
+def render(done, total, copied, expected, rate, label, width):
+    """Build the status line, giving whatever room is left to the album."""
     if total > 0:
         share = min(100, done * 100 // total)
-        head = f"[{done:>6,} / {total:<6,} {share:>3}%] "
+        head = f"[{share:>3}%] {done:,}/{total:,}"
     else:
-        head = f"[{done:>6,} files] "
+        head = f"[{done:,} files]"
+
+    if expected > 0:
+        head += f"  {human_bytes(copied)}/{human_bytes(expected)}"
+    if rate > 0:
+        head += f"  {human_bytes(rate)}/s"
+        remaining = expected - copied
+        if remaining > 0:
+            head += f"  ETA {human_duration(remaining / rate)}"
+    head += "  "
     return head + fit(label, max(0, width - len(head)))
 
 
 def main(argv=None, stream=None, out=None):
     parser = argparse.ArgumentParser(description=__doc__)
     parser.add_argument("--total", type=int, default=0, help="files expected")
+    parser.add_argument("--bytes", type=int, default=0, help="bytes expected")
     parser.add_argument("--interval", type=float, default=0.1, help="seconds between redraws")
     args = parser.parse_args(argv)
 
@@ -56,31 +135,53 @@ def main(argv=None, stream=None, out=None):
     width = shutil.get_terminal_size((100, 24)).columns - 1
 
     done = 0
+    copied = 0
+    rate = Rate()
+    started = time.monotonic()
+    rate.add(started, 0)
     last_drawn = 0.0
     label = ""
+
     for line in stream:
-        path = line.rstrip("\n")
+        size, path = parse(line)
-        # rsync reports directories too, with a trailing slash. They are not
+        # rsync reports directories too, with a trailing slash and an inode
-        # files and counting them would put the percentage past a hundred.
+        # size. Counting them puts the percentage past a hundred and the byte
+        # total well over what will actually be transferred.
         if not path or path.endswith("/"):
             continue
         done += 1
+        copied += size
         label = album_of(path) or os.path.basename(path)
 
         now = time.monotonic()
+        rate.add(now, copied)
         if interactive:
             if now - last_drawn >= args.interval:
-                out.write("\r\033[2K" + render(done, args.total, label, width))
+                out.write(
+                    "\r\033[2K"
+                    + render(done, args.total, copied, args.bytes, rate.per_second(),
+                             label, width)
+                )
                 out.flush()
                 last_drawn = now
         elif now - last_drawn >= 30:
-            out.write(render(done, args.total, label, width) + "\n")
+            out.write(
+                render(done, args.total, copied, args.bytes, rate.per_second(), label, width)
+                + "\n"
+            )
             out.flush()
             last_drawn = now
 
+    elapsed = max(1e-9, time.monotonic() - started)
     if interactive:
         out.write("\r\033[2K")
-    out.write(render(done, args.total, label, width).rstrip() + "\n")
+    summary = render(done, args.total, copied, args.bytes, 0, label, width).rstrip()
+    out.write(f"{summary}\n")
+    if copied:
+        out.write(
+            f"copied {human_bytes(copied)} in {human_duration(elapsed)}"
+            f" at {human_bytes(copied / elapsed)}/s\n"
+        )
     out.flush()
     return 0
 

tools/sync-to-ipod.sh

@@ -46,9 +46,10 @@ catches an unmounted device: /media/IPOD/Music then resolves to the host's own
 root filesystem, and this refuses to empty that.
 
 Progress is one line that rewrites itself, showing the album currently going
-across and how far through the transfer is. Working the total out first means a
+across, how far through the transfer is, the rate, and an estimate of what is
-second pass over the tree, which is the price of a percentage that means
+left. Working the totals out first means a second pass over the tree, which is
-something; rsync's own is computed against a file list it is still building.
+the price of figures that mean something; rsync's own percentage is computed
+against a file list it is still building.
 
 Reach the device with the Apple firmware's disk mode: Menu+Select to reboot,
 then immediately Select+Play. Power off afterwards by holding Play.
@@ -175,12 +176,17 @@ fi
 # second pass over the tree but means the transfer can show a real percentage
 # rather than a number that grows as rsync discovers more work.
 printf 'sync-to-ipod: working out what needs copying...\n' >&2
-total=$(rsync "${options[@]}" --dry-run --out-format='%n' "$mirror/" "$destination/" |
+# %l is the file's size, which is what makes an estimate possible. Directories
-    grep -cve '/$' || true)
+# are dropped: rsync reports those too, with an inode size that would inflate
+# the total by several megabytes of nothing.
+counted=$(rsync "${options[@]}" --dry-run --out-format='%l %n' "$mirror/" "$destination/" |
+    awk '!/\/$/ { files++; bytes += $1 } END { print files + 0, bytes + 0 }')
+total=${counted% *}
+total_bytes=${counted#* }
 printf 'sync-to-ipod: %s files to copy\n' "$total" >&2
 
-rsync "${options[@]}" --out-format='%n' "$mirror/" "$destination/" |
+rsync "${options[@]}" --out-format='%l %n' "$mirror/" "$destination/" |
-    python3 "$here/rsync_progress.py" --total "$total"
+    python3 "$here/rsync_progress.py" --total "$total" --bytes "$total_bytes"
 status=${PIPESTATUS[0]}
 [ "$status" -eq 0 ] || die "rsync exited $status"