Re: High INTERRUPT rate on CPU 0

From: Attilio Rao <attilio_at_freebsd.org>
Date: Tue, 17 Nov 2009 22:21:50 +0100
2009/11/17 neutral neutral <ptr.neutral_at_gmail.com>:
> Hello,
>
> Yesterday I get a fresh install of FreeBSD 8.0 RC3 Current. However just
> some hours after the installation the machine began very slow/laggy.
>
> $ top -P CC
> (...)
> last pid:  1460;  load averages:  0.01,  0.08,
> 0.07                                             up 0+00:11:00  08:28:59
> 100 processes: 1 running, 99 sleeping
> CPU 0:  0.0% user,  0.0% nice,  0.0% system, 81.9% interrupt, 18.1% idle
> CPU 1:  1.1% user,  0.0% nice,  3.2% system,  0.0% interrupt, 95.7% idle
> Mem: 160M Active, 141M Inact, 143M Wired, 1512K Cache, 112M Buf, 2525M Free
> Swap: 4096M Total, 4096M Free
>
> $ top -S
>
> last pid:  1457;  load averages:  0.08,  0.13,
> 0.08                                             up 0+00:07:59  08:25:58
> 177 processes: 4 running, 157 sleeping, 16 waiting
> CPU:  0.8% user,  0.0% nice,  1.2% system, 37.8% interrupt, 60.2% idle
> Mem: 158M Active, 127M Inact, 149M Wired, 1484K Cache, 112M Buf, 2534M Free
> Swap: 4096M Total, 4096M Free
>
>  PID USERNAME    THR PRI NICE   SIZE    RES STATE   C   TIME   WCPU COMMAND
>   11 root          2 171 ki31     0K    16K RUN     0   8:38 112.16% idle
>   12 root         17 -64    -     0K   136K WAIT    0   5:39 77.29% intr
>  1405 hender       11  44    0   116M 86380K ucond   1   0:11  1.86%
> firefox-bin
>  1259 root          1  44    0   322M   316M select  1   0:10  0.00% Xorg
>    3 root          1  -8    -     0K     8K -       1   0:02  0.00% g_up
>    4 root          1  -8    -     0K     8K -       1   0:01  0.00% g_down
>  1440 hender        1  44    0   136M 14468K select  1   0:01  0.00%
> npviewer.bin
>   13 root          1  44    -     0K     8K -       1   0:01  0.00% yarrow
>  1432 hender        2  44    0 37584K 19268K piperd  1   0:01  0.00%
> gnome-terminal
>  1345 hender        1  44    0 19712K 14204K select  1   0:01  0.00%
> metacity
>  1348 hender        1  44    0 49048K 25112K select  1   0:01  0.00%
> nautilus
>  1390 root          1  48    4  3300K  1084K biord   1   0:01  0.00%
> fsck_ufs
>  1347 hender        1  44    0 34164K 20608K select  1   0:00  0.00%
> gnome-panel
>  1370 hender        1  44    0 33148K 18024K select  1   0:00  0.00%
> wnck-applet
>  1331 hender        1  44    0  8588K  5552K select  1   0:00  0.00%
> gconfd-2
>  1337 hender        2  44    0 94612K 15776K piperd  1   0:00  0.00%
> gnome-settings-daem
>  1201 haldaemon     1  44    0  7236K  4920K select  1   0:00  0.00% hald
>  1380 hender        1  44    0 32300K 22552K select  1   0:00  0.00%
> clock-applet
>  1342 hender        1  44    0  6308K  3236K select  1   0:00  0.00%
> gam_server
>  575 root          1  44    0  3448K  1136K select  1   0:00  0.00% moused
>   17 root          1  44    -     0K     8K syncer  1   0:00  0.00% syncer
>  1352 hender        1  44    0 26804K 18844K select  1   0:00  0.00%
> gnome-power-manager
>   19 root          1  44    -     0K     8K biord   1   0:00  0.00%
> softdepflush
>  1308 hender        2  52    0 21768K 11932K piperd  1   0:00  0.00%
> gnome-session
>  958 messagebus    1  44    0  3500K  2176K select  1   0:00  0.00%
> dbus-daemon
>  1350 hender        2  46    0 19240K  6896K select  1   0:00  0.00%
> bonobo-activation-s
>  1247 root          1  44    0  3804K  1700K ATA re  0   0:00  0.00%
> hald-addon-storage
>   14 root         32 -64    -     0K   256K -       0   0:00  0.00% usb
>  1381 hender        1  44    0 22044K 14568K select  1   0:00  0.00%
> notification-area-a
>  1354 hender        1  44    0 87032K 14120K select  1   0:00  0.00%
> gnome-volume-contro
>    0 root          9 -68    0     0K    64K -       1   0:00  0.00% kernel
>  1318 hender        1  44    0  3500K  2056K select  1   0:00  0.00%
> dbus-daemon
>   16 root          1  44    -     0K     8K psleep  1   0:00  0.00%
> bufdaemon
>  1328 hender        1  44    0 19320K 12456K select  1   0:00  0.00%
> seahorse-agent
>  1087 avahi         1  44    0  5092K  2536K select  1   0:00  0.00%
> avahi-daemon
>  1258 root          1  45    0  7588K  4312K select  1   0:00  0.00%
> gdm-simple-slave
>  1372 hender        2  44    0  7764K  4116K piperd  0   0:00  0.00%
> gvfs-hal-volume-mon
>  1368 hender        1  44    0  6688K  4000K select  1   0:00  0.00%
> gvfsd-trash
>  1204 root         17  44    0 14532K  4668K waitvt  1   0:00  0.00%
> console-kit-daemon
>  1205 root          1  44    0  5928K  2752K select  1   0:00  0.00%
> hald-runner
>  1297 root          1  44    0  7696K  3804K select  1   0:00  0.00%
> gdm-session-worker
>  1073 root          1  44    0  7504K  3688K select  1   0:00  0.00%
> gdm-binary
>    2 root          1  -8    -     0K     8K GEOM t  1   0:00  0.00% g_event
>  1333 hender        1  44    0  6468K  3268K select  1   0:00  0.00% gvfsd
>  1374 hender        1  44    0  7304K  3944K select  1   0:00  0.00%
> gvfs-gphoto2-volume
>  779 root          1  44    0  3344K  1312K select  1
>
> $ systat -vmstat
>
>    2 users    Load  0.15  0.22  0.10                  Nov 17 18:16
>
> Mem:KB    REAL            VIRTUAL                       VN PAGER   SWAP
> PAGER
>        Tot   Share      Tot    Share    Free           in   out     in
> out
> Act  182280   25972   743712    36292 2679304  count
> All  232564   40544  3238872    56908          pages
> Proc:                                                            Interrupts
>  r   p   d   s   w   Csw  Trp  Sys  Int  Sof  Flt        cow   93416 total
>             94      180k  197 1509  89k  205   19     12 zfod        atkbd0
> 1
>                                                          ozfod       psm0
> irq12
>  0.2%Sys  40.3%Intr  0.5%User  0.0%Nice 58.9%Idle        %ozfod
> fwohci0+ 1
> |    |    |    |    |    |    |    |    |    |    |       daefr 89400 uhci2
> ehci
> ++++++++++++++++++++>                                     prcfr    20 uhci3
> ehci
>                                       919 dtbuf      292 totfr  1998 cpu0:
> time
> Namei     Name-cache   Dir-cache    100000 desvn          react       mskc0
> 256
>   Calls    hits   %    hits   %      8091 numvn          pdwak  1998 cpu1:
> time
>    1221    1221 100                  1082 frevn          pdpgs
>                                                          intrn
> Disks   ad4   ad8                                  146440 wire
> KB/t   0.00 15.96                                  135892 act
> tps       0   141                                   79928 inact
> MB/s   0.00  2.21                                    1988 cache
> %busy     0   100                                 2677300 free
>
>    2 users    Load  0.12  0.21  0.10                  Nov 17 18:16
>
> Mem:KB    REAL            VIRTUAL                       VN PAGER   SWAP
> PAGER
>        Tot   Share      Tot    Share    Free           in   out     in
> out
> Act  183688   25972   746272    36292 2680552  count
> All  233988   40544  3241432    56908          pages
> Proc:                                                            Interrupts
>  r   p   d   s   w   Csw  Trp  Sys  Int  Sof  Flt        cow   92797 total
>             94      179k 2877 4010  88k  202 2292   2291 zfod        atkbd0
> 1
>                                                          ozfod       psm0
> irq12
>  1.7%Sys  40.5%Intr  3.7%User  0.0%Nice 54.2%Idle        %ozfod
> fwohci0+ 1
> |    |    |    |    |    |    |    |    |    |    |       daefr 88736 uhci2
> ehci
> =++++++++++++++++++++>>                                   prcfr    63 uhci3
> ehci
>                                        72 dtbuf     3268 totfr  1999 cpu0:
> time
> Namei     Name-cache   Dir-cache    100000 desvn          react       mskc0
> 256
>   Calls    hits   %    hits   %      8091 numvn          pdwak  1999 cpu1:
> time
>     793     793 100                  1083 frevn          pdpgs
>                                                          intrn
> Disks   ad4   ad8                                  139872 wire
> KB/t   0.00 15.98                                  137304 act
> tps       0   142                                   83820 inact
> MB/s   0.00  2.22                                    1592 cache
> %busy     0    99                                 2678960 free
>
> $ vmstat -i
> interrupt                          total       rate
> irq1: atkbd0                         201          0
> irq12: psm0                            9          0
> irq16: fwohci0+                        2          0
> irq19: uhci2 ehci*              25229879      89151
> irq23: uhci3 ehci1                  4852         17
> cpu0: timer                       565386       1997
> irq256: mskc0                        389          1
> cpu1: timer                       562755       1988
> Total                           26363473      93157
> $
>

That looks like an interrupt storm on IRQ19.
I'm not sure if that is buggy hardware or just one of the usual USB
necessary quirks

Attilio


-- 
Peace can only be achieved by understanding - A. Einstein
Received on Tue Nov 17 2009 - 20:21:53 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:39:58 UTC