top(1), ps(1): per-process CPU time accounting wrong?

classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

top(1), ps(1): per-process CPU time accounting wrong?

Timo Buhrmester
On -current amd64 (GENERIC and GENERIC.MP), per-process CPU time accounting seems wrong to me, judging from watching top(1) and ps(1) while compiling stuff.

The system is under load, building an OpenBSD release, but top(1) and ps(1) look like there's not much going on:
Most of the time, top(1) (with idle processes hidden) shows the load and CPU usage, but no processes that are actually consuming the CPU time:
| load averages:  2.97,  2.06,  1.66                     flap.localdomain 23:47:04
| 38 processes: 36 idle, 2 on processor
| CPU0 states: 50.7% user,  0.0% nice, 15.4% system,  0.2% interrupt, 33.7% idle
| CPU1 states: 34.1% user,  0.0% nice,  9.4% system,  0.0% interrupt, 56.5% idle
| Memory: Real: 36M/1127M act/tot Free: 2088M Cache: 643M Swap: 0K/2224M
|
|   PID USERNAME PRI NICE  SIZE   RES STATE     WAIT      TIME    CPU COMMAND


Occasionally the pertinent programs do show up, but with *very* little apparent CPU usage:
| load averages:  2.87,  2.00,  1.63                     flap.localdomain 23:47:19
| 38 processes: 36 idle, 2 on processor
| CPU0 states: 60.0% user,  0.0% nice,  0.0% system,  0.0% interrupt, 40.0% idle
| CPU1 states: 42.3% user,  0.0% nice,  0.0% system,  0.0% interrupt, 57.7% idle
| Memory: Real: 49M/1139M act/tot Free: 2077M Cache: 643M Swap: 0K/2224M
|
|   PID USERNAME PRI NICE  SIZE   RES STATE     WAIT      TIME    CPU COMMAND
| 11425 root      64    0   19M   20M onproc    -         0:00  0.29% cc1
| 14278 root      -6    0 4380K 5172K sleep     piperd    0:00  0.10% as
|  7894 root      18    0 2268K 4388K sleep     pause     0:01  0.05% make
| 19935 root      10    0  528K 1492K sleep     wait      0:00  0.05% cc



ps aux seems to get it wrong, too:
| # ps aux
| USER       PID %CPU %MEM   VSZ   RSS TT  STAT  STARTED       TIME COMMAND
| [...]
| root     19561  0.0  0.0   836   904 p0  Is    11:03PM    0:00.18 -ksh (ksh)
| root     11801  0.0  0.1   764  1700 p0  I+    11:40PM    0:00.01 make release
| root      7894  0.1  0.1  2296  4444 p0  S+    11:44PM    0:00.65 make
| root     22634  0.0  0.0   628   696 p0  S+    11:47PM    0:00.00 /bin/sh -ec cc [...]
| root      2566  0.8  0.5 18672 18556 p0  R+    11:47PM    0:00.37 /usr/lib/gcc-lib/amd64-unknown-openbsd5.8/4.2.1/cc1 [...]
| root     30930  0.0  0.0   524  1484 p0  S+    11:47PM    0:00.00 cc [...]
| root     16823  0.0  0.2  4384  5176 p0  S+    11:47PM    0:00.01 as -Qy -o trees.o -
| [...]


ps axl does show at least some `short term' usage:
| # ps axl
|   UID   PID  PPID CPU PRI  NI   VSZ   RSS WCHAN   STAT  TT       TIME COMMAND
| [...]
|     0 19561 14740   0  18   0   836   904 pause   Is    p0    0:00.18 -ksh (ksh)
|     0 11801 19561  27  18   0   764  1700 pause   I+    p0    0:00.01 make release
|     0  7894 11801  36  18   0  2340  4520 pause   S+    p0    0:00.89 make
|     0   621 21260  36  10   0   528  1476 wait    S+    p0    0:00.00 cc [...]
|     0 21260  7894  36  18   0   624   688 pause   S+    p0    0:00.00 /bin/sh -ec cc  [...]
|     0  9291   621  36  64   0 11944 12180 -       R+    p0    0:00.07 /usr/lib/gcc-lib/amd64-unknown-openbsd5.8/4.2.1/cc1 [...]
|     0  5156   621  36  -6   0  4388  5140 piperd  S+    p0    0:00.01 as -Qy -o uhci_pci.o -
| [...]


Any idea as for what's happening here?  Or is this as-expected an I'm misinterpreting the values?


Cheers,
Timo Buhrmester


PS: Attached the output of dmesg(8) just in case it matters
# dmesg
OpenBSD 5.8-current (GENERIC.MP) #0: Sat Sep  5 23:00:31 CEST 2015
    [hidden email]:/usr/src/sys/arch/amd64/compile/GENERIC.MP
real mem = 3472392192 (3311MB)
avail mem = 3363315712 (3207MB)
mpath0 at root
scsibus0 at mpath0: 256 targets
mainbus0 at root
bios0 at mainbus0
acpi0 at bios0: rev 2
acpi0: sleep states S0 S3 S4 S5
acpi0: tables DSDT FACP APIC MCFG OEMX ECDT DBGP BOOT OEMB HPET SSDT
acpi0: wakeup devices SBAZ(S4) P0PC(S4) OHC0(S4) OHC1(S4) EHC0(S4) OHC2(S4) OHC3(S4) EHC1(S4) OHC4(S4) PCE2(S4) PCE5(S4) GLAN(S4) PCE6(S4) PCE7(S4) PWRB(S4) SLPB(S4)
acpitimer0 at acpi0: 3579545 Hz, 32 bits
acpimadt0 at acpi0 addr 0xfee00000: PC-AT compat
cpu0 at mainbus0: apid 0 (boot processor)
cpu0: AMD Athlon(tm) II Dual-Core M300, 2001.03 MHz
cpu0: FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,MMX,FXSR,SSE,SSE2,HTT,SSE3,MWAIT,CX16,POPCNT,NXE,MMXX,FFXSR,PAGE1GB,LONG,3DNOW2,3DNOW,LAHF,CMPLEG,SVM,EAPICSP,AMCR8,ABM,SSE4A,3DNOWP,OSVW,IBS,SKINIT,ITSC
cpu0: 64KB 64b/line 2-way I-cache, 64KB 64b/line 2-way D-cache, 512KB 64b/line 16-way L2 cache
cpu0: ITLB 32 4KB entries fully associative, 16 4MB entries fully associative
cpu0: DTLB 48 4KB entries fully associative, 48 4MB entries fully associative
cpu0: AMD erratum 721 detected and fixed
cpu0: smt 0, core 0, package 0
mtrr: Pentium Pro MTRR support, 8 var ranges, 88 fixed ranges
cpu0: apic clock running at 200MHz
cpu0: mwait min=64, max=64, IBE
cpu1 at mainbus0: apid 1 (application processor)
cpu1: AMD Athlon(tm) II Dual-Core M300, 2000.06 MHz
cpu1: FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,MMX,FXSR,SSE,SSE2,HTT,SSE3,MWAIT,CX16,POPCNT,NXE,MMXX,FFXSR,PAGE1GB,LONG,3DNOW2,3DNOW,LAHF,CMPLEG,SVM,EAPICSP,AMCR8,ABM,SSE4A,3DNOWP,OSVW,IBS,SKINIT,ITSC
cpu1: 64KB 64b/line 2-way I-cache, 64KB 64b/line 2-way D-cache, 512KB 64b/line 16-way L2 cache
cpu1: ITLB 32 4KB entries fully associative, 16 4MB entries fully associative
cpu1: DTLB 48 4KB entries fully associative, 48 4MB entries fully associative
cpu1: AMD erratum 721 detected and fixed
cpu1: smt 0, core 1, package 0
ioapic0 at mainbus0: apid 2 pa 0xfec00000, version 21, 24 pins
acpimcfg0 at acpi0 addr 0xe0000000, bus 0-255
acpiec0 at acpi0
acpihpet0 at acpi0: 14318180 Hz
acpiprt0 at acpi0: bus 0 (PCI0)
acpiprt1 at acpi0: bus 1 (P0P1)
acpiprt2 at acpi0: bus 4 (P0PC)
acpiprt3 at acpi0: bus -1 (PCE2)
acpiprt4 at acpi0: bus 2 (PCE5)
acpiprt5 at acpi0: bus 3 (PCE6)
acpicpu0 at acpi0: C1(@1 halt!), PSS
acpicpu1 at acpi0: C1(@1 halt!), PSS
acpitz0 at acpi0: critical temperature is 105 degC
acpiasus at acpi0 not configured
acpiac0 at acpi0: AC unit online
acpibat0 at acpi0: BAT0 not present
acpibtn0 at acpi0: PWRB
acpibtn1 at acpi0: SLPB
acpibtn2 at acpi0: LID_
cpu0: 2001 MHz: speeds: 2000 1400 800 MHz
pci0 at mainbus0 bus 0
pchb0 at pci0 dev 0 function 0 "AMD RS880 Host" rev 0x00
ppb0 at pci0 dev 1 function 0 "AMD RS780 PCIE" rev 0x00
pci1 at ppb0 bus 1
radeondrm0 at pci1 dev 5 function 0 "ATI Mobility Radeon HD 4200" rev 0x00
drm0 at radeondrm0
radeondrm0: apic 2 int 18
azalia0 at pci1 dev 5 function 1 "ATI Radeon HD 4200 HD Audio" rev 0x00: msi
azalia0: no supported codecs
ppb1 at pci0 dev 5 function 0 "AMD RS780 PCIE" rev 0x00: msi
pci2 at ppb1 bus 2
ale0 at pci2 dev 0 function 0 "Attansic Technology L1E" rev 0xb0: AR8121, msi, address 00:00:47:ed:43:c5
atphy0 at ale0 phy 0: F1 10/100/1000 PHY, rev. 9
ppb2 at pci0 dev 6 function 0 "AMD RS780 PCIE" rev 0x00: msi
pci3 at ppb2 bus 3
athn0 at pci3 dev 0 function 0 "Atheros AR9285" rev 0x01: apic 2 int 18
athn0: AR9285 rev 2 (1T1R), ROM rev 13, address 00:25:d3:fa:22:ac
ahci0 at pci0 dev 17 function 0 "ATI SBx00 SATA" rev 0x00: apic 2 int 22, AHCI 1.1
ahci0: port 0: 3.0Gb/s
ahci0: port 1: 1.5Gb/s
scsibus1 at ahci0: 32 targets
sd0 at scsibus1 targ 0 lun 0: <ATA, ST9320325AS, 0002> SCSI3 0/direct fixed naa.5000c5001e84e800
sd0: 305245MB, 512 bytes/sector, 625142448 sectors
cd0 at scsibus1 targ 1 lun 0: <TSSTcorp, CDDVDW TS-L633C, AS01> ATAPI 5/cdrom removable
ohci0 at pci0 dev 18 function 0 "ATI SB700 USB" rev 0x00: apic 2 int 16, version 1.0, legacy support
ohci1 at pci0 dev 18 function 1 "ATI SB700 USB" rev 0x00: apic 2 int 16, version 1.0, legacy support
ehci0 at pci0 dev 18 function 2 "ATI SB700 USB2" rev 0x00: apic 2 int 17
usb0 at ehci0: USB revision 2.0
uhub0 at usb0 "ATI EHCI root hub" rev 2.00/1.00 addr 1
ohci2 at pci0 dev 19 function 0 "ATI SB700 USB" rev 0x00: apic 2 int 18, version 1.0, legacy support
ehci1 at pci0 dev 19 function 2 "ATI SB700 USB2" rev 0x00: apic 2 int 19
usb1 at ehci1: USB revision 2.0
uhub1 at usb1 "ATI EHCI root hub" rev 2.00/1.00 addr 1
piixpm0 at pci0 dev 20 function 0 "ATI SBx00 SMBus" rev 0x3c: SMI
iic0 at piixpm0
spdmem0 at iic0 addr 0x50: 2GB DDR2 SDRAM non-parity PC2-6400CL6 SO-DIMM
spdmem1 at iic0 addr 0x51: 2GB DDR2 SDRAM non-parity PC2-6400CL6 SO-DIMM
azalia1 at pci0 dev 20 function 2 "ATI SBx00 HD Audio" rev 0x00: apic 2 int 16
azalia1: codecs: VIA/0x0397
audio0 at azalia1
pcib0 at pci0 dev 20 function 3 "ATI SB700 ISA" rev 0x00
ppb3 at pci0 dev 20 function 4 "ATI SB600 PCI" rev 0x00
pci4 at ppb3 bus 4
pchb1 at pci0 dev 24 function 0 "AMD AMD64 10h HyperTransport" rev 0x00
pchb2 at pci0 dev 24 function 1 "AMD AMD64 10h Address Map" rev 0x00
pchb3 at pci0 dev 24 function 2 "AMD AMD64 10h DRAM Cfg" rev 0x00
km0 at pci0 dev 24 function 3 "AMD AMD64 10h Misc Cfg" rev 0x00
pchb4 at pci0 dev 24 function 4 "AMD AMD64 10h Link Cfg" rev 0x00
usb2 at ohci0: USB revision 1.0
uhub2 at usb2 "ATI OHCI root hub" rev 1.00/1.00 addr 1
usb3 at ohci1: USB revision 1.0
uhub3 at usb3 "ATI OHCI root hub" rev 1.00/1.00 addr 1
usb4 at ohci2: USB revision 1.0
uhub4 at usb4 "ATI OHCI root hub" rev 1.00/1.00 addr 1
isa0 at pcib0
isadma0 at isa0
pckbc0 at isa0 port 0x60/5 irq 1 irq 12
pckbd0 at pckbc0 (kbd slot)
wskbd0 at pckbd0: console keyboard
pms0 at pckbc0 (aux slot)
wsmouse0 at pms0 mux 0
pms0: Elantech Touchpad, version 2, firmware 0x40101
pcppi0 at isa0 port 0x61
spkr0 at pcppi0
uvideo0 at uhub1 port 2 configuration 1 interface 0 "Chicony Electronics Co., Ltd. CNF7129" rev 2.00/15.15 addr 2
video0 at uvideo0
vscsi0 at root
scsibus2 at vscsi0: 256 targets
softraid0 at root
scsibus3 at softraid0: 256 targets
root on sd0a (77e6e8f2c5ca7d21.a) swap on sd0b dump on sd0b
radeondrm0: 1366x768
wsdisplay0 at radeondrm0 mux 1: console (std, vt100 emulation), using wskbd0
wsdisplay0: screen 1-5 added (std, vt100 emulation)

Reply | Threaded
Open this post in threaded view
|

Re: top(1), ps(1): per-process CPU time accounting wrong?

Michael McConville-2
Timo Buhrmester wrote:

> On -current amd64 (GENERIC and GENERIC.MP), per-process CPU time
> accounting seems wrong to me, judging from watching top(1) and ps(1)
> while compiling stuff.
>
> The system is under load, building an OpenBSD release, but top(1) and
> ps(1) look like there's not much going on: Most of the time, top(1)
> (with idle processes hidden) shows the load and CPU usage, but no
> processes that are actually consuming the CPU time:
> | load averages:  2.97,  2.06,  1.66                     flap.localdomain 23:47:04
> | 38 processes: 36 idle, 2 on processor
> | CPU0 states: 50.7% user,  0.0% nice, 15.4% system,  0.2% interrupt, 33.7% idle
> | CPU1 states: 34.1% user,  0.0% nice,  9.4% system,  0.0% interrupt, 56.5% idle
> | Memory: Real: 36M/1127M act/tot Free: 2088M Cache: 643M Swap: 0K/2224M
> |
> |   PID USERNAME PRI NICE  SIZE   RES STATE     WAIT      TIME    CPU COMMAND

There's just over one core being consumed here. If there's one hungry
single-threaded process, its load can appear split between multiple
cores because it gets context switched a bunch of times in each sampling
interval.

Reply | Threaded
Open this post in threaded view
|

Re: top(1), ps(1): per-process CPU time accounting wrong?

Michael McConville-2
In reply to this post by Timo Buhrmester
Timo Buhrmester wrote:

> On -current amd64 (GENERIC and GENERIC.MP), per-process CPU time
> accounting seems wrong to me, judging from watching top(1) and ps(1)
> while compiling stuff.
>
> [...]
>
> Occasionally the pertinent programs do show up, but with *very* little apparent CPU usage:
> | load averages:  2.87,  2.00,  1.63                     flap.localdomain 23:47:19
> | 38 processes: 36 idle, 2 on processor
> | CPU0 states: 60.0% user,  0.0% nice,  0.0% system,  0.0% interrupt, 40.0% idle
> | CPU1 states: 42.3% user,  0.0% nice,  0.0% system,  0.0% interrupt, 57.7% idle
> | Memory: Real: 49M/1139M act/tot Free: 2077M Cache: 643M Swap: 0K/2224M
> |
> |   PID USERNAME PRI NICE  SIZE   RES STATE     WAIT      TIME    CPU COMMAND
> | 11425 root      64    0   19M   20M onproc    -         0:00  0.29% cc1
> | 14278 root      -6    0 4380K 5172K sleep     piperd    0:00  0.10% as
> |  7894 root      18    0 2268K 4388K sleep     pause     0:01  0.05% make
> | 19935 root      10    0  528K 1492K sleep     wait      0:00  0.05% cc

When building software, you usually have a lot of compiler processes
coming and going. The CPU utilization stats (in the header) are more
averaged than the process list stats. So, when building you're likely to
see a lot of CPU utilization in the per-CPU stats but no offending
process in the list.

Reply | Threaded
Open this post in threaded view
|

Re: top(1), ps(1): per-process CPU time accounting wrong?

Timo Buhrmester
On Sun, Sep 06, 2015 at 06:34:39PM -0400, Michael McConville wrote:
> When building software, you usually have a lot of compiler processes
> coming and going. The CPU utilization stats (in the header) are more
> averaged than the process list stats. So, when building you're likely to
> see a lot of CPU utilization in the per-CPU stats but no offending
> process in the list.

Hm, I guess that would explain the low apparent CPU usage *if* processes are shown in top(1)'s list, but most of the time, the list (of non-idle processes) was empty.  That still strikes me as odd, because regardless of averaging, there's definitely a few processes running or runnable at any given time, while compiling.
Or does top(1) do a second pass to verify a process is still alive, before printing it (but after getting the statistics in the first place)?

Thanks for your reply.

Reply | Threaded
Open this post in threaded view
|

Re: top(1), ps(1): per-process CPU time accounting wrong?

Ted Unangst-6
Timo Buhrmester wrote:
> On Sun, Sep 06, 2015 at 06:34:39PM -0400, Michael McConville wrote:
> > When building software, you usually have a lot of compiler processes
> > coming and going. The CPU utilization stats (in the header) are more
> > averaged than the process list stats. So, when building you're likely to
> > see a lot of CPU utilization in the per-CPU stats but no offending
> > process in the list.
>
> Hm, I guess that would explain the low apparent CPU usage *if* processes are shown in top(1)'s list, but most of the time, the list (of non-idle processes) was empty.  That still strikes me as odd, because regardless of averaging, there's definitely a few processes running or runnable at any given time, while compiling.
> Or does top(1) do a second pass to verify a process is still alive, before printing it (but after getting the statistics in the first place)?

The minutiae of process cpu% calculations are in sys/kern/sched_bsd.c