[Bug 4052] New: sftp-server: input queue growth makes uploads quadratic in the backlog

[bugzilla-daemon at mindrot.org]

https://bugzilla.mindrot.org/show_bug.cgi?id=4052

            Bug ID: 4052
           Summary: sftp-server: input queue growth makes uploads
                    quadratic in the backlog
           Product: Portable OpenSSH
           Version: 10.6p2
          Hardware: Other
                OS: FreeBSD
            Status: NEW
          Severity: enhancement
          Priority: P5
         Component: sftp-server
          Assignee: unassigned-bugs at mindrot.org
          Reporter: Alexander-openssh at Leidinger.net

Created attachment 4021
  --> https://bugzilla.mindrot.org/attachment.cgi?id=4021&action=edit
Possible solution

Summary
-------

When a client does not limit its unanswered SSH2_FXP_WRITE requests and
writes 4 KiB per request, sftp-server reads faster than it processes. 
Its
input queue grows, every growth copies the whole queue, and the server
spends its time in that copy.  Time grows with the square of the
backlog:
32 MiB took 24 s and 64 MiB took 96 s, against 0.7 s and 1.3 s for the
same
upload with at most 1 MiB of requests unanswered.  32 KiB requests are
not
affected.

Seen in 10.4p1 on FreeBSD and 9.6p1 on Linux.  The loop below is
unchanged
in openssh-portable master (sftp-server.c 1.156).

How it happens
--------------

sftp_server_main() reads up to sizeof(buf), 16 KiB, into iqueue, then
calls
process() once.  process() handles one request.  With 4 KiB writes a
read
brings in nearly four requests and one leaves, so iqueue grows by about
12 KiB per pass for as long as the client keeps sending.

sshbuf_put() reaches sshbuf_allocate(), which grows the buffer by what
is
needed, rounded up to SSHBUF_SIZE_INC (256).  So almost every read goes
through recallocarray(), and recallocarray() allocates anew, copies the
old
contents and clears them.  Each pass costs O(queue size).

Counted with an LD_PRELOAD wrapper on FreeBSD, for one upload of 4 KiB
writes with no cap:

        size    recallocarray calls     sum of old sizes
        16 MiB  1,035                   8.1 GiB
        32 MiB  2,066                   32.5 GiB

With at most 1 MiB unanswered, 32 MiB took 237 calls and 303 MiB. 
memmove()
from sshbuf_maybe_pack() was negligible in all of them.

The queue stops growing only at SSHBUF_SIZE_MAX, 128 MiB, through the
backpressure added for bug 1286.  That bug reported this same loop,
when the
result was the server exiting.  The backpressure stops the server
dying, not
the queue growing.

The backlog feeds itself: the longer the queue, the slower the server,
so
the more arrives while it works.  A client only slightly slower than
the
server may never start one, so the same upload can take 1 s or 30 s,
and
writing to /dev/null is slowed as much as writing to a file once a
backlog
exists.

Who triggers it
---------------

The protocol allows it: draft-ietf-secsh-filexfer-02 says "There is no
limit
on the number of outstanding (non-acknowledged) requests".  OpenSSH's
own
sftp client limits its requests and is not affected.  PuTTY's pscp is:
xfer_upload_ready() looks only at the send buffer, and PSCP_SEND_BLOCK
is
4096.  Uploading a 4.7 GB file with pscp 0.83 over a LAN ran at 0.4 to
1 MB/s, while pscp -scp moved 1 GiB at 60 MB/s over the same
connection.

The cost is one CPU and the queue's memory, to an authenticated user.

Measurements
------------

sftp-queue-repro.py (attached) talks to sftp-server over a socketpair,
with
no network and no ssh.  4 KiB writes, wall time in seconds, as "1 MiB
cap /
no cap":

        FreeBSD 16.0-CURRENT, OpenSSH 10.4p1, ZFS

        size    stock           patched
        8 MiB   0.18 / 0.83     0.15 / 0.21
        16 MiB  0.29 / 5.97     0.24 / 0.49
        32 MiB  0.72 / 24.06    0.51 / 0.80
        64 MiB  1.27 / 95.89    0.98 / 1.39

        Ubuntu 24.04 on WSL2, OpenSSH 9.6p1, ext4, stock only

        8 MiB   0.22 / 1.25
        16 MiB  0.17 / 4.70
        32 MiB  0.22 to 0.51 / 4.77 to 10.67, four runs
        64 MiB  0.36 to 0.74 / 44 to 102, and 4.79 in one run of four

On FreeBSD 256 MiB with no cap took 728 s stock and 7.6 s patched, and
the
server's time was nearly all user time.  On Linux it divides between
user
and system time.

A possible change
-----------------

Attached, against 10.4p1: after a read, keep calling process() while
more
than sizeof(buf) is queued and less than SFTP_MAX_MSG_LENGTH of output
waits.  Below that the loop behaves as it does today.

The output bound matters.  Without it a burst of SSH2_FXP_READ requests
grows oqueue the same way: 256 MiB of 32 KiB reads, with replies held
back
for 2 s, took 5 to 7 s instead of 3.

Measured with the change on FreeBSD:

        reads, 32 KiB, 1 MiB window, 15 runs    median 0.52 s, stock
0.54 s
        the read burst above                    3.1 to 3.5 s, stock 3.0
to 3.4 s
        regress sftp, sftp-batch, sftp-cmds,
        sftp-badcmds, sftp-glob, sftp-perm      pass, as stock

The regress cases use the sftp client, which caps its requests, so they
do
not reach the new loop.  The reproducer does, as does the larger
harness
behind the read figures, which compared the data of every write and
read.
pscp itself did not run against the change; its request pattern was
sent
through plink instead, to the patched server: 32 MiB in 1.7 to 2.4 s,
stock
21 to 22 s.

Growing the buffers geometrically in sshbuf_allocate() would address
the
copies at another level.  That was not tried.

-- 
You are receiving this mail because:
You are watching the assignee of the bug.