From owner-svn-src-head@freebsd.org Sat May 12 20:22:21 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 E9B23FCF51D; Sat, 12 May 2018 20:22:20 +0000 (UTC) (envelope-from mmacy@freebsd.org) Received: from smtp.freebsd.org (smtp.freebsd.org [96.47.72.83]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client CN "smtp.freebsd.org", Issuer "Let's Encrypt Authority X3" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 936AC7188E; Sat, 12 May 2018 20:22:20 +0000 (UTC) (envelope-from mmacy@freebsd.org) Received: from mail-it0-f48.google.com (mail-it0-f48.google.com [209.85.214.48]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "Google Internet Authority G2" (verified OK)) (Authenticated sender: mmacy) by smtp.freebsd.org (Postfix) with ESMTPSA id 55FE0278AB; Sat, 12 May 2018 20:22:20 +0000 (UTC) (envelope-from mmacy@freebsd.org) Received: by mail-it0-f48.google.com with SMTP id c3-v6so6272434itj.4; Sat, 12 May 2018 13:22:20 -0700 (PDT) X-Gm-Message-State: ALKqPwfoo1lFjPIlcpTJ7GzyrsaadiHEAOXf3lCIK7x22HXXDuq8WD/T Fe2UP9OPMqXSUEtknLpmfB/qAnxGfaCdVIpFydo= X-Google-Smtp-Source: AB8JxZpDB6mWLlsZIDY9ie/964TvJQ/XrMqsBcLEzg9wL/6oKjrNt/4JqYuxQ7Fr/APgEB1F8MmIIWe3UUpvz+DeLfE= X-Received: by 2002:a24:4455:: with SMTP id o82-v6mr3385515ita.4.1526156539705; Sat, 12 May 2018 13:22:19 -0700 (PDT) MIME-Version: 1.0 References: <201805120126.w4C1QYMu097965@repo.freebsd.org> <20180512073516.GA68235@x2.osted.lan> In-Reply-To: <20180512073516.GA68235@x2.osted.lan> From: Matthew Macy Date: Sat, 12 May 2018 13:22:09 -0700 X-Gmail-Original-Message-ID: Message-ID: Subject: Re: svn commit: r333509 - in head/sys: dev/hwpmc kern sys To: Peter Holm Cc: src-committers@freebsd.org, svn-src-all@freebsd.org, svn-src-head@freebsd.org Content-Type: text/plain; charset="UTF-8" X-Content-Filtered-By: Mailman/MimeDel 2.1.25 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 20:22:21 -0000 Fixed in 333575. On Sat, May 12, 2018 at 00:35 Peter Holm wrote: > 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 >