misc/126230: weird process cpu usage stats and weird load average

[Kris Kennaway]

The following reply was made to PR misc/126230; it has been noted by GNATS.

From: Kris Kennaway <kris at FreeBSD.org>
To: Jakub Jasinski <jakub.jasinski at utoronto.ca>
Cc: freebsd-gnats-submit at FreeBSD.org
Subject: Re: misc/126230: weird process cpu usage stats and weird load average
Date: Tue, 05 Aug 2008 20:08:36 +0200

 Jakub Jasinski wrote:
 > uhci2: <Intel 631XESB/632XESB/3100 USB controller USB-3> port
 > 0x1040-0x105f irq 18 at device 29.2 on pci0 uhci2: [GIANT-LOCKED]
 > uhci2: [ITHREAD]
 > usb2: <Intel 631XESB/632XESB/3100 USB controller USB-3> on uhci2
 > usb2: USB revision 1.0
 > uhub2: <Intel UHCI root hub, class 9/0, rev 1.00/1.00, addr 1> on usb2
 > uhub2: 2 ports with 2 removable, self powered
 > ukbd0: <No brand KVM A1, class 0/0, rev 1.10/0.00, addr 2> on uhub2
 > kbd2 at ukbd0
 > ums0: <No brand KVM A1, class 0/0, rev 1.10/0.00, addr 2> on uhub2
 > ums0: 5 buttons and Z dir.
 > 
 > Ok, so the keyboard and mouse are there.  I detached them, killed
 > moused, rerun rsync and I got the same weird top output:
 
 Are the devices still attached (i.e. did they detach)?  What if you 
 compile a kernel with no USB support at all (obviously you won't be able 
 to log in with a USB keyboard, but you can still log in remotely).
 
 Kris
 
 
 > 
 > FreeBSD 7.0-RELEASE (CUSTOM) #2: Mon Aug  4 12:44:23 EDT 2008
 > last pid:  1258;  load averages:  0.00,  0.00,  0.00   up 0+01:09:53
 > 13:20:17 last pid:  1266;  load averages:  1.98,  0.55,  0.20   up 0
 > +01:11:33  13:21:57 58 processes:  1 running, 57 sleeping
 > CPU states:  0.9% user,  0.0% nice, 36.0% system,  3.5% interrupt,
 > 59.6% idle Mem: 142M Active, 59M Inact, 278M Wired, 48K Cache, 214M
 > Buf, 7433M Free Swap: 8192M Total, 8192M Free
 > 
 >   PID USERNAME    THR PRI NICE   SIZE    RES STATE  C   TIME   WCPU
 > COMMAND
 > 662 root 2   4    0 14112K  2504K select 3   0:15 12.65% apcupsd
 > 1266 root 1  54    0 17196K 12112K select 0 0:03 10.50% rsync
 > 756 root 1   4    0  9940K  1260K select 2 0:08  6.40% authdaemon
 > 1259 root 1  48    0  7656K  2328K CPU1   1   0:02  5.27% top
 > 981 root 1   4    0 30108K  5292K select 2   0:06  4.59% sendmail
 > 1265 root 1   4    0 17196K 11824K select 3   0:02  4.59% rsync
 > 790 root 1   4    0 9940K  1260K select 1   0:06  4.49% authdaemon
 > 774 root 1 4    0  3604K  1220K select 2   0:06  4.49% couriertcp
 > 791 root 1   4    0  9940K  1260K select 0   0:06  4.49% authdaemon
 > 
 > etc.
 > 
 > ...and why are apcupsd (connected via serial port),  syslogd,
 > couriertcpd, sendmail, etc. working a the _exact_ same time for the
 > same duration at around the same WPCU%?
 > 
 > Just for comparison, this is a summary of top on FreeBSD 6.2 (32 bit) on
 > another non-deployed box running pretty much the same software (courier
 > imap, clamav, spamassassin, etc.) after rsync is activated:
 > 43.48% for one rsync process
 > 1.96% for another
 > 0.00% for everything else.
 > 
 > On Tue, 5 Aug 2008 16:50:04 GMT
 > Kris Kennaway <kris at FreeBSD.org> wrote:
 > 
 >>  Jakub Jasinski wrote:
 >>  > I recompiled the kernel with the ULE scheduler and the only
 >>  > difference now is that every 'working' process has higher WCPU
 >>  > _after_ rsync is activated. Before rsync is activated all process
 >>  > have 0% WCPU.
 >>  > 
 >>  > BTW, thanks for the help.
 >>  > 
 >>  > [root at mail2 ~]# vmstat -i
 >>  > interrupt                          total       rate
 >>  > irq1: atkbd0                          78          0
 >>  > irq4: sio0                          2023          5
 >>  > irq14: ata0                           58          0
 >>  > irq16: uhci0 ehci0                     1          0
 >>  > irq18: ciss0 uhci2                  2618          6
 >>  > irq22: uhci4                          19          0
 >>  > cpu0: timer                       751994       1994
 >>  > irq257: bce1                        2271          6
 >>  > cpu1: timer                       744491       1974
 >>  > cpu2: timer                       744494       1974
 >>  > cpu3: timer                       744513       1974
 >>  > Total                            2992560       7937
 >>  
 >>  Your system is sharing an interrupt between the ciss and one of the
 >> USB controllers.  This means that every time there is an interrupt
 >> from disk I/O the USB drivers will also wake up to process it.  This
 >> could be causing things like moused and cups to run.  What devices
 >> are attached to uhci2?
 >>  
 > 
 >