Bug 179827 - [hwpmc] process-mode counters aren't correctly read on multi-core machines
Summary: [hwpmc] process-mode counters aren't correctly read on multi-core machines
Status: Open
Alias: None
Product: Base System
Classification: Unclassified
Component: kern (show other bugs)
Version: Unspecified
Hardware: Any Any
: Normal Affects Only Me
Assignee: freebsd-bugs (Nobody)
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2013-06-22 02:50 UTC by Adrian Chadd
Modified: 2017-12-31 22:27 UTC (History)
0 users

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Adrian Chadd freebsd_committer freebsd_triage 2013-06-22 02:50:00 UTC
When using a process mode counter PMC on a multi-core machine, the pmc_read() -> PMC_OP_PMCRW event is not correctly reading the PMC.

What's going on in hwpmc_mod.c is thus:

* It grabs the current thread CPU;
* It then checks if the PMC is active;
* If it's currently active, it reads the PMC from the current CPU rather than the target CPU;
* .. otherwise it returns the old counter value.

When I enabled pmc debugging: DEBUG in the kernel, then:

# sysctl kern.hwpmc.debugflags="csw=swo,swi pmc=ops"

I'd see this:

* lots of swi, swo (swapin, swapout) of the process, which updates the cached PMC value
* a PMC,OPS event every second whilst it was reading the process mode counter
* .. but the PMC,OPS value would always be the "old" one, rather than the updated one.

The only time the counter value was updated was if the PMC,OPS (ie, the PMC_OP_PMCRW event) occured _during_ the running of the process - ie, the scheduler put the process being counted _and_ the pmcstat process on the same CPU, switched out the process under profiling  (which would switch it out and update the value) and switched in pmcstat to do the read.

This reads like it was really designed for reading counters from an active process - ie, where you'd put pmc_read() at specific points in a programs execution in order to count how long certain events were taking.

It's totally bogus for the SMP case, where your current process being run is on another CPU and doesn't get switched out for long stretches of time, whilst pmcstat wakes up once a second on another CPU to do a counter read.

Fix: 

I'm not sure. There may be multiple problems here:

* One is ensuring the PMC stats are read from the CPU the pmc counter is actively active on, as it may be a different CPU to the thread calling pmc_read() -> PMC_OP_PMCRW;
* Another is checking to see if the PMC is actually active at the present moment on _any_ CPU and if it is, fetch the statistics from said correct CPU.
* I'm not sure what the deal is with running counting mode samples on a multi-core CPU with multiple threads running in the process under count. Ie, if you have 4 threads on 4 separate CPUs running and you're trying to count '-p instructions', then I think the right behaviour is to enable the instructions counter on -all- the CPUs with those threads active. So what should pmc_read() do? Does the kernel-side correctly read all the CPUs with threads active for that particular registered PMC? Or what is actually going on?
How-To-Repeat: * grab a multi-core device;
* Grab some CPU chewing process that doesn't do any kind of blocking - ie, some minute long math problem;
* run pmcstat in counting mode - pmcstat -p instructions -w 1 ./process
* watch the counters look totally bogus.
* See above for the sysctl line to enable pmc debugging and you'll see how bogus the sampling is.
Comment 1 Hiren Panchasara freebsd_committer freebsd_triage 2013-06-22 10:35:55 UTC
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.
Comment 2 Adrian Chadd freebsd_committer freebsd_triage 2013-06-22 18:03:46 UTC
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.
Comment 3 Adrian Chadd freebsd_committer freebsd_triage 2013-06-22 21:23:24 UTC
Right. Do that but with the test running in another window, so you
don't get the message overlap.

THen look at how the results show lots of '0' from pmcstat, and then
correlate that with the one-second "PMC,OPS" sample lines. See how
whenever they're run whilst the process is running (ie, the last event
was SWI) and it hasn't yet been de-scheduled. because it's still
running, the saved counter is never updated with the PMC counter and
subsequent reads (until it does get de-scheduled!) return the same
cached value. Hence, lots of '0's, followed by a big, big counter
value.




adrian
Comment 4 Hiren Panchasara 2013-06-23 02:05:13 UTC
On Sat, Jun 22, 2013 at 1:23 PM, Adrian Chadd <adrian@freebsd.org> wrote:
> Right. Do that but with the test running in another window, so you
> don't get the message overlap.

Here is how it looks:

#  p/instructions
        293898819
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
                0
#  p/instructions
     201677536862

>
> THen look at how the results show lots of '0' from pmcstat, and then
> correlate that with the one-second "PMC,OPS" sample lines. See how
> whenever they're run whilst the process is running (ie, the last event
> was SWI) and it hasn't yet been de-scheduled. because it's still
> running, the saved counter is never updated with the PMC counter and
> subsequent reads (until it does get de-scheduled!) return the same
> cached value. Hence, lots of '0's, followed by a big, big counter
> value.

Precisely how it looks.

Thanks for the explanation.

cheers,
Hiren
Comment 5 Eitan Adler freebsd_committer freebsd_triage 2017-12-31 08:00:12 UTC
For bugs matching the following criteria:

Status: In Progress Changed: (is less than) 2014-06-01

Reset to default assignee and clear in-progress tags.

Mail being skipped