From owner-freebsd-performance@FreeBSD.ORG Mon Jan 2 22:19:37 2012 Return-Path: Delivered-To: freebsd-performance@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id C0B40106567C for ; Mon, 2 Jan 2012 22:19:37 +0000 (UTC) (envelope-from dieterbsd@engineer.com) Received: from mailout-us.gmx.com (mailout-us.gmx.com [74.208.5.67]) by mx1.freebsd.org (Postfix) with SMTP id 8D8458FC21 for ; Mon, 2 Jan 2012 22:19:37 +0000 (UTC) Received: (qmail 15218 invoked by uid 0); 2 Jan 2012 22:19:31 -0000 Received: from 67.206.187.152 by rms-us010.v300.gmx.net with HTTP Content-Type: text/plain; charset="utf-8" Date: Mon, 02 Jan 2012 17:19:27 -0500 From: "Dieter BSD" Message-ID: <20120102221929.218250@gmx.com> MIME-Version: 1.0 To: freebsd-performance@freebsd.org X-Authenticated: #74169980 X-Flags: 0001 X-Mailer: GMX.com Web Mailer x-registered: 0 Content-Transfer-Encoding: 8bit X-GMX-UID: JkhwbyU03zOlNR3dAHAhHg9+IGRvb0CT Subject: cmp(1) has a bottleneck, but where? X-BeenThere: freebsd-performance@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Performance/tuning List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 02 Jan 2012 22:19:37 -0000 Task: cp(1) a several-GB file from one drive to another, then run cmp(1) to verify.  Cp runs as expected, but cmp runs slower than expected.  Neither the disks nor the cpu is maxed out.  Local drives, no network involved.  Machine is otherwise idle. FreeBSD 8.2 amd64 4 GiB main memory FFS soft updates SATA 2TB drives Doesn't matter which drives/controllers, the example below uses 3132 (siis) with 3726 PM, and JMB363 (ahci), both on PCIe x1 cards Since this ML seems obscessed with the scheduler: kern.sched.preemption: 1 kern.sched.idlespinthresh: 4 kern.sched.idlespins: 10000 kern.sched.static_boost: 160 kern.sched.preempt_thresh: 64 kern.sched.interact: 30 kern.sched.slice: 13 kern.sched.name: ULE cp: extended device statistics                                             device    r/s    w/s     kr/s     kw/s wait  svc_t  %b  controller      ada3  610.9    0.0  77968.6      0.0    1    1.0  64  siisch0_pm3 NCQ ada12    0.5  607.4      8.0  77736.7    6    4.4  60  ahcich1     NCQ    6 users    Load  0.54  0.46  0.33                  Jan  2 13:16 Mem:KB    REAL            VIRTUAL                       VN PAGER   SWAP PAGER        Tot   Share      Tot    Share    Free           in   out     in   out Act  276728   42264  3615536   100420  117572  count All  335744   43452 1077460k   135596          pages Proc:                                                            Interrupts  r   p   d   s   w   Csw  Trp  Sys  Int  Sof  Flt        cow    3921 total  1         153      8076  191 1277 1920 1341             zfod        atkbd0 1                                                          ozfod       uart0 irq4 32.7%Sys   3.4%Intr  0.7%User  0.0%Nice 63.1%Idle        %ozfod    66 psm0 irq12 |    |    |    |    |    |    |    |    |    |    |       daefr       cx23880mpe ================++                                        prcfr   619 siis0 puc0                                       120 dtbuf          totfr  1235 cx23880mpe Namei     Name-cache   Dir-cache    135408 desvn          react     1 fwohci1 bg   Calls    hits   %    hits   %     51442 numvn        2 pdwak       ohci0+ 21      25      25 100                 33843 frevn    36283 pdpgs       ehci0+ 22                                                          intrn       pcm0 nfe0 Disks  ada3 ada12                                  322804 wire   2000 cpu0: time KB/t    128   127                                 1441764 act tps     619   620                                 1670132 inact MB/s  77.07 77.01                                  107684 cache %busy    65    63                                    9888 free                                                   380800 buf cmp: extended device statistics                                             device    r/s    w/s     kr/s     kw/s wait  svc_t  %b  controller      ada3  705.2    0.0  45042.3      0.0    0    0.6  40  siisch0_pm3 NCQ ada12  706.2    0.0  45042.3      0.0    0    0.5  33  ahcich1     NCQ    6 users    Load  0.00  0.07  0.17                  Jan  2 13:32 Mem:KB    REAL            VIRTUAL                       VN PAGER   SWAP PAGER        Tot   Share      Tot    Share    Free           in   out     in   out Act 1970756   45312 37243128   100420  145224  count  1399             All 2029948   46696 1111086k   135596          pages 22348 Proc:                                                            Interrupts  r   p   d   s   w   Csw  Trp  Sys  Int  Sof  Flt        cow    4187 total  2   1     153       10k 7161 1312 2187 1524 7024        zfod        atkbd0 1                                                          ozfod       uart0 irq4 10.6%Sys   2.5%Intr 19.3%User  0.0%Nice 67.5%Idle        %ozfod    88 psm0 irq12 |    |    |    |    |    |    |    |    |    |    |       daefr       cx23880mpe =====++>>>>>>>>>                                          prcfr   700 siis0 puc0                                        11 dtbuf     1321 totfr  1399 cx23880mpe Namei     Name-cache   Dir-cache    135408 desvn          react       fwohci1 bg   Calls    hits   %    hits   %     51442 numvn          pdwak       ohci0+ 21                                     33639 frevn          pdpgs       ehci0+ 22                                                          intrn       pcm0 nfe0 Disks  ada3 ada12                                  312052 wire   2000 cpu0: time KB/t  63.88 63.88                                 1764068 act tps     700   700                                 1330864 inact MB/s  43.65 43.65                                  134912 cache %busy    38    33                                   10312 free                                                   380800 buf The disks can read much faster: cat file > /dev/null: extended device statistics                                             device    r/s    w/s     kr/s     kw/s wait  svc_t  %b  controller      ada3  781.2    0.0  99663.3      0.0    0    1.1  83  siisch0_pm3 NCQ ada12  712.3    0.0  90642.3      0.0    1    1.1  78  ahcich1     NCQ    6 users    Load  0.16  0.14  0.20                  Jan  2 13:49 Mem:KB    REAL            VIRTUAL                       VN PAGER   SWAP PAGER        Tot   Share      Tot    Share    Free           in   out     in   out Act  276604   41864  3630548   100420  191588  count All  335608   43064 1077474k   135596          pages Proc:                                                            Interrupts  r   p   d   s   w   Csw  Trp  Sys  Int  Sof  Flt        cow    4270 total  3         153       12k 1599  95k 2271 1582             zfod        atkbd0 1                                                          ozfod       uart0 irq4 37.2%Sys   3.7%Intr  0.9%User  0.0%Nice 58.2%Idle        %ozfod    82 psm0 irq12 |    |    |    |    |    |    |    |    |    |    |       daefr       cx23880mpe ===================+>                                     prcfr   757 siis0 puc0                                         4 dtbuf          totfr  1431 cx23880mpe Namei     Name-cache   Dir-cache    135408 desvn          react       fwohci1 bg   Calls    hits   %    hits   %     51441 numvn        2 pdwak       ohci0+ 21      25      25 100                 33826 frevn    49879 pdpgs       ehci0+ 22                                                          intrn       pcm0 nfe0 Disks  ada3 ada12                                  305216 wire   2000 cpu0: time KB/t    128   128                                 1442164 act tps     757   716                                 1613304 inact MB/s  94.31 89.20                                  181700 cache %busy    80    79                                    9888 free                                                   380800 buf So reading from the disks isn't the bottleneck, and systat reports that the cpu is 67% idle so the cpu isn't the bottleneck, I'm wondering what *is* cmp's bottleneck?  What else is there that wouldn't show up as one or the other?