System-Auslastung steigt kontinuierlich auf 6000% an

german

#1

Hallo,

bei einem frisch aufgesetzten UCS 4.0 (incl. aktueller Updates) steigt die CPU-Last fast linear auf bis zu 6000% Prozent an (lt. Statistik).
Es handelt sich um ein Dual-Core System (i3 4010U), installierte Rollen DC-Master und UVMM (1 VM, idled derzeit mit 5%).
Normale CPU-Load liegt zwischen 10-20%.
Identischer Fehler lag schon auf einem anderen System mit stark abweichender Hardware (PC Engines APU.1C4) vor, auch dort CPU-Load bis 6000%.

Leider lässt sich der Prozess nicht eingrenzen, da da System nahezu unbedienbar war.
Welchen relevanten Logs kann ich evtl. weitere hilfreiche Hinweise zur Eingrenzung entnehmen?
Anbei ein Screenshot.


#2

Hallo,

standardmäßig werden in aktuellen UCS-Neuinstallationen die so genannten System Stats aktiviert.
Dieser Mechanismus protokoliert Dinge wie Speicherauslastung, Prozesslisten, etc. in regelmäßigen Abständen in die /var/log/univention/system-stats.log - da würde ich mal reinschauen.

Gegebenenfalls macht es Sinn, das Intervall der Protokollierung zu verkürzen, um nichts zu verpassen, standardmäßig wird alle 30 Minuten gelogged - der Beispielcode verkürzt das nach Cron-Notation auf alle 5 Minuten:

ucr search system/stats ucr set system/stats/cron="0,5 * * * *"

Mit freundlichen Grüßen,
Tim Petersen


#3

Hallo Herr Petersen,

danke für die schnelle Antwort.
Im Log sind einige Auffälligkeiten festzustellen, offensichtlich wurde der smbd minütlich geforked:

root 3624 0.0 0.0 467016 3408 ? S Mar29 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 15556 0.0 0.3 521148 24576 ? S 17:23 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 15612 0.0 0.2 516996 24296 ? S 17:24 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 15654 0.0 0.2 516996 24296 ? S 17:25 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 15718 0.0 0.2 516996 24296 ? S 17:26 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 15740 0.0 0.2 516996 24296 ? S 17:27 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 15786 0.0 0.2 516996 24296 ? S 17:28 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 15816 0.0 0.2 516996 24296 ? S 17:29 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 16039 0.0 0.2 516996 24296 ? S 17:30 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 16072 0.0 0.2 516996 24292 ? S 17:31 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 16158 0.0 0.2 516996 24292 ? S 17:32 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 16228 0.0 0.2 516996 24292 ? S 17:34 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 16280 0.0 0.2 516996 24296 ? S 17:35 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 16348 0.0 0.2 516996 24292 ? S 17:36 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 16383 0.0 0.2 516996 24300 ? S 17:37 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 16453 0.0 0.2 516996 24300 ? S 17:38 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 16489 0.0 0.2 516996 24296 ? S 17:39 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 16590 0.0 0.2 516996 24288 ? S 17:40 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 16625 0.0 0.2 516996 24300 ? S 17:41 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 16710 0.0 0.2 516996 24300 ? S 17:42 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 16731 0.0 0.2 516996 24292 ? S 17:43 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 16808 0.0 0.2 516996 24292 ? S 17:44 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 16940 0.0 0.2 516996 24300 ? S 17:45 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground root 17035 0.0 0.2 516996 24300 ? S 17:46 0:00 | \_ /usr/sbin/smbd -D --option=server role check:inhibit=yes --foreground

Ähnliches ist auch bei anderen Tasks festzustellen, die davon evtl. abhängig sind:

sessionclean lsof awk xargs lsof cron sh univention-user quota smbd


#4

Bis 13:30, 29.03. gab es zwei Zombie Tasks, ab 14:00 Uhr nicht mehr, scheint aber ein anderes Problem gewesen zu sein, da das Phänomen erst am 31.03. began.
Anbei mal der relevante Teil aus dem Log, Anzahl der Tasks ist von durschschnittlich 200 auf 483 angestiegen. Auswirkungen beschränken sich auf den Load, Arbeitsspeicherauslastung war durchgängig gering (35%, ca. 3 GB).
Um 21:45 wurde der Server dann hard resettet (shutdown -r now blieb wirkungslos).

Auffällig im Log:
Zahlreiche PIDs für eine Samba-Session:

-> /usr/bin/smbstatus

Samba version 4.2.0rc2-Debian
PID     Username      Group         Machine            Protocol Version       
------------------------------------------------------------------------------
15556     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49291) SMB2_10     
16590     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49316) SMB2_10     
16383     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49313) SMB2_10     
16280     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49305) SMB2_10     
16710     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49318) SMB2_10     
17269     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49327) SMB2_10     
17035     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49322) SMB2_10     
16228     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49304) SMB2_10     
16039     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49301) SMB2_10     
15654     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49296) SMB2_10     
15816     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49300) SMB2_10     
16731     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49319) SMB2_10     
15718     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49297) SMB2_10     
15740     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49298) SMB2_10     
17351     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49328) SMB2_10     
17225     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49326) SMB2_10     
17064     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49323) SMB2_10     
16625     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49317) SMB2_10     
16158     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49303) SMB2_10     
15786     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49299) SMB2_10     
16808     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49320) SMB2_10     
17148     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49325) SMB2_10     
16489     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49315) SMB2_10     
16453     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49314) SMB2_10     
17129     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49324) SMB2_10     
16940     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49321) SMB2_10     
16072     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49302) SMB2_10     
16348     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49309) SMB2_10     
15612     -1            -1            192.168.100.23 (ipv4:192.168.100.23:49292) SMB2_10     

Service      pid     machine       Connected at
-------------------------------------------------------

No locked files

system-stats.zip (356 KB)


#5

Hallo,

an den System-Stats fällt auf, dass die Last über den Tag schon relativ kontinuierlich steigt.

top - 06:00:02 up 1 day,  8:28,  0 share4,  load average: 0.00, 0.03, 0.06
top - 06:00:05 up 1 day,  8:28,  0 share4,  load average: 0.00, 0.03, 0.06
top - 06:30:02 up 1 day,  8:58,  0 share4,  load average: 0.96, 0.33, 0.20
top - 06:30:05 up 1 day,  8:58,  0 share4,  load average: 0.96, 0.33, 0.20
top - 07:00:02 up 1 day,  9:28,  0 share4,  load average: 0.16, 0.21, 0.34
top - 07:00:05 up 1 day,  9:28,  0 share4,  load average: 0.23, 0.22, 0.35
top - 07:30:01 up 1 day,  9:58,  0 share4,  load average: 1.02, 1.07, 0.87
top - 07:30:04 up 1 day,  9:58,  0 share4,  load average: 1.02, 1.07, 0.87
top - 08:00:02 up 1 day, 10:28,  0 share4,  load average: 3.21, 2.37, 1.93
top - 08:00:05 up 1 day, 10:28,  0 share4,  load average: 3.21, 2.37, 1.93
top - 08:30:02 up 1 day, 10:58,  0 share4,  load average: 3.03, 3.06, 2.86
top - 08:30:05 up 1 day, 10:58,  0 share4,  load average: 3.34, 3.13, 2.88
top - 09:00:02 up 1 day, 11:28,  0 share4,  load average: 4.01, 4.06, 3.81
top - 09:00:05 up 1 day, 11:28,  0 share4,  load average: 4.01, 4.06, 3.81
top - 09:30:02 up 1 day, 11:58,  0 share4,  load average: 5.13, 5.10, 4.81
top - 09:30:05 up 1 day, 11:58,  0 share4,  load average: 5.13, 5.10, 4.81
top - 10:00:02 up 1 day, 12:28,  0 share4,  load average: 6.33, 6.20, 5.90
top - 10:00:05 up 1 day, 12:28,  0 share4,  load average: 6.33, 6.20, 5.90
top - 10:30:01 up 1 day, 12:58,  0 share4,  load average: 7.03, 7.14, 6.88
top - 10:30:04 up 1 day, 12:58,  0 share4,  load average: 6.95, 7.13, 6.88
top - 11:00:02 up 1 day, 13:28,  0 share4,  load average: 8.08, 8.04, 7.78
top - 11:00:05 up 1 day, 13:28,  0 share4,  load average: 8.07, 8.04, 7.78
top - 11:30:02 up 1 day, 13:58,  0 share4,  load average: 9.64, 9.24, 8.86
top - 11:30:05 up 1 day, 13:58,  0 share4,  load average: 9.64, 9.24, 8.86
top - 12:00:02 up 1 day, 14:28,  0 share4,  load average: 10.07, 10.11, 9.82
top - 12:00:05 up 1 day, 14:28,  0 share4,  load average: 10.22, 10.14, 9.84
top - 12:30:02 up 1 day, 14:58,  0 share4,  load average: 11.03, 11.09, 10.86
top - 12:30:05 up 1 day, 14:58,  0 share4,  load average: 11.03, 11.09, 10.86
top - 13:00:02 up 1 day, 15:28,  0 share4,  load average: 12.10, 12.20, 11.87
top - 13:00:05 up 1 day, 15:28,  0 share4,  load average: 12.10, 12.20, 11.87
top - 13:30:02 up 1 day, 15:58,  0 share4,  load average: 13.85, 13.24, 12.89
top - 13:30:05 up 1 day, 15:58,  0 share4,  load average: 13.85, 13.24, 12.89
top - 14:00:02 up 1 day, 16:28,  0 share4,  load average: 14.18, 14.10, 13.82
top - 14:00:05 up 1 day, 16:28,  0 share4,  load average: 14.40, 14.15, 13.83
top - 14:30:02 up 1 day, 16:58,  0 share4,  load average: 15.00, 15.03, 14.79
top - 14:30:05 up 1 day, 16:58,  0 share4,  load average: 15.00, 15.03, 14.79
top - 15:00:02 up 1 day, 17:28,  0 share4,  load average: 16.88, 16.36, 16.01
top - 15:00:05 up 1 day, 17:28,  0 share4,  load average: 16.88, 16.36, 16.01
top - 15:30:01 up 1 day, 17:58,  0 share4,  load average: 17.09, 17.07, 16.82
top - 15:30:05 up 1 day, 17:58,  0 share4,  load average: 17.08, 17.07, 16.82
top - 16:00:02 up 1 day, 18:28,  0 share4,  load average: 18.19, 18.10, 17.80
top - 16:00:05 up 1 day, 18:28,  0 share4,  load average: 18.34, 18.13, 17.81
top - 16:30:02 up 1 day, 18:58,  0 share4,  load average: 19.19, 19.12, 18.80
top - 16:30:05 up 1 day, 18:58,  0 share4,  load average: 19.19, 19.12, 18.80
top - 17:00:02 up 1 day, 19:28,  0 share4,  load average: 20.11, 20.12, 19.89
top - 17:00:05 up 1 day, 19:28,  0 share4,  load average: 20.26, 20.16, 19.90
top - 17:30:02 up 1 day, 19:58,  0 share4,  load average: 26.66, 24.05, 22.09
top - 17:30:05 up 1 day, 19:58,  0 share4,  load average: 26.85, 24.13, 22.13
top - 18:00:02 up 1 day, 20:28,  0 share4,  load average: 51.13, 49.97, 42.69
top - 18:00:05 up 1 day, 20:28,  0 share4,  load average: 51.13, 49.97, 42.69
top - 18:30:02 up 1 day, 20:58,  0 share4,  load average: 52.50, 52.24, 50.78
top - 18:30:05 up 1 day, 20:58,  0 share4,  load average: 52.50, 52.24, 50.78
...

Die Samba-Prozesse sind bis 17:30 relativ unauffällig, sorgen aber dann für die Verdoppelung der Last. Hier sollte man ggf. auch mal schauen, was auf dem Client 192.168.100.23 zu diesem Zeitpunkt passiert.

Die stetig ansteigende Zahl der Prozesse ist allerdings nicht nur durch die Samba-Prozesse bedingt. Die halbstündlich laufenden cronjobs für die Session-Bereinigung von PHP aus /etc/cron.d/php5 werden nicht fertig und stapeln sich mit der Zeit. Das wäre aus meiner Sicht vielleicht als erstes zu prüfen.

Viele Grüße,
Dirk Ahrnke


#6

Guter Hinweis - ich habe vergessen zu erwähnen, dass zu dem Zeitpunkt (ab ca. 7 oder 8:00 Uhr) der Client nicht mehr online war… :-/
Aus irgendeinem Grund scheinen also die Prozesse nicht sauber beendet worden zu sein…
Leider kann ich das Phänomen auch nicht nachstellen, da mir die genauen Umstände nicht bekannt sind, die zum Problem führen.


#7

Heute wieder ähnliches Fehlerbild, aktuelle Auslastung sogar 9,6k % …, Anstieg diesmal deutlich linearer (s. Anhang).
Ursache könnte diesmal eine (bisher nicht erfolgreiche) Installation von Tine20 in einer zusätzlichen VM sein, würde zumindest zeitlich mit dem Beginn des Anstiegs am 06.04.
ab ca. 21/22 Uhr zusammenfallen.
Auch diesmal laut smbstatus wieder zahlreiche PIDs für einen Client, der nicht dauerhaft online war, und vor allem nicht auf aktiv auf Files zugegriffen hat (Netzlaufwerke waren aber zumindest zeitweise verbunden).

660 Tasks & Load-Average von 117, auch nach beenden von samba-ad-dc:

top - 22:40:15 up 4 days, 7:37, 1 user, load average: 117,84, 114,77, 108,38 Tasks: 660 total, 1 running, 657 sleeping, 0 stopped, 2 zombie %Cpu(s): 1,7 us, 0,3 sy, 0,0 ni, 98,1 id, 0,0 wa, 0,0 hi, 0,0 si, 0,0 st KiB Mem: 8122276 total, 6429820 used, 1692456 free, 142308 buffers KiB Swap: 8310780 total, 58620 used, 8252160 free, 1029404 cached

Server ist derzeit noch nicht durchgestartet.
3 Zombies existieren derzeit, und lassen sich auch mit kill -9 nicht beenden:

[code]root@ucs:~# ps aux | awk ‘"[Zz]" ~ $8 { printf("%s, PID = %d\n", $8, $2); }’
Z, PID = 12534
Z, PID = 18329
Z, PID = 21150

root@ucs:~# ps auxf | grep 12534
root 12534 0.0 0.0 0 0 ? Z Apr06 0:00 | _ [univention-virt]

root@ucs:~# ps auxf | grep 18329
root 18329 0.0 0.0 0 0 ? Z 22:29 0:00 _ [websockify]

root@ucs:~# ps auxf | grep 21150
root 21150 0.0 0.0 0 0 ? Z 15:38 0:00 | _ [univention-virt] [/code]

Dazu die Parents:

root 2937 0.0 0.0 176 0 ? Ss Apr03 0:00 \_ runsv univention-bind root 2938 0.0 0.0 176 4 ? Ss Apr03 0:00 \_ runsv univention-directory-listener listener 30138 0.0 0.5 538824 42888 ? S Apr05 0:01 | \_ /usr/sbin/univention-directory-listener -F -b dc=ml,dc=ways -m /usr/lib/univention-directory-listener/system -c /var/lib/univention-directory-listener -d 2 -x -ZZ -D cn=admin,dc=ml,dc=ways -y /etc/ldap.secret root 12534 0.0 0.0 0 0 ? Z Apr06 0:00 | \_ [univention-virt] <defunct> root 21150 0.0 0.0 0 0 ? Z 15:38 0:00 | \_ [univention-virt] <defunct>
und

root 18329 0.0 0.0 0 0 ? Z 22:29 0:00 \_ [websockify] <defunct>
und

root      2937  0.0  0.0    176     0 ?        Ss   Apr03   0:00  \_ runsv univention-bind
root      2938  0.0  0.0    176     4 ?        Ss   Apr03   0:00  \_ runsv univention-directory-listener
listener 30138  0.0  0.5 538824 42888 ?        S    Apr05   0:01  |   \_ /usr/sbin/univention-directory-listener -F -b dc=ml,dc=ways -m /usr/lib/univention-directory-listener/system -c /var/lib/univention-directory-listener -d 2 -x -ZZ -D cn=admin,dc=ml,dc=ways -y /etc/ldap.secret
root     12534  0.0  0.0      0     0 ?        Z    Apr06   0:00  |       \_ [univention-virt] <defunct>

Derzeit kann ich aber noch nicht einschätzen, ob die drei Zombies relevant für das Problem sind oder nur eine Folge dessen.

im listener.log sind einige Einträge die auf LDAP-Probleme hindeuten, die auch einen Einfluss auf Samba (samba4-idmap) haben:

06.04.15 22:35:12.612  LISTENER    ( PROCESS ) : samba4-idmap: removing entry for S-1-5-21-4163309571-2108280767-1046492088-1115
Revoke certificate: tine.ml.ways
Using configuration from openssl.cnf
Revoking Certificate 04.
Data Base Updated
unable to write 'random state'
Using configuration from openssl.cnf
unable to write 'random state'
Stopping nagios-nrpe: nagios-nrpe.
Starting nagios-nrpe: nagios-nrpe.
OK.
06.04.15 23:07:07.172  LISTENER    ( PROCESS ) : samba4-idmap: added entry for S-1-4-2012
SQL: CREATE USER "tine$" IN GROUP pkgdbg

Generating RSA private key, 2048 bit long modulus
........................................+++
...............................................................................................................+++
unable to write 'random state'
e is 65537 (0x10001)
You are about to be asked to enter information that will be incorporated
into your certificate request.
What you are about to enter is what is called a Distinguished Name or a DN.
There are quite a few fields but you can leave some blank
For some fields there will be a default value,
If you enter '.', the field will be left blank.
-----
Country Name (2 letter code) [DE]:State or Province Name (full name) [DE]:Locality Name (eg, city) [DE]:Organization Name (eg, company) [
ML.WAYS]:Organizational Unit Name (eg, section) [Univention Corporate Server]:Common Name (eg, YOUR name) [tine.ml.ways]:Email Address [s
sl@ml.ways]:
Please enter the following 'extra' attributes
to be sent with your certificate request
A challenge password []:An optional company name [Univention GmbH]:yes: standard output: Broken pipe
yes: write error
Using configuration from openssl.cnf
Check that the request matches the signature
Signature ok
The Subject's Distinguished Name is as follows
countryName           :PRINTABLE:'DE'
stateOrProvinceName   :PRINTABLE:'DE'
localityName          :PRINTABLE:'DE'
organizationName      :PRINTABLE:'ML.WAYS'
organizationalUnitName:PRINTABLE:'Univention Corporate Server'
commonName            :PRINTABLE:'tine.ml.ways'
emailAddress          :IA5STRING:'ssl@ml.ways'
Certificate is to be certified until Apr  4 21:07:08 2020 GMT (1825 days)

Write out database with 1 new entries
Data Base Updated
unable to write 'random state'
06.04.15 23:07:17.341  LISTENER    ( PROCESS ) : samba4-idmap: renaming entry for S-1-4-2012 to S-1-5-21-4163309571-2108280767-1046492088
-1116
Stopping nagios-nrpe: nagios-nrpe.
Starting nagios-nrpe: nagios-nrpe.
OK.



#8

Hallo,

die Fehler im listener.log sehen eher nach “ich kann nicht auf die Platte schreiben” aus.
Da ist auf jeden Fall “unable to write ‘random state’”, welches zumeist ein Schreibproblem der .rnd Datei im Home des jeweiligen Accounts bedeutet.

Mein Hinweis zu den PHP5-Cronjobs ist wohl untergegangen. Das muß auch nicht die Ursache sein, kann aber bei der Suche helfen.

Viele Grüße,
Dirk Ahrnke


#9

Danke für den Hinweis, auch meine weitere Recherche hat Probleme mit den Platten und/oder Controller ergeben, zu sehen im syslog während des Bootvorgangs:

Apr  8 21:24:48 ucs kernel: [   11.978695] ata1.00: failed command: WRITE FPDMA QUEUED
Apr  8 21:24:48 ucs kernel: [   11.978699] ata1.00: cmd 61/08:70:60:f0:d0/00:00:11:00:00/40 tag 14 ncq 4096 out
Apr  8 21:24:48 ucs kernel: [   11.978699]          res 40/00:94:b8:f2:d0/00:00:11:00:00/40 Emask 0x10 (ATA bus error)
Apr  8 21:24:48 ucs kernel: [   11.978701] ata1.00: status: { DRDY }
[...]
Apr  8 21:24:48 ucs kernel: [   11.978814] ata1: hard resetting link
Apr  8 21:24:48 ucs kernel: [   12.470411] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Apr  8 21:24:48 ucs kernel: [   12.470438] ata2: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Apr  8 21:24:48 ucs kernel: [   12.483651] ata2.00: configured for UDMA/133
Apr  8 21:24:48 ucs kernel: [   12.483677] ata1.00: configured for UDMA/133
Apr  8 21:24:48 ucs kernel: [   12.483691] ata2: EH complete
Apr  8 21:24:48 ucs kernel: [   12.483719] ata1: EH complete
Apr  8 21:24:48 ucs kernel: [   12.490409] ata1: limiting SATA link speed to 3.0 Gbps
Apr  8 21:24:48 ucs kernel: [   12.490415] ata1.00: exception Emask 0x10 SAct 0x7fffffff SErr 0x400000 action 0x6 frozen
Apr  8 21:24:48 ucs kernel: [   12.490416] ata1.00: irq_stat 0x08000008, interface fatal error
Apr  8 21:24:48 ucs kernel: [   12.490418] ata1: SError: { Handshk }
Apr  8 21:24:48 ucs kernel: [   12.490421] ata1.00: failed command: WRITE FPDMA QUEUED

Dem Hinweis bin ich tatsächlich noch nicht nachgegangen - wie kann ich nachprüfen, wie lange die Jobs denn benötigen?


#10

Hallo,

zum SATA-Problem kann ich im Moment nicht viel beitragen, es gibt ein paar Fundstellen in Ubuntu und Debian-Foren, die sind aber alle auf ältere Kernel bezogen, deshalb auch fraglich, ob hier anzuwenden.

Zu den PHP-Cronjobs:

In den system-stats ist zu sehen, dass diese nach 30 Minuten noch nicht fertig sind. Dann kommt schon der nächste:

root 24682 0.0 0.0 100796 5652 ? S 20:09 0:00 \_ /USR/SBIN/CRON root 24686 0.0 0.0 4192 492 ? Ss 20:09 0:00 | \_ /bin/sh -c [ -x /usr/lib/php5/maxlifetime ] && [ -x /usr/lib/php5/sessionclean ] && [ -d /var/lib/php5 ] && /usr/lib/php5/sessionclean /var/lib/php5 $(/usr/lib/php5/maxlifetime) root 24691 0.0 0.0 4192 472 ? S 20:09 0:00 | \_ /bin/sh /usr/lib/php5/sessionclean /var/lib/php5 24 root 24692 0.0 0.0 4244 556 ? S 20:09 0:00 | \_ /usr/bin/lsof -w -l +d /var/lib/php5 root 24695 0.0 0.0 4244 100 ? D 20:09 0:00 | | \_ /usr/bin/lsof -w -l +d /var/lib/php5 root 24693 0.0 0.0 6776 616 ? S 20:09 0:00 | \_ awk -- { if (NR > 1) { print $9; } } root 24694 0.0 0.0 4260 452 ? S 20:09 0:00 | \_ xargs -i touch -c {} root 26201 0.0 0.0 100796 5652 ? S 20:39 0:00 \_ /USR/SBIN/CRON root 26210 0.0 0.0 4192 480 ? Ss 20:39 0:00 | \_ /bin/sh -c [ -x /usr/lib/php5/maxlifetime ] && [ -x /usr/lib/php5/sessionclean ] && [ -d /var/lib/php5 ] && /usr/lib/php5/sessionclean /var/lib/php5 $(/usr/lib/php5/maxlifetime) root 26215 0.0 0.0 4192 492 ? S 20:39 0:00 | \_ /bin/sh /usr/lib/php5/sessionclean /var/lib/php5 24 root 26216 0.0 0.0 4244 520 ? S 20:39 0:00 | \_ /usr/bin/lsof -w -l +d /var/lib/php5 root 26219 0.0 0.0 4244 104 ? D 20:39 0:00 | | \_ /usr/bin/lsof -w -l +d /var/lib/php5 root 26217 0.0 0.0 6776 576 ? S 20:39 0:00 | \_ awk -- { if (NR > 1) { print $9; } } root 26218 0.0 0.0 4260 496 ? S 20:39 0:00 | \_ xargs -i touch -c {} root 27791 0.0 0.0 100796 5652 ? S 21:09 0:00 \_ /USR/SBIN/CRON root 27795 0.0 0.0 4192 488 ? Ss 21:09 0:00 | \_ /bin/sh -c [ -x /usr/lib/php5/maxlifetime ] && [ -x /usr/lib/php5/sessionclean ] && [ -d /var/lib/php5 ] && /usr/lib/php5/sessionclean /var/lib/php5 $(/usr/lib/php5/maxlifetime) root 27800 0.0 0.0 4192 508 ? S 21:09 0:00 | \_ /bin/sh /usr/lib/php5/sessionclean /var/lib/php5 24 root 27801 0.0 0.0 4244 512 ? S 21:09 0:00 | \_ /usr/bin/lsof -w -l +d /var/lib/php5 root 27804 0.0 0.0 4244 100 ? D 21:09 0:00 | | \_ /usr/bin/lsof -w -l +d /var/lib/php5 root 27802 0.0 0.0 6776 560 ? S 21:09 0:00 | \_ awk -- { if (NR > 1) { print $9; } } root 27803 0.0 0.0 4260 444 ? S 21:09 0:00 | \_ xargs -i touch -c {}

Entweder es gibt ein gravierendes Problem mit dem Filesystem von /var/lib/php5 oder es sind einfach zu viele Dateien dort drin.

Viele Grüße,
Dirk Ahrnke


#11

Danke für die schnelle Antwort!
Load ging noch auf 12k % hoch, dann war final Schluss…
Zum SATA-Problem hatte ich auch schon verschiedene Hinweise gefunden, vom ext4-Bug bis hin zu Bugs des verwendendeten Asmedia-Controllers, ich werde das parallel im Auge behalten, habe nur leider keine Möglichkeit, den Controller zu tauschen (Intel NUC-Board mit mini PCIe SATA-Controller).
Alternativ kann ich noch den onboard Controller nutzen, dann aber kein RAID über mdadm bauen.
Auf einem anderen System (PC Engines AMD APU1C4) trat das Fehlerbild allerdings auch mit einem anderen (onboard) Controller (ATI SB7x0/SB8x0/SB9x0 SATA Controller) identisch auf.

/var/lib/php5 ist leer, zumindest aktuell:

root@ucs:/var/lib/php5# ls -lah
insgesamt 8,0K
drwx-wx-wt  2 root root 4,0K Feb  3 23:02 .
drwxr-xr-x 65 root root 4,0K Mär 29 20:06 ..
root@ucs:/var/lib/php5#

inodes sind ebenfalls nur zu 1% in Nutzung.
Ich versuche, das System nochmals unter Last zu setzen, und prüfen, ob dann dort Dateien vorliegen…


#12

Hallo,

noch mal zum PHP:

Ich bin da heute früh falsch abgebogen. Das hängt u.U. beim lsof, welches nachsieht, welche Prozesse Dateien in /var/lib/php5 offen haben.

[code]# cat /usr/lib/php5/sessionclean
#!/bin/sh

first find all used files and touch them (hope it’s not massive amount of files)

[ -x /usr/bin/lsof ] && /usr/bin/lsof -w -l +d “${1}” | awk – ‘{ if (NR > 1) { print $9; } }’ | xargs -i touch -c {}

find all files older then maxlifetime

find “${1}” -depth -mindepth 1 -maxdepth 1 -ignore_readdir_race -type f -cmin “+${2}” -delete
[/code]

Man sollte also mal nachschauen, ob sich dort etwas aufbaut.

# /usr/bin/lsof -w -l +d /var/lib/php5

Viele Grüße,
Dirk Ahrnke


#13

Das System lief jetzt einige Wochen stabil, nachdem ich eine (NFS-)Freigabe nicht mehr für Streaming (Aufnahme/Wiedergabe über eine Linux SAT-Box) genutzt habe.
Nachdem ich die Freigabe mal wieder auf dem Receiver gemountet habe, ging auch die Last wieder hoch, allerdings nicht sofort, sondern mit deutlicher Verzögerung von einigen Tagen.
Laut Statistik begann der Anstieg heute um 0:00 Uhr - deutet also auf einen Cron-Job o.ä. der zu dem Zeitpunkt zum Problem geführt hat.

/usr/bin/lsof -w -l +d /var/lib/php5

liefert leider kein Ergebnis (Abfrage hängt)


#14

Hallo,

dieses “Hängen” des lsof könnte letztendlich der Grund sein, weswegen die PHP Maintenance-Skripte nicht fertig werden und sich stapeln.
Über grundsätzliche Probleme von UCS mit NFS-Shares ist mir nichts bekannt, im Gegenteil. Wir nutzen z.B. für den UVMM seit Jahren Disk-Images auf NFS.

Ich habs zwar selbst noch nicht gesehen, aber es gibt diverse Hinweise im Netz, dass df und lsof hängen wenn der NFS-Mount defekt (“stale”) ist.

Viele Grüße,
Dirk Ahrnke


#15

Hallo Herr Ahrnke,

der NFS-Mount kann eigentlich nicht stale sein, denn er funktionierte zu dem Zeitpunkt noch - allerdings nicht mehr die SMB-Shares, hier ist es in dem Zustand dann auch nicht möglich den Dienst neu zu starten.


#16

Hallo,

ich würd gern mal kurz meinen Eindruck zusammenfassen:

Aus bisher nicht bekannten Gründen wird ein “lsof” nicht fertig.
“lsof” wird durch /etc/cron.d/php5 alle 30 Minuten aufgerufen. Diese Skripte prüfen nicht, ob noch eine andere Instanz läuft.
In der Folge werden immer mehr Instanzen der Skripte gestartet und die System-Auslastung steigt

Wenn man das Problem bei der Wurzel packen will, müsste man herausfinden, warum “lsof” sich derartig verhält.
Bis dahin könnte man überlegen, die PHP5 Skripte zeitweise zu deaktivieren und bei Bedarf manuell zu starten.

Viele Grüße,
Dirk Ahrnke


#17

Hallo,

evtl. habe ich die Ursache gefunden - die Systemzeit war nicht korrekt, da NTP zwar konfiguriert aber nicht aktiviert war.
Möglicherweise kam es dadurch insbesondere unter Last (Anlage neuer VMs) zu starkem Jitter, was wiederum Probleme mit den Prozessen verursachte.
Zuletzt wich die Zeit ca. 1 Stunde ab…
Ich müsste noch die ntp Logs hierzu durchforsten.
Seit ca. drei Wochen läuft das System soweit stabil.