Date: Sat, 22 Jun 2013 17:10:01 GMT From: Adrian Chadd <adrian@freebsd.org> To: freebsd-bugs@FreeBSD.org Subject: Re: kern/179827: [hwpmc] process-mode counters aren't correctly read on multi-core machines Message-ID: <201306221710.r5MHA1aq048745@freefall.freebsd.org>
next in thread | raw e-mail | index | archive | help
The following reply was made to PR kern/179827; it has been noted by GNATS.
From: Adrian Chadd <adrian@freebsd.org>
To: hiren panchasara <hiren@freebsd.org>
Cc: bug-followup@freebsd.org
Subject: Re: kern/179827: [hwpmc] process-mode counters aren't correctly
read on multi-core machines
Date: Sat, 22 Jun 2013 10:03:46 -0700
You can't do sleep() ; that yields the CPU.
Replace it with a busy loop that constantly does some math.
Adrian
On 22 June 2013 02:35, hiren panchasara <hiren@freebsd.org> wrote:
> This is what I am seeing on head:
>
> -bash-4.2$ uname -a
> FreeBSD head.box.some.com 10.0-CURRENT FreeBSD 10.0-CURRENT #0
> r251604: Tue Jun 11 19:08:35 UTC 2013
> hirenp@head.box.some.com:/home/hirenp/head/sys/amd64/compile/GENERIC
> amd64
> -bash-4.2$ sysctl hw.ncpu
> hw.ncpu: 24
> -bash-4.2$
>
> -bash-4.2$ sysctl -a | grep hwpmc
> kern.features.hwpmc_hooks: 1
> kern.hwpmc.softevents: 16
> kern.hwpmc.callchaindepth: 8
> kern.hwpmc.debugflags: csw=swo,swi pmc=ops
> kern.hwpmc.hashsize: 16
> kern.hwpmc.nsamples: 512
> kern.hwpmc.mtxpoolsize: 32
> kern.hwpmc.logbuffersize: 4
> kern.hwpmc.nbuffers: 64
> -bash-4.2$
>
> -bash-4.2$ cat count.c
> #include <stdio.h>
> #include <stdint.h>
> #include <time.h>
>
> int main() {
>
> for (int i=0; i<60; i++) {
> sleep(1);
> }
>
> return 0;
> }
>
>
> -bash-4.2$ pmcstat -p instructions -w 1 ./count
> CSW:SWO:1: cpu=2 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> PMC:OPS:1: start pmc=0xfffffe005d81e800 mode=3 ri=21
> CSW:SWI:1: cpu=16 proc=0xfffffe0047afc970 (2616, pmcstat) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=2 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=16 ri=21 new=0
> CSW:SWO:1: cpu=16 proc=0xfffffe0047afc970 (2616, pmcstat) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=16 ri=21 tmp=6285116
> CSW:SWI:1: cpu=20 proc=0xfffffe0047afc970 (2616, pmcstat) pp=0xfffffe005dbd6c00
> CSW:SWI:1: cpu=20 ri=21 new=6285116
> CSW:SWO:1: cpu=20 proc=0xfffffe0047afc970 (2616, pmcstat) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=20 ri=21 tmp=6245302
> CSW:SWI:1: cpu=1 proc=0xfffffe0047afc970 (2616, pmcstat) pp=0xfffffe005dbd6c00
> CSW:SWI:1: cpu=1 ri=21 new=12530418
> CSW:SWO:1: cpu=1 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=1 ri=21 tmp=11918927
>
> # PMC:OPS:1: rw id=-16579051 flags=0x20
> PMC:OPS:2: rw id=21 -> old 1751141
> CSW:SWO:1: cpu=12 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSWnstructions
> 244493:S45 WO:1: cpu=6 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=1 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWI:1:
> c# p/instructionpu=s
> 1 ri=21 new=24449345
> PMC:OPS:1: rw id=-16579051 flags=0x20
> CSW:SWO:1: cpu=1 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> PMC:OPS:2: rw id=21 -> old 1751141
> C SW:0 SWO:1: cpu=1 ri=21 tmp=97027040
> CSW:SWO:1: cpu=6 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
>
> PMC# p/instruction:Os
> PS:1: rw id=-16579051 flags=0x20
> CSW:SWI:1: cpu=16 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> PMC:OPS:2: rw id=21 -> old 73d9521
> C 9702704SW:0 SWI:1: cpu=16 ri=21 new=121476385
> CSW:SWO:1: cpu=6 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWO:1: cpu=16 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=16 ri=21 tmp=121961432
>
> PM# p/instructionC:Os
> PS:1: rw id=-16579051 flags=0x20
> PMC:OPS:2: rw id=21 -> old e8290f9
> 12196143CS2 W:SWO:1: cpu=6 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=16 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWI:1: cpu=16 ri=21 new=243437817
> CSW:SWO:1: cpu=16 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=16 ri=21 tmp=56320362
>
> PM# p/instructionC:Os
> PS:1: rw id=-16579051 flags=0x20
> PMC:OPS:2: rw id=21 -> old 11ddf263
> 5632036CSW2 :SWO:1: cpu=6 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=16 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWI:1: cpu=16 ri=21 new=299758179
> CSW:SWO:1: cpu=16 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=16 ri=21 tmp=56408687
>
> PM# p/instructionC:Os
> PS:1: rw id=-16579051 flags=0x20
> PMC:OPS:2: rw id=21 -> old 153aacd2
> 5640868CSW7 :SWO:1: cpu=6 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=16 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWI:1: cpu=16 ri=21 new=356166866
> CSW:SWO:1: cpu=16 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=16 ri=21 tmp=56364300
>
> PM# p/instructionC:Os
> PS:1: rw id=-16579051 flags=0x20
> PMC:OPS:2: rw id=21 -> old 1896b9de
> 5636430CS0 W:SWO:1: cpu=6 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=16 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWI:1: cpu=16 ri=21 new=412531166
> CSW:SWO:1: cpu=16 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=16 ri=21 tmp=56239777
>
> PM# p/instructionC:Os
> PS:1: rw id=-16579051 flags=0x20
> PMC:OPS:2: rw id=21 -> old 1bf0e07f
> 5623977CS7 W:SWO:1: cpu=6 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=16 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWI:1: cpu=16 ri=21 new=468770943
> CSW:SWO:1: cpu=16 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=16 ri=21
> tm# p/instructionp=5s
> 6380282
> PMC:OPS:1: rw id=-16579051 flags=0x20
> PMC:OPS:2: rw id=21 -> old 1f4d2bf9
> 5638028CSW2 :SWO:1: cpu=6 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=16 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWI:1: cpu=16 ri=21
> ne# p/instructionw=s
> 525151225
> PMC:OPS:1: rw id=-16579051 flags=0x20
> CSW:SWO:1: cpu=16 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> PMC:OPS:2: rw id=21 -> old 1f4d2bf9
> C SW:0 SWO:1: cpu=16 ri=21 tmp=96934506
> CSW:SWO:1: cpu=6 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=3
> pr# p/instructionoc=s
> 0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> PMC:OPS:1: rw id=-16579051 flags=0x20
> CSW:SWI:1: cpu=3 ri=21 new=622085731
> PMC:OPS:2: rw id=21 -> old 25144663
> C 9693450SW6 :SWO:1: cpu=3 proc=0xfffffe0047afc970 (2616,
> count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=12 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWO:1: cpu=3 ri=21 tmp=105656199
>
> PM# p/instructionC:Os
> PS:1: rw id=-16579051 flags=0x20
> PMC:OPS:2: rw id=21 -> old 2b6075ea
> 10565619CSW9 :SWO:1: cpu=12 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=3 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWI:1: cpu=3 ri=21 new=727741930
> CSW:SWO:1: cpu=3 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=3 ri=21 tmp=56325090
>
> PMC# p/instruction:Os
> PS:1: rw id=-16579051 flags=0x20
> PMC:OPS:2: rw id=21 -> old 2ebbe9cc
> 5632509CSW0 :SWO:1: cpu=12 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=3 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWI:1: cpu=3 ri=21 new=784067020
> CSW:SWO:1: cpu=3 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=3 ri=21 tmp=56354857
>
> PMC# p/instruction:Os
> PS:1: rw id=-16579051 flags=0x20
> PMC:OPS:2: rw id=21 -> old 3217d1f5
> 5635485CSW7 :SWO:1: cpu=12 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=3 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWI:1: cpu=3 ri=21 new=840421877
> CSW:SWO:1: cpu=3 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=3 ri=21 tmp=56379009
>
> PMC# p/instruction:OPs
> S:1: rw id=-16579051 flags=0x20
> PMC:OPS:2: rw id=21 -> old 35741876
> 5637900CSW9 :SWO:1: cpu=12 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=3 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWI:1: cpu=3 ri=21 new=896800886
> CSW:SWO:1: cpu=3 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=3 ri=21 tmp=56376678
>
> PMC# p/instruction:Os
> PS:1: rw id=-16579051 flags=0x20
> PMC:OPS:2: rw id=21 -> old 38d055dc
> 5637667CSW8 :SWO:1: cpu=12 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=3 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWI:1: cpu=3 ri=21 new=953177564
> CSW:SWO:1: cpu=3 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=3 ri=21 tmp=56363010
>
> PM# p/instructionC:Os
> PS:1: rw id=-16579051 flags=0x20
> PMC:OPS:2: rw id=21 -> old 3c2c5dde
> 5636301CS0 W:SWO:1: cpu=6 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=3 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> C
> SW# p/instruction:SWs
> I:1: cpu=3 ri=21 new=1009540574
> PMC:OPS:1: rw id=-16579051 flags=0x20
> CSW:SWO:1: cpu=3 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=6 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWO:1: cpu=3 ri=21 tmp=96981520
> CSW:SWO:1: cpu=0 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> PMC:OPS:2: rw id=21 -> old 3c2c5dde
> CSW0 :SWO:1: cpu=0 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
>
> PM# p/instructionC:Os
> PS:1: rw id=-16579051 flags=0x20
> CSW:SWI:1: cpu=14 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=0 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=14 ri=21 new=1106522094
> PMC:OPS:2: rw id=21 -> old 41f42fee
> C 9698152SW0 :SWO:1: cpu=14 proc=0xfffffe0047afc970 (2616,
> count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=17 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWO:1: cpu=14 ri=21 tmp=106788274
>
> P# p/instructionMC:s
> OPS:1: rw id=-16579051 flags=0x20
> PMC:OPS:2: rw id=21 -> old 4851a5a0
> 10678827CS4 W:SWO:1: cpu=3 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=10 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWI:1: cpu=10 ri=21 new=1213310368
> CSW:SWO:1: cpu=10 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=10 ri=21 tmp=57088659
>
> P# p/instructionMC:s
> OPS:1: rw id=-16579051 flags=0x20
> PMC:OPS:2: rw id=21 -> old 4bb8c033
> 5708865CSW9 :SWO:1: cpu=3 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=10 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWI:1: cpu=10 ri=21 new=1270399027
> CSW:SWO:1: cpu=10 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=10 ri=21 tmp=57123975
>
> P# p/instructionMCs
> :OPS:1: rw id=-16579051 flags=0x20
> PMC:OPS:2: rw id=21 -> old 4f2064ba
> 5712397CSW5 :SWO:1: cpu=3 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=10 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWI:1: cpu=10 ri=21 new=1327523002
> CSW:SWO:1: cpu=10 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=10 ri=21 tmp=57119065
>
> P# p/instructionMCs
> :OPS:1: rw id=-16579051 flags=0x20
> PMC:OPS:2: rw id=21 -> old 5287f613
> 5711906CSW5 :SWO:1: cpu=3 proc=0xfffffe0047ea6970 (2615, pmcstat) pp=0
> CSW:SWI:1: cpu=10 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWI:1: cpu=10 ri=21 new=1384642067
> CSW:SWO:1: cpu=10 proc=0xfffffe0047afc970 (2616, count) pp=0xfffffe005dbd6c00
> CSW:SWO:1: cpu=10 ri=21 tmp=57119883
>
> <truncated> as it was too long.
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?201306221710.r5MHA1aq048745>