From owner-freebsd-bugs@FreeBSD.ORG  Sat Jun 22 17:10:01 2013
Return-Path: <owner-freebsd-bugs@FreeBSD.ORG>
Delivered-To: freebsd-bugs@smarthost.ysv.freebsd.org
Received: from mx1.freebsd.org (mx1.freebsd.org
 [IPv6:2001:1900:2254:206a::19:1])
 by hub.freebsd.org (Postfix) with ESMTP id 9BBA0917
 for <freebsd-bugs@smarthost.ysv.freebsd.org>;
 Sat, 22 Jun 2013 17:10:01 +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 7D5C31600
 for <freebsd-bugs@smarthost.ysv.freebsd.org>;
 Sat, 22 Jun 2013 17:10:01 +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 r5MHA1Hr048746
 for <freebsd-bugs@freefall.freebsd.org>; Sat, 22 Jun 2013 17:10:01 GMT
 (envelope-from gnats@freefall.freebsd.org)
Received: (from gnats@localhost)
 by freefall.freebsd.org (8.14.7/8.14.7/Submit) id r5MHA1aq048745;
 Sat, 22 Jun 2013 17:10:01 GMT (envelope-from gnats)
Date: Sat, 22 Jun 2013 17:10:01 GMT
Message-Id: <201306221710.r5MHA1aq048745@freefall.freebsd.org>
To: freebsd-bugs@FreeBSD.org
Cc: 
From: Adrian Chadd <adrian@freebsd.org>
Subject: Re: kern/179827: [hwpmc] process-mode counters aren&#39;t correctly
 read on multi-core machines
X-BeenThere: freebsd-bugs@freebsd.org
X-Mailman-Version: 2.1.14
Precedence: list
Reply-To: Adrian Chadd <adrian@freebsd.org>
List-Id: Bug reports <freebsd-bugs.freebsd.org>
List-Unsubscribe: <http://lists.freebsd.org/mailman/options/freebsd-bugs>,
 <mailto:freebsd-bugs-request@freebsd.org?subject=unsubscribe>
List-Archive: <http://lists.freebsd.org/pipermail/freebsd-bugs>
List-Post: <mailto:freebsd-bugs@freebsd.org>
List-Help: <mailto:freebsd-bugs-request@freebsd.org?subject=help>
List-Subscribe: <http://lists.freebsd.org/mailman/listinfo/freebsd-bugs>,
 <mailto:freebsd-bugs-request@freebsd.org?subject=subscribe>
X-List-Received-Date: Sat, 22 Jun 2013 17:10:01 -0000

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&#39;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.