[Ubuntu] Onverklaarbare load

[xerix]

Ik heb sinds kort een Ubuntu servertje (Ubuntu Server Edition 7.10) draaien op een Athlon64 3500, 2GB ram, 2x WD500GB in RAID1 (software raid). De server draait nu een week maar doet voorlopig niks. De bak zou dus 100% van de tijd idle moeten zijn. De enige extra processen die erop draaien zijn apache2, tomcat6, mysql en cacti om wat statistieken te genereren.
Bij het bladeren door de cacti gegenereerde stats viel het mij op dat de load van de server op bepaalde tijdstippen rond de 3 zit. Dit patroon herhaald zich met ongeveer gelijke intervallen. Sinds gister is de regelmaat van de intervallen veranderd, dit was eerst rond de 12uur maar is nu naar ongeveer 4uur gegaan (zoals te zien is op de grafiekjes).
Om te achterhalen waar deze load vandaan komt heb ik de cronjobs doorgespit en alle logs nagekeken maar hierin kon ik geen aanleiding voor de load vinden. Als ik tijdens zo'n load moment kijk naar de processen met 'top' staat hier ook geen enkel proces wat een hoge cpu usage heeft. Het zal hem dus ergens in de IO zitten vermoed ik. Het enige wat ik kan bedenken is de softraid configuratie die wellicht een check oid. uitvoerd. Ik ben verder geen exper op linux gebied met mijn beperkte kennis en google heb ik de oorzaak niet kunnen achterhalen, wellicht dat iemand tegen een soortgelijke situatie is aangelopen.


Afgelopen dag

Afgelopen 2 dagen

Afgelopen week

[moto-moi]

Heb je al geprobeerd om iostat op zo'n moment te draaien?

[xerix]

moto-moi schreef op donderdag 15 november 2007 @ 13:36:
Heb je al geprobeerd om iostat op zo'n moment te draaien?

Ja ook geprobeerd:

code:

Linux 2.6.22-14-server (bamibal)        11/15/2007

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.39    0.00    0.23    0.03    0.00   99.35

Device:            tps   Blk_read/s   Blk_wrtn/s   Blk_read   Blk_wrtn
sda               1.08         0.27        21.11     142756   11190512
sdb               1.08         0.29        21.11     154944   11190512
md0               0.07         0.02         0.58       9938     307952
md1               1.92         0.54        15.17     284866    8042432

Dit lijkt me toch niet spectaculair

[Hmzaniac]

Indexering van beagled? Cron jobs? updatedb?

[deadinspace]

Zou je eens, tijdens zo'n periode van load:

• uptime

  runnen, en kijken of die ook die load rapporteert (laatste 3 getalletjes)
• De volledige output hier pasten van

  ps auxf

• De inhoud van /proc/mdstat hier pasten

• vmstat 10 20

  runnen, en de volledige output hier posten (duurt een paar minuten om te draaien)

Je kan ook nog iets van

vmstat 60

En die pas afbreken (met ctrl-C) op het moment dat de load weer enige tijd (5 minuten ofzo) op normaal nivo is. Daar zou dan mooi het verschil tussen de periode met loge load en de periode met lage load op te zien moeten zijn

[CyBeR]

xerix schreef op donderdag 15 november 2007 @ 13:34:

Bij het bladeren door de cacti gegenereerde stats viel het mij op dat de load van de server op bepaalde tijdstippen rond de 3 zit.

Je leest de grafiek verkeerd. Je load zit meestal net onder de 1, soms er net boven.

[Mysteryman]

de load pieken had/heb ik ook en zijn te verklaren door de cronjobs die dan worden gestart... Zowiezo MySQL doet nogal wat controles e.d. om de databases schoon te houden...

Overigens zou het ook een kernel hik kunnen zijn... Ik heb een keer gehad onder ubuntu 6.06 dat er midden in de nacht (02.00) uur een kernel hik was, die er voor zorgde dat mijn load ~1.20 zat...

Misschien dat een reboot wil helpen...

[xerix]

deadinspace schreef op donderdag 15 november 2007 @ 18:15:
Zou je eens, tijdens zo'n periode van load:

• uptime

  runnen, en kijken of die ook die load rapporteert (laatste 3 getalletjes)
• De volledige output hier pasten van

  ps auxf

• De inhoud van /proc/mdstat hier pasten

• vmstat 10 20

  runnen, en de volledige output hier posten (duurt een paar minuten om te draaien)

Je kan ook nog iets van
[cmd]vmstat 60[cmd]
En die pas afbreken (met ctrl-C) op het moment dat de load weer enige tijd (5 minuten ofzo) op normaal nivo is. Daar zou dan mooi het verschil tussen de periode met loge load en de periode met lage load op te zien moeten zijn

Ik ga het proberen Ben nu nog steeds aan het wachten op de volgende 'piek'.

Mysteryman schreef op donderdag 15 november 2007 @ 22:50:
de load pieken had/heb ik ook en zijn te verklaren door de cronjobs die dan worden gestart... Zowiezo MySQL doet nogal wat controles e.d. om de databases schoon te houden...

Overigens zou het ook een kernel hik kunnen zijn... Ik heb een keer gehad onder ubuntu 6.06 dat er midden in de nacht (02.00) uur een kernel hik was, die er voor zorgde dat mijn load ~1.20 zat...

Misschien dat een reboot wil helpen...

Ik snap alleen niet waarom dit een uur aanhoudt.. kan me geen proces voorstellen wat zo lang een hoge load veroorzaakt.

[arnem_]

het proces "tracker" veroorzaakt bij sommige Ubuntu-gebruikers een enorme load. Het is volgens mij bedoelt als Beagle indexer. Ik heb het programma uitgezet.

[xerix]

arnem_ schreef op donderdag 15 november 2007 @ 23:43:
het proces "tracker" veroorzaakt bij sommige Ubuntu-gebruikers een enorme load. Het is volgens mij bedoelt als Beagle indexer. Ik heb het programma uitgezet.

Ik heb geen beagle geinstalleerd, het gaat hier om de server editie. Beagle/tracker zijn toch desktop tools?

[kmf]

lijkt me logrotate of zo. Of updatedb. Mysql heeft zelf niet echt een "opschoontask" of zo.

[xerix]

deadinspace schreef op donderdag 15 november 2007 @ 18:15:
Zou je eens, tijdens zo'n periode van load:

• uptime

  runnen, en kijken of die ook die load rapporteert (laatste 3 getalletjes)
• De volledige output hier pasten van

  ps auxf

• De inhoud van /proc/mdstat hier pasten

• vmstat 10 20

  runnen, en de volledige output hier posten (duurt een paar minuten om te draaien)

Je kan ook nog iets van

vmstat 60

En die pas afbreken (met ctrl-C) op het moment dat de load weer enige tijd (5 minuten ofzo) op normaal nivo is. Daar zou dan mooi het verschil tussen de periode met loge load en de periode met lage load op te zien moeten zijn

Nou ik heb eindelijk de mogelijkheid gehad om tijdens zo'n load periode te monitoren, ik kan hier geen rare dingen in terugvinden.
Hier de output:

jemoer@bamibal:~$ uptime
 13:21:44 up 11 days,  2:49,  2 users,  load average: 0.72, 0.77, 0.72

jemoer@bamibal:~$ ps auxf
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         2  0.0  0.0      0     0 ?        S<   Nov09   0:00 [kthreadd]
root         3  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [migration/0]
root         4  0.0  0.0      0     0 ?        SN   Nov09   0:00  \_ [ksoftirqd/0]
root         5  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [watchdog/0]
root         6  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [events/0]
root         7  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [khelper]
root        26  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [kblockd/0]
root        27  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [kacpid]
root        28  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [kacpi_notify]
root       158  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [kseriod]
root       180  0.0  0.0      0     0 ?        S    Nov09   0:00  \_ [pdflush]
root       181  0.0  0.0      0     0 ?        S    Nov09   0:02  \_ [pdflush]
root       182  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [kswapd0]
root       234  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [aio/0]
root      2011  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [ksuspend_usbd]
root      2012  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [khubd]
root      2030  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [ata/0]
root      2031  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [ata_aux]
root      2178  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [scsi_eh_0]
root      2179  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [scsi_eh_1]
root      2214  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [scsi_eh_2]
root      2215  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [scsi_eh_3]
root      2353  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [md0_raid1]
root      2359  0.0  0.0      0     0 ?        S<   Nov09   0:09  \_ [md1_raid1]
root      2431  0.0  0.0      0     0 ?        S<   Nov09   0:05  \_ [kjournald]
root      3741  0.0  0.0      0     0 ?        S<   Nov09   0:00  \_ [kjournald]
root         1  0.0  0.0   2864  1892 ?        Ss   Nov09   0:01 /sbin/init
root      2589  0.0  0.0   2452   700 ?        S<s  Nov09   0:00 /sbin/udevd --daemon
root      4030  0.0  0.0   1700   516 tty4     Ss+  Nov09   0:00 /sbin/getty 38400 tty4
root      4031  0.0  0.0   1692   516 tty5     Ss+  Nov09   0:00 /sbin/getty 38400 tty5
root      4034  0.0  0.0   1692   516 tty2     Ss+  Nov09   0:00 /sbin/getty 38400 tty2
root      4035  0.0  0.0   1696   520 tty3     Ss+  Nov09   0:00 /sbin/getty 38400 tty3
root      4037  0.0  0.0   1696   516 tty6     Ss+  Nov09   0:00 /sbin/getty 38400 tty6
syslog    4080  0.0  0.0   1916   736 ?        Ss   Nov09   0:01 /sbin/syslogd -u syslog
root      4099  0.0  0.0   1840   540 ?        S    Nov09   0:00 /bin/dd bs 1 if /proc/kmsg of /var/run/klogd/kmsg
klog      4101  0.0  0.0   2620  1408 ?        Ss   Nov09   0:00 /sbin/klogd -P /var/run/klogd/kmsg
root      4120  0.0  0.0   5280   992 ?        Ss   Nov09   0:00 /usr/sbin/sshd
root     12597  0.0  0.1   8036  2376 ?        Ss   13:12   0:00  \_ sshd: jemoer [priv]
jemoer   12599  0.0  0.0   8036  1532 ?        S    13:12   0:00      \_ sshd: jemoer@pts/0
jemoer   12600  0.1  0.1   5744  3140 pts/0    Ss   13:12   0:00          \_ -bash
jemoer   12625  0.0  0.0   2620   972 pts/0    R+   13:14   0:00              \_ ps auxf
root      4174  0.0  0.0   1752   528 ?        S    Nov09   0:00 /bin/sh /usr/bin/mysqld_safe
mysql     4214  0.0  0.9 178308 19020 ?        Sl   Nov09   0:26  \_ /usr/sbin/mysqld --basedir=/usr --datadir=/database/mysql --user=mysql --pid-file=/var/run/mysqld/my
root      4215  0.0  0.0   1680   548 ?        S    Nov09   0:00  \_ logger -p daemon.err -t mysqld_safe -i -t mysqld
root      4307  0.0  0.0   2060   396 ?        Ss   Nov09   0:00 /sbin/mdadm --monitor --pid-file /var/run/mdadm/monitor.pid --daemonise --scan --syslog
daemon    4321  0.0  0.0   1964   432 ?        Ss   Nov09   0:00 /usr/sbin/atd
root      4332  0.0  0.0   2336   908 ?        Ss   Nov09   0:00 /usr/sbin/cron
root      4442  0.0  0.0   1696   516 tty1     Ss+  Nov09   0:00 /sbin/getty 38400 tty1
root     28783  0.0  0.0   3308   880 ?        S    Nov11   0:00 /usr/sbin/hddtemp -d -l 127.0.0.1 -p 7634 -s | /dev/sda /dev/sdb
tomcat    1697  0.0  5.9 232452 122624 ?       Sl   Nov14   1:57 /usr/local/jvm/sunjre/bin/java -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.
root     18369  0.0  0.4  24216  8852 ?        Ss   Nov15   0:00 /usr/sbin/apache2 -k start
www-data 16520  0.0  0.4  27056  9996 ?        S    Nov18   0:01  \_ /usr/sbin/apache2 -k start
www-data 16521  0.0  0.4  26000  9124 ?        S    Nov18   0:02  \_ /usr/sbin/apache2 -k start
www-data 16522  0.0  0.4  26516  9688 ?        S    Nov18   0:02  \_ /usr/sbin/apache2 -k start
www-data 16523  0.0  0.4  27052 10076 ?        S    Nov18   0:02  \_ /usr/sbin/apache2 -k start
www-data 16524  0.0  0.4  26824  9996 ?        S    Nov18   0:01  \_ /usr/sbin/apache2 -k start
www-data 20322  0.0  0.4  26824  9936 ?        S    Nov18   0:01  \_ /usr/sbin/apache2 -k start
www-data 21485  0.0  0.4  27040 10160 ?        S    Nov18   0:02  \_ /usr/sbin/apache2 -k start
www-data 32187  0.0  0.4  26808  9980 ?        S    Nov19   0:02  \_ /usr/sbin/apache2 -k start

jemoer@bamibal:~$ cat /proc/mdstat 
Personalities : [linear] [multipath] [raid0] [raid1] [raid6] [raid5] [raid4] [raid10] 
md1 : active raid1 sda3[0] sdb3[1]
      453008832 blocks [2/2] [UU]
      
md0 : active raid1 sda1[0] sdb1[1]
      29294400 blocks [2/2] [UU]
      
unused devices: <none>

jemoer@bamibal:~$ vmstat 10 20
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
 0  0      0 1183628 205652 457696    0    0     0    10    4   15  0  0 100  0
 0  0      0 1183644 205652 457696    0    0     0    10    5   52  0  0 100  0
 0  0      0 1183644 205660 457696    0    0     0    50   18   56  0  0 100  0
 0  0      0 1182580 205668 457704    0    0     0    34   47  195  7  1 92  0
 0  0      0 1182588 205668 457712    0    0     0     6    4   56  0  0 100  0
 0  0      0 1186836 205668 457712    0    0     0     8    5   55  0  0 100  0
 0  0      0 1186836 205668 457712    0    0     0    10    6   54  0  0 100  0
 0  0      0 1186836 205672 457712    0    0     0    20    8   54  0  0 100  0
 0  0      0 1186836 205672 457712    0    0     0     7    5   53  0  0 100  0
 0  0      0 1186836 205672 457712    0    0     0     4    5   52  0  0 100  0
 0  0      0 1186836 205672 457712    0    0     0     6    4   56  0  0 100  0
 0  0      0 1186836 205672 457712    0    0     0    16    5   55  0  0 100  0
 0  0      0 1186836 205672 457712    0    0     0     4    3   52  0  0 100  0
 0  0      0 1186836 205672 457712    0    0     0     4    2   52  0  0 100  0
 0  0      0 1186836 205672 457712    0    0     0    16    9   54  0  0 100  0
 0  0      0 1186836 205672 457712    0    0     0     7    5   53  0  0 100  0
 0  0      0 1186836 205672 457712    0    0     0     4    2   54  0  0 100  0
 0  0      0 1186836 205672 457712    0    0     0     4    2   52  0  0 100  0
 0  0      0 1186836 205672 457712    0    0     0     7    4   53  0  0 100  0
 0  0      0 1186836 205672 457712    0    0     0     4    2   52  0  0 100  0

[xerix]

Niemand een idee waar mijn onverklaarbare load vandaan komt?

[xerix]

echt niemand?

[Rainmaker]

Ik zie niks vreemds in die output.

Kun je voor de zekerheid je cron deamon anders eens uitzetten en kijken of de load nog terugkomt?

/etc/init.d/crond stop

[Verwijderd]

xerix schreef op dinsdag 20 november 2007 @ 13:22:

jemoer@bamibal:~$ uptime
 13:21:44 up 11 days,  2:49,  2 users,  load average: 0.72, 0.77, 0.72

Ik zie ook niks vreemds, dus eerst maar eens de controles: wat is je uptime buiten die hoge load times? Wat is de output van crontab -l (zowel als user als ook als root). Heb je chkrootkit gedraaid?

[xerix]

Rainmaker schreef op dinsdag 11 december 2007 @ 12:24:
Ik zie niks vreemds in die output.

Kun je voor de zekerheid je cron deamon anders eens uitzetten en kijken of de load nog terugkomt?

/etc/init.d/crond stop

Ik heb de cron deamon gestopt en zelf een scriptje geschreven die elke minuut de load wegschrijft, maar er blijven van die load pieken komen.

Verwijderd schreef op dinsdag 11 december 2007 @ 14:43:
[...]


Ik zie ook niks vreemds, dus eerst maar eens de controles: wat is je uptime buiten die hoge load times? Wat is de output van crontab -l (zowel als user als ook als root). Heb je chkrootkit gedraaid?

M'n uptime buiten die hoge load tijden is:

08:02:25 up 33 days, 21:36,  1 user,  load average: 0.00, 0.00, 0.00

crontab -l geeft; no crontab for root/user

chkrootkit vindt ook niks.

[Rainmaker]

In single user mode starten, waardoor er nauwelijks tot geen services actief zijn misschien?

Is het niet mrtg die die grafiekjes die je post aan het maken is

(ondanks de smiley wel een suggestie)

[ Voor 11% gewijzigd door Rainmaker op 13-12-2007 13:16 ]

[Sir Isaac]

Tracker is al genoemd, maar ik heb uit de treat nog niet begrepen of die nu draait of niet. Tracker is een alternatief voor Beagle en veroorzaakt ook bij mij regelmatig een hoge load.

[Apen-nootjes]

Misschien heb je hier wat aan? : http://forum.ubuntu-nl.org/topic/19293

[xerix]

Rainmaker schreef op donderdag 13 december 2007 @ 13:14:
In single user mode starten, waardoor er nauwelijks tot geen services actief zijn misschien?

Is het niet mrtg die die grafiekjes die je post aan het maken is

(ondanks de smiley wel een suggestie)

Nee grafiekjes worden niet meer gemaakt nu de cron deamon uitstaat. Dus dat kan het ook niet zijn,

Sir Isaac schreef op donderdag 13 december 2007 @ 17:38:
Tracker is al genoemd, maar ik heb uit de treat nog niet begrepen of die nu draait of niet. Tracker is een alternatief voor Beagle en veroorzaakt ook bij mij regelmatig een hoge load.

Tracker draait niet, tgaat hier om een ubuntu server 7.10 machine. Deze staat op een colo dus er veel mee pielen kan ik ook niet.

Apen-nootjes schreef op donderdag 13 december 2007 @ 18:19:
Misschien heb je hier wat aan? : http://forum.ubuntu-nl.org/topic/19293

Zelfde verhaal, er draait geen x oid. Het vreemde vind ik gewoon dat er wel hoge load is maar dit nergens te verklaren valt. Er is geen proces wat veel cpu/geheugen gebruikt en er is bijna geen disk activiteit.

[DeadLock]

Een relatief kleine kans, de TS heeft ubuntu server (zonder X tenzij hij die zelf nog heeft zitten installeren) en in dat topic werd het probleem door X of compiz veroorzaakt.

Je kan eens kijken welke cronjobs er draaien, en in het oog houden of er een rechtstreeks verband is tussen die hoge load pieken en een bepaalde cronjob. Anders zal je eens moeten kijken welke daemon het eventueel kan veroorzaken.

Edit: oeps, te traag getypt

[ Voor 3% gewijzigd door DeadLock op 13-12-2007 20:41 ]

[Rainmaker]

Nou valt me toch 1 proces op in de ps output:

code:

root      4099  0.0  0.0   1840   540 ?        S    Nov09   0:00 /bin/dd bs 1 if /proc/kmsg of /var/run/klogd/kmsg

Waar komt die vandaan?

[deadinspace]

Rainmaker schreef op vrijdag 14 december 2007 @ 09:43:
Nou valt me toch 1 proces op in de ps output:

code:

root      4099  0.0  0.0   1840   540 ?        S    Nov09   0:00 /bin/dd bs 1 if /proc/kmsg of /var/run/klogd/kmsg

Waar komt die vandaan?

Dat is volgensmij om kernel log messages te kopieren naar een gewone file, waar hij verwerkt kan worden door klogd. Beetje jammer om daar een heel nieuw proces voor te gebruiken misschien, maar lijkt me verder doodnormaal.