From owner-freebsd-arm@freebsd.org Mon Aug 20 14:59:43 2018 Return-Path: Delivered-To: freebsd-arm@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 697241070BBB for ; Mon, 20 Aug 2018 14:59:43 +0000 (UTC) (envelope-from wlosh@bsdimp.com) Received: from mail-it0-x235.google.com (mail-it0-x235.google.com [IPv6:2607:f8b0:4001:c0b::235]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "Google Internet Authority G3" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id EDFBC71069 for ; Mon, 20 Aug 2018 14:59:42 +0000 (UTC) (envelope-from wlosh@bsdimp.com) Received: by mail-it0-x235.google.com with SMTP id 139-v6so20811386itf.0 for ; Mon, 20 Aug 2018 07:59:42 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=bsdimp-com.20150623.gappssmtp.com; s=20150623; h=mime-version:sender:in-reply-to:references:from:date:message-id :subject:to:cc; bh=CCZxh7KvEyiPdwpyBSRbby2e5pkrZ18AuaUvbdUQ0m8=; b=kOcLa6kCeXej53E3VlI5UlMi9lpKV9jJwl9mJVaGQXmGrLV3ZcWC1tX8sSj7JNIrjR YaQnqts5NBs1NUzTtyGzuQUlOzOEAeTpAXtFNGWqQRuBG8lkPBzIntbbBPAhvP6Cs9SK q+4DB0p0SBfqjQF6h40PBpqJLqWOcFqCyNWPEtnMjAwevk8KcYMKnrRp5G+myKPSm1Yd +cXeEMcwReh+cP2pkIfUxPUZEwddxSKiJD1tB8ZryZ83uIuZU/SxuZlEnAgeS88kYWg+ JRrTLJxYFQoK6HwN6GDaZdCwQCRQjTrhi9bgvt/DfQ0h4HWyACbOzn47ha73XEsDtP0e 1WJg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:sender:in-reply-to:references:from :date:message-id:subject:to:cc; bh=CCZxh7KvEyiPdwpyBSRbby2e5pkrZ18AuaUvbdUQ0m8=; b=FColv5grG1cx7cefkR6yLCuI274s4er2ZYa6L3lfKaABkMllMDAJuGl1BNmocccZuc c1II+xcbQNF3xbQvuITGJVvYRWkJ7lpdpfXp2Km0RZqo0AEIpO1SrnYeCzz5mpJAyNmL NJ+Q9aYEhDGcV08DkqJEis14kBUKCUj8llvGa+p/s2CNkk5AvjmHDHLjWjxIOvJDG/ps weIVaO1lD81vzxmYvKnnQ7UYAoNAWj8xQP6t27diAzCruQ7qkm2qPfxmzKs4q4WEGKbB kLaoptrx9hK2Wc9m85uftxzbJRJN21PoV1U9AAd0csrO2b21pkBxu12qlCvN5g5hSrJ/ 59Xw== X-Gm-Message-State: AOUpUlHfdGbg2uSEGTKYDf5Xo3HwFWoIxqjd/r0Cni67eyYkob+Vpi2k Zv4MZK7X+EOzubmhbTx4K7RYx8uBprK2DRch/dTJSw== X-Google-Smtp-Source: AA+uWPw5JEEj5gpX4/aiOZ0sQ0DQQWHgXuRHIRQi9TWSAh+5QN61MezOopHhnXLGpZAA4MX5t4j2tMFYv5gzw5b2Xj4= X-Received: by 2002:a24:83c6:: with SMTP id d189-v6mr13320728ite.75.1534777182157; Mon, 20 Aug 2018 07:59:42 -0700 (PDT) MIME-Version: 1.0 Sender: wlosh@bsdimp.com Received: by 2002:a4f:2806:0:0:0:0:0 with HTTP; Mon, 20 Aug 2018 07:59:41 -0700 (PDT) X-Originating-IP: [50.227.106.226] In-Reply-To: References: <20180808153800.GF26133@www.zefox.net> <20180808204841.GA19379@raichu> <2DC1A479-92A0-48E6-9245-3FF5CFD89DEF@yahoo.com> <20180809033735.GJ30738@phouka1.phouka.net> <20180809175802.GA32974@www.zefox.net> <20180812173248.GA81324@phouka1.phouka.net> <20180812224021.GA46372@www.zefox.net> <20180813021226.GA46750@www.zefox.net> <0D8B9A29-DD95-4FA3-8F7D-4B85A3BB54D7@yahoo.com> <20180815221728.GA59074@www.zefox.net> <9EA5D75D-A03F-4B25-B65E-03E93DE30130@yahoo.com> From: Warner Losh Date: Mon, 20 Aug 2018 08:59:41 -0600 X-Google-Sender-Auth: toV0oagydjYiolBmeuvEDRzNupo Message-ID: Subject: Re: RPI3 swap experiments ["was killed: out of swap space" with: "v_free_count: 5439, v_inactive_count: 1"] To: Mark Millard Cc: bob prohaska , freebsd-arm , Mark Johnston Content-Type: text/plain; charset="UTF-8" X-Content-Filtered-By: Mailman/MimeDel 2.1.27 X-BeenThere: freebsd-arm@freebsd.org X-Mailman-Version: 2.1.27 Precedence: list List-Id: "Porting FreeBSD to ARM processors." List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 20 Aug 2018 14:59:43 -0000 On Mon, Aug 20, 2018 at 8:00 AM, Mark Millard via freebsd-arm < freebsd-arm@freebsd.org> wrote: > There is a way to explore Mark Johnston's swap information > reports (from his patches for such). > > Taking a Pine64+ 2GB as an example (4 cores with 1 > HW-thread per core, 2 GiBytes of RAM, USB device for > root file system and swap partition): > > In one login: > # nice -20 gstat -pd > > In another login: > # stress -d 2 -m 4 --vm-keep --vm-bytes 536870912 > > That "4" and "536870912" total to the 2 GiBytes so > swapping is induced for the context in question. > (Scale --vm-bytes appropriately to context.) > > [stress is from sysutils/stress .] > > gstat tends to show things such as: > > dT: 1.006s w: 1.000s > L(q) ops/s r/s kBps ms/r w/s kBps ms/w d/s kBps > ms/d %busy Name > 0 0 0 0 0.0 0 0 0.0 0 0 > 0.0 0.0| mmcsd0 > 56 312 0 0 0.0 312 19985 142.6 0 0 > 0.0 99.6| da0 > > where the ms/w and kBps are fairly stable but the Length > of the queue length is widely variable. For the above it > makes the likes of 56 writes queued * 142.6 ms/write (mean) > [as an estimate] a rather large total time for the last > of the queued writes to complete. (If I understand how > to interpret the above.) > No. 142.6ms/write is the average of the time that the operations that completed during the polling interval took to complete. There's no estimating here. So, at 6 or 7 per second for the operation to complete, coupled with a parallel factor of 1 (typical for low end junk flash), we wind up with 56 operations in the queue taking 8-10s to complete. > It appears to me that, compared to a observed capacity of > roughly around 20 MiBytes/sec for writes, large amounts of > bytes are being queued up to be written in a short time, > for which it just takes a while for the backlog to be > finished. > Yes. That matches my expectation as well. In other devices, I've found that I needed to rate-limit things to more like 50-75% of the max value to keep variance in performance low. It's the whole reason I wrote the CAM I/O scheduler. > The following is from multiple such runs, several manually > stopped but some killed because of sustained low free > memory. I had left vm.pageout_oom_seq=12 in place for this, > making the kills easier to get than the 120 figure would. It > does not take very long generally for some sort of message to > show up. > > > > waited 9s for async swap write > waited 9s for swap buffer > waited 9s for async swap write > waited 9s for async swap write > waited 9s for async swap write > v_free_count: 1357, v_inactive_count: 1 > Aug 20 06:04:27 pine64 kernel: pid 1010 (stress), uid 0, was killed: out > of swap space > waited 5s for async swap write > waited 5s for swap buffer > waited 5s for async swap write > waited 5s for async swap write > waited 5s for async swap write > waited 13s for async swap write > waited 12s for swap buffer > waited 13s for async swap write > waited 12s for async swap write > waited 12s for async swap write > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 161177, size: 131072 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 164766, size: 65536 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 164064, size: 12288 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 161630, size: 131072 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 161177, size: 131072 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 164766, size: 65536 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 161630, size: 131072 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 164064, size: 12288 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 161177, size: 131072 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 164766, size: 65536 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 161630, size: 131072 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 164064, size: 12288 > waited 65s for async swap write > waited 65s for swap buffer > waited 65s for async swap write > waited 65s for async swap write > waited 65s for async swap write > v_free_count: 955, v_inactive_count: 1 > Aug 20 06:11:49 pine64 kernel: pid 1047 (stress), uid 0, was killed: out > of swap space > waited 5s for async swap write > waited 5s for swap buffer > waited 5s for async swap write > waited 5s for async swap write > waited 5s for async swap write > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 314021, size: 12288 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 314084, size: 32768 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 314856, size: 32768 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 314638, size: 131072 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 312518, size: 4096 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 312416, size: 16384 > waited 39s for async swap write > waited 39s for swap buffer > waited 39s for async swap write > waited 39s for async swap write > waited 39s for async swap write > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 314802, size: 24576 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 314934, size: 40960 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 315617, size: 32768 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 312484, size: 4096 > swap_pager: indefinite wait buffer: bufobj: 0, blkno: 328616, size: 131072 > waited 31s for async swap write > waited 31s for swap buffer > waited 31s for async swap write > waited 31s for async swap write > waited 31s for async swap write > waited 5s for async swap write > waited 5s for swap buffer > waited 5s for async swap write > waited 5s for async swap write > waited 5s for async swap write These numbers are consistent with the theory that the swap device becomes overwhelmed, spiking latency and causing crappy down-stream effects. You can use the I/O scheduler to limit the write rates at the low end. You might also be able to schedule a lower write queue depth at the top end as well, but I've not seen good ways to do that. Warner