From owner-freebsd-bugs@FreeBSD.ORG Sat Jun 22 09:40:02 2013 Return-Path: Delivered-To: freebsd-bugs@smarthost.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [8.8.178.115]) by hub.freebsd.org (Postfix) with ESMTP id 8EACE845 for ; Sat, 22 Jun 2013 09:40:02 +0000 (UTC) (envelope-from gnats@FreeBSD.org) Received: from freefall.freebsd.org (freefall.freebsd.org [IPv6:2001:1900:2254:206c::16:87]) by mx1.freebsd.org (Postfix) with ESMTP id 718AF1497 for ; Sat, 22 Jun 2013 09:40:02 +0000 (UTC) Received: from freefall.freebsd.org (localhost [127.0.0.1]) by freefall.freebsd.org (8.14.7/8.14.7) with ESMTP id r5M9e2Xm055567 for ; Sat, 22 Jun 2013 09:40:02 GMT (envelope-from gnats@freefall.freebsd.org) Received: (from gnats@localhost) by freefall.freebsd.org (8.14.7/8.14.7/Submit) id r5M9e2X9055566; Sat, 22 Jun 2013 09:40:02 GMT (envelope-from gnats) Date: Sat, 22 Jun 2013 09:40:02 GMT Message-Id: <201306220940.r5M9e2X9055566@freefall.freebsd.org> To: freebsd-bugs@FreeBSD.org Cc: From: hiren panchasara Subject: Re: kern/179827: [hwpmc] process-mode counters aren't correctly read on multi-core machines X-BeenThere: freebsd-bugs@freebsd.org X-Mailman-Version: 2.1.14 Precedence: list Reply-To: hiren panchasara List-Id: Bug reports List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sat, 22 Jun 2013 09:40:02 -0000 The following reply was made to PR kern/179827; it has been noted by GNATS. From: hiren panchasara To: bug-followup@FreeBSD.org, adrian@FreeBSD.org Cc: Subject: Re: kern/179827: [hwpmc] process-mode counters aren't correctly read on multi-core machines Date: Sat, 22 Jun 2013 02:35:55 -0700 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 #include #include 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 as it was too long.