svn commit: r333509 - in head/sys: dev/hwpmc kern sys
Peter Holm
peter at holm.cc
Sat May 12 07:35:27 UTC 2018
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 at 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
More information about the svn-src-all
mailing list