[Eisfair] Absturz, Log-Datei vor dem Absturz

[Marcus Roeckrath]

Hallo Alex,

habe ein wenig in Deine gesammelten Daten reingeschaut; ier mal der
kritische Zeitpunkt vom 12.2. ab 13:25.

1. Die Load steigt urplötzlich an:

top - 13:25:00 up 1 day, 12:10,  9 users,  load average: 0.07, 0.03, 0.05
top - 13:30:00 up 1 day, 12:15,  9 users,  load average: 3.87, 2.00, 0.83
top - 13:35:00 up 1 day, 12:20,  9 users,  load average: 4.00, 3.27, 1.70
top - 13:40:00 up 1 day, 12:25,  8 users,  load average: 4.05, 3.76, 2.35
top - 13:45:00 up 1 day, 12:30,  8 users,  load average: 4.08, 3.99, 2.84
top - 13:50:00 up 1 day, 12:35,  8 users,  load average: 4.15, 4.07, 3.19
top - 13:55:00 up 1 day, 12:40,  8 users,  load average: 4.03, 4.06, 3.43
top - 14:00:00 up 1 day, 12:45,  8 users,  load average: 4.08, 4.06, 3.60
top - 14:05:00 up 1 day, 12:50,  8 users,  load average: 4.12, 4.08, 3.73
top - 14:10:00 up 1 day, 12:55,  9 users,  load average: 4.08, 4.10, 3.84
top - 14:15:00 up 1 day, 13:00, 10 users,  load average: 4.09, 4.06, 3.89
top - 14:20:00 up 1 day, 13:05,  9 users,  load average: 4.25, 4.09, 3.94
top - 14:25:00 up 1 day, 13:10,  9 users,  load average: 4.01, 4.06, 3.97
top - 14:30:00 up 1 day, 13:15,  9 users,  load average: 4.02, 4.06, 3.99
top - 14:35:00 up 1 day, 13:20,  9 users,  load average: 4.00, 4.02, 3.99
top - 14:40:00 up 1 day, 13:25,  9 users,  load average: 4.12, 4.08, 4.02
top - 14:45:00 up 1 day, 13:30,  8 users,  load average: 4.06, 4.09, 4.05
top - 14:50:00 up 1 day, 13:35,  8 users,  load average: 4.01, 4.04, 4.05
top - 14:55:00 up 1 day, 13:40,  8 users,  load average: 4.00, 4.01, 4.05
top - 15:00:00 up 1 day, 13:45,  8 users,  load average: 4.12, 4.08, 4.06
top - 15:05:00 up 1 day, 13:50,  8 users,  load average: 4.03, 4.05, 4.05
top - 15:10:00 up 1 day, 13:55,  7 users,  load average: 4.05, 4.05, 4.05
top - 15:15:00 up 1 day, 14:00,  6 users,  load average: 4.09, 4.06, 4.05
top - 15:20:00 up 1 day, 14:05,  6 users,  load average: 4.06, 4.07, 4.05
top - 15:25:00 up 1 day, 14:10,  4 users,  load average: 4.00, 4.04, 4.05
top - 15:30:00 up 1 day, 14:15,  4 users,  load average: 4.13, 4.09, 4.06
top - 15:35:00 up 1 day, 14:20,  4 users,  load average: 4.21, 4.13, 4.07
top - 15:40:00 up 1 day, 14:25,  4 users,  load average: 4.00, 4.06, 4.05
top - 15:45:00 up 1 day, 14:30,  4 users,  load average: 4.09, 4.07, 4.05
top - 15:50:00 up 1 day, 14:35,  4 users,  load average: 4.06, 4.07, 4.05
top - 15:55:00 up 1 day, 14:40,  4 users,  load average: 4.01, 4.04, 4.05
top - 16:00:00 up 1 day, 14:45,  4 users,  load average: 4.00, 4.02, 4.05
top - 16:05:00 up 1 day, 14:50,  4 users,  load average: 4.15, 4.14, 4.10
top - 16:10:00 up 1 day, 14:55,  4 users,  load average: 4.09, 4.14, 4.12
top - 16:15:00 up 1 day, 15:00,  4 users,  load average: 4.06, 4.07, 4.09
top - 16:20:00 up 1 day, 15:05,  4 users,  load average: 4.26, 4.14, 4.12
top - 16:25:00 up 1 day, 15:10,  4 users,  load average: 4.51, 4.37, 4.24
top - 16:30:00 up 1 day, 15:15,  4 users,  load average: 4.02, 4.17, 4.20
top - 16:35:00 up 1 day, 15:20,  4 users,  load average: 4.01, 4.07, 4.14
top - 16:40:00 up 1 day, 15:25,  4 users,  load average: 4.19, 4.15, 4.15
top - 16:45:00 up 1 day, 15:30,  4 users,  load average: 4.38, 4.33, 4.23

Von einer ganz normalen Load um 13:25 springt sie dann auf knapp 4 und
erholt sich nicht mehr.

2. messages 13:25-13:27:36

Feb 12 13:25:00 myeis fcron[31074]: Job '/bin/bash /data/vol-bac/mon'
started for user root (pid 31075)
Feb 12 13:25:02 myeis fcron[31074]: Job '/bin/bash /data/vol-bac/mon'
completed
Feb 12 13:25:21 myeis OVPN_server[3435]: alap/185.10.94.1:1194 Need IPv6
code in mroute_extract_addr_from_packet
Feb 12 13:26:50 myeis apcupsd[3823]: Communications with UPS lost.
Feb 12 13:27:36 myeis kernel: INFO: rcu_sched detected stall on CPU 1
(t=15000 jiffies)
Feb 12 13:27:36 myeis kernel: Pid: 3652, comm: smbd Tainted: G           O
3.2.75-eisfair-1-VIRT #1
Feb 12 13:27:36 myeis kernel: Call Trace:
Feb 12 13:27:36 myeis kernel:  [__rcu_pending+0x64/0x28f]
__rcu_pending+0x64/0x28f

Jetzt knallt der Kernel einen Trace mit der Prozess-ID 3652 (smbd) raus.
Dieser Prozess sieht in der top-Ausgabe aber unauffällig aus.

Das wiederholt sich, bis (Stunden später; Ende gegen 16:45) nichts mehr
geht, wobei irgendwann der OOM-Killer ins Spiel kommt.

3. Ram um 13:30:

MemTotal:        6235724 kB
MemFree:          264948 kB
Buffers:          380672 kB
Cached:          4236428 kB
SwapCached:          188 kB
Active:          3215236 kB
Inactive:        2504116 kB
Active(anon):     958904 kB
Inactive(anon):   144764 kB
Active(file):    2256332 kB
Inactive(file):  2359352 kB
Unevictable:           0 kB
Mlocked:               0 kB
HighTotal:       5377992 kB
HighFree:          91296 kB
LowTotal:         857732 kB
LowFree:          173652 kB
SwapTotal:        265068 kB
SwapFree:         261936 kB
Dirty:               140 kB
Writeback:             0 kB
AnonPages:       1101908 kB
Mapped:            35940 kB
Shmem:              1408 kB
Slab:             224300 kB
SReclaimable:     204684 kB
SUnreclaim:        19616 kB
KernelStack:        2696 kB
PageTables:         7088 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:     3382928 kB
Committed_AS:    2477200 kB
VmallocTotal:     122880 kB

Es sind non ca. 260 MB frei, ein wenig ist geswapt; IMHO nichts
Ungewöhnliches.

Der RAM hat im Minimum noch ca. 80 MB frei, wobei mir die große Schwankung
über kurze Zeiträume auffällt; hier folgende Werte innerhalb 20 Minuten:

MemFree:         3873364 kB
MemFree:          183348 kB
MemFree:           82764 kB
MemFree:         1862152 kB

Beim Minimalstand geht kurzzeitig die Last auch auf 1,75 hoch, stabilisiert
sich aber beim nächsten Monitoring fünf Minuten später.

-- 
Gruss Marcus