From owner-svn-src-head@freebsd.org Sat May 12 07:35:27 2018 Return-Path: Delivered-To: svn-src-head@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 EE082FC98B0; Sat, 12 May 2018 07:35:26 +0000 (UTC) (envelope-from pho@holm.cc) Received: from relay01.pair.com (relay01.pair.com [209.68.5.15]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 8BF1A77062; Sat, 12 May 2018 07:35:26 +0000 (UTC) (envelope-from pho@holm.cc) Received: from x2.osted.lan (87-58-223-204-dynamic.dk.customer.tdc.net [87.58.223.204]) by relay01.pair.com (Postfix) with ESMTP id 7AC42D00AC9; Sat, 12 May 2018 03:35:19 -0400 (EDT) Received: from x2.osted.lan (localhost [127.0.0.1]) by x2.osted.lan (8.14.9/8.14.9) with ESMTP id w4C7ZGdA068614 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=NO); Sat, 12 May 2018 09:35:16 +0200 (CEST) (envelope-from pho@x2.osted.lan) Received: (from pho@localhost) by x2.osted.lan (8.14.9/8.14.9/Submit) id w4C7ZGIE068613; Sat, 12 May 2018 09:35:16 +0200 (CEST) (envelope-from pho) Date: Sat, 12 May 2018 09:35:16 +0200 From: Peter Holm To: Matt Macy Cc: src-committers@freebsd.org, svn-src-all@freebsd.org, svn-src-head@freebsd.org Subject: Re: svn commit: r333509 - in head/sys: dev/hwpmc kern sys Message-ID: <20180512073516.GA68235@x2.osted.lan> References: <201805120126.w4C1QYMu097965@repo.freebsd.org> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <201805120126.w4C1QYMu097965@repo.freebsd.org> User-Agent: Mutt/1.5.23 (2014-03-12) X-BeenThere: svn-src-head@freebsd.org X-Mailman-Version: 2.1.25 Precedence: list List-Id: SVN commit messages for the src tree for head/-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sat, 12 May 2018 07:35:27 -0000 On Sat, May 12, 2018 at 01:26:34AM +0000, Matt Macy wrote: > Author: mmacy > Date: Sat May 12 01:26:34 2018 > New Revision: 333509 > URL: https://svnweb.freebsd.org/changeset/base/333509 > > Log: > hwpmc(9): Make pmclog buffer pcpu and update constants > > On non-trivial SMP systems the contention on the pmc_owner mutex leads > to a substantial number of samples captured being from the pmc process > itself. This change a) makes buffers larger to avoid contention on the > global list b) makes the working sample buffer per cpu. > > Run pmcstat in the background (default event rate of 64k): > pmcstat -S UNHALTED_CORE_CYCLES -O /dev/null sleep 600 & > > Before: > make -j96 buildkernel -s >&/dev/null 3336.68s user 24684.10s system 7442% cpu 6:16.50 total > > After: > make -j96 buildkernel -s >&/dev/null 2697.82s user 1347.35s system 6058% cpu 1:06.77 total > > For more realistic overhead measurement set the sample rate for ~2khz > on a 2.1Ghz processor: > pmcstat -n 1050000 -S UNHALTED_CORE_CYCLES -O /dev/null sleep 6000 & > > Collecting 10 samples of `make -j96 buildkernel` from each: > > x before > + after > > real time: > N Min Max Median Avg Stddev > x 10 76.4 127.62 84.845 88.577 15.100031 > + 10 59.71 60.79 60.135 60.179 0.29957192 > Difference at 95.0% confidence > -28.398 +/- 10.0344 > -32.0602% +/- 7.69825% > (Student's t, pooled s = 10.6794) > > system time: > N Min Max Median Avg Stddev > x 10 2277.96 6948.53 2949.47 3341.492 1385.2677 > + 10 1038.7 1081.06 1070.555 1064.017 15.85404 > Difference at 95.0% confidence > -2277.47 +/- 920.425 > -68.1574% +/- 8.77623% > (Student's t, pooled s = 979.596) > > x no pmc > + pmc running > real time: > > HEAD: > N Min Max Median Avg Stddev > x 10 58.38 59.15 58.86 58.847 0.22504567 > + 10 76.4 127.62 84.845 88.577 15.100031 > Difference at 95.0% confidence > 29.73 +/- 10.0335 > 50.5208% +/- 17.0525% > (Student's t, pooled s = 10.6785) > > patched: > N Min Max Median Avg Stddev > x 10 58.38 59.15 58.86 58.847 0.22504567 > + 10 59.71 60.79 60.135 60.179 0.29957192 > Difference at 95.0% confidence > 1.332 +/- 0.248939 > 2.2635% +/- 0.426506% > (Student's t, pooled s = 0.264942) > > system time: > > HEAD: > N Min Max Median Avg Stddev > x 10 1010.15 1073.31 1025.465 1031.524 18.135705 > + 10 2277.96 6948.53 2949.47 3341.492 1385.2677 > Difference at 95.0% confidence > 2309.97 +/- 920.443 > 223.937% +/- 89.3039% > (Student's t, pooled s = 979.616) > > patched: > N Min Max Median Avg Stddev > x 10 1010.15 1073.31 1025.465 1031.524 18.135705 > + 10 1038.7 1081.06 1070.555 1064.017 15.85404 > Difference at 95.0% confidence > 32.493 +/- 16.0042 > 3.15% +/- 1.5794% > (Student's t, pooled s = 17.0331) > > Reviewed by: jeff@ > Approved by: sbruno@ > Differential Revision: https://reviews.freebsd.org/D15155 > > Modified: > head/sys/dev/hwpmc/hwpmc_amd.c > head/sys/dev/hwpmc/hwpmc_core.c > head/sys/dev/hwpmc/hwpmc_e500.c > head/sys/dev/hwpmc/hwpmc_intel.c > head/sys/dev/hwpmc/hwpmc_logging.c > head/sys/dev/hwpmc/hwpmc_mod.c > head/sys/dev/hwpmc/hwpmc_mpc7xxx.c > head/sys/dev/hwpmc/hwpmc_piv.c > head/sys/dev/hwpmc/hwpmc_ppc970.c > head/sys/dev/hwpmc/hwpmc_ppro.c > head/sys/dev/hwpmc/hwpmc_soft.c > head/sys/kern/kern_pmc.c > head/sys/sys/pmc.h > head/sys/sys/pmckern.h > > Modified: head/sys/dev/hwpmc/hwpmc_amd.c > ============================================================================== > --- head/sys/dev/hwpmc/hwpmc_amd.c Fri May 11 22:16:23 2018 (r333508) Got this during boot: ada1: Serial Number 15150F3BC143 ada1: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 8192bytes) ada1: Command Queueing enabled ada1: 976762MB (2000409264 512 byte sectors) Fatal trap 12: page fault while in kernel mode cpuid = 103; apic id = 7b fault virtual address = 0x38 fault code = supervisor write data, page not present instruction pointer = 0x20:0xffffffff826d0a3e stack pointer = 0x28:0xffffffff827c62c0 frame pointer = 0x28:0xffffffff827c62f0 code segment = base 0x0, limit 0xfffff, type 0x1b = DPL 0, pres 1, long 1, def32 0, gran 1 processor eflags = interrupt enabled, resume, IOPL = 0 current process = 0 (swapper) [ thread pid 0 tid 100000 ] Stopped at pmclog_initialize+0x15e: addl $0x1,ll+0x17(%rax) db> bt Tracing pid 0 tid 100000 td 0xffffffff81ff1160 pmclog_initialize() at pmclog_initialize+0x15e/frame 0xffffffff827c62f0 load() at load+0x1097/frame 0xffffffff827c6350 kern_syscall_module_handler() at kern_syscall_module_handler+0x2a1/frame 0xffffffff827c63a0 module_register_init() at module_register_init+0xc0/frame 0xffffffff827c63d0 mi_startup() at mi_startup+0x118/frame 0xffffffff827c63f0 btext() at btext+0x2c db> x/s version version: FreeBSD 12.0-CURRENT #2 r333519: Sat May 12 09:14:17 CEST 2018\012 pho@flix1a.netperf.freebsd.org:/usr/obj/usr/src/amd64.amd64/sys/PHO\012 db> show registers cs 0x20 ds 0x3b ll+0x1a es 0x3b ll+0x1a fs 0x13 gs 0x28 ll+0x7 ss 0x28 ll+0x7 rax 0 rcx 0xffffffffffffffff rdx 0xffffffff826e0a21 ucp_events+0x2d81 rbx 0x34 ll+0x13 rsp 0xffffffff827c62c0 rbp 0xffffffff827c62f0 rsi 0xffffffff81b16340 lock_class_mtx_spin rdi 0x34 ll+0x13 r8 0x20000 r9 0x32 ll+0x11 r10 0xfffff8183fd1f380 r11 0 r12 0x67 ll+0x46 r13 0x67 ll+0x46 r14 0x1 r15 0x68 ll+0x47 rip 0xffffffff826d0a3e pmclog_initialize+0x15e rflags 0x10247 _binary_t5fw_cfg_uwire_txt_size+0xac98 pmclog_initialize+0x15e: addl $0x1,ll+0x17(%rax) db> - Peter