www.fabiankeil.de/blog-surrogat/2006/06/27/unbeabsichtigte-zwiebelsuppen-sendepausen.html

Unbeabsichtigte Zwiebelsuppen-Sendepausen

Bis heute gab mir der frisch eingerichtete Server bereits drei mal die Gelegenheit, die Funktionsfähigkeit von Stratos Webinterface-Reset zu testen – funktioniert.

[Balken-Diagramm des Tages-Durchsatzes von tor.fabiankeil.de. Am 24. und 25. etwa 100 GigaByte, am 26. nur 25] Irgendwann hört tor.fabiankeil.de einfach auf zu arbeiten, ohne das ich wüsste warum. Protokollierte Fehlermeldungen gibt es keine, die serielle Schnittstelle ist reaktionslos, der Reset die einzige Reanimations-Möglichkeit.

Die außerplanmäßige Sendepause in der vorletzten Nacht hatte noch keine deutlichen Auswirkungen auf die Bandbreiten-Statistik, doch der Ausfall in der vergangenen Nacht sorgte für eine Viertelung des Durchsatzes.

[Grafik: 24-Stunden-Durchsatz. Zwei deutlichtbare Sende-Unterbrechungen.] Beim dritten Ausfall war ich Live dabei, er dauerte daher nur ein paar Minuten, unterbrach aber nicht nur den Tor-Betrieb, sondern auch meinen Versuch von RELENG_6_1 auf RELENG_6 zu wechseln.

Während den ersten beiden Sendepausen war nur Tor aktiv, die Auslastung wenige Minuten vor dem zweiten Ausfall:

last pid:  7996;  load averages:  0.40,  0.37,  0.36  up 0+18:38:25    05:55:02
83 processes:  2 running, 66 sleeping, 15 waiting
CPU states: 21.3% user,  0.0% nice, 17.8% system, 20.2% interrupt, 40.7% idle
Mem: 100M Active, 157M Inact, 102M Wired, 12K Cache, 60M Buf, 134M Free
Swap: 1024M Total, 1024M Free

  PID USERNAME  THR PRI NICE   SIZE    RES STATE    TIME   WCPU COMMAND
   11 root        1 171   52     0K     8K RUN    857:30 53.61% idle
   12 root        1 -44 -163     0K     8K WAIT    45:22  6.54% swi1: net
   23 root        1 -68 -187     0K     8K WAIT    14:48  2.83% irq12: fxp0 fxp1
 7973 root        1  96    0  2264K  1544K RUN      0:00  0.51% top
   13 root        1 -32 -151     0K     8K WAIT     5:49  0.10% swi4: clock sio
   33 root        1 171   52     0K     8K pgzero   0:02  0.10% pagezero
    3 root        1  -8    0     0K     8K -        0:16  0.05% g_up
 1586 _tor       14  20    0    99M 97912K kserel 188:36  0.00% tor
   15 root        1 -16    0     0K     8K -        1:01  0.00% yarrow
 1443 root        1  -8    0     0K     8K geli:w   0:49  0.00% g_eli[0] md0
    4 root        1  -8    0     0K     8K -        0:21  0.00% g_down
   35 root        1  20    0     0K     8K syncer   0:17  0.00% syncer
 1439 root        1  -8    0     0K     8K mdwait   0:13  0.00% md0
   24 root        1 -64 -183     0K     8K WAIT     0:08  0.00% irq14: ata0
    2 root        1  -8    0     0K     8K -        0:07  0.00% g_event
   42 root        1 -16    0     0K     8K -        0:06  0.00% schedcpu
  453 root        1  96    0  2920K  1752K select   0:05  0.00% ntpd
  256 _pflogd     1 -58    0  1548K  1216K bpf      0:05  0.00% pflog

Die letzte Paket-Filter-Statistik:

Status: Enabled for 0 days 18:37:52           Debug: Urgent

Hostid: 0x1ec3da6b

Interface Stats for fxp0              IPv4             IPv6
  Bytes In                     25077859159                0
  Bytes Out                    27498863362                0
  Packets In
    Passed                        36192760                0
    Blocked                          32213                0
  Packets Out
    Passed                        36871432                0
    Blocked                            265                0

State Table                          Total             Rate
  current entries                     5290               
  searches                        73567507         1096.8/s
  inserts                           600068            8.9/s
  removals                          594778            8.9/s
Counters
  match                             752600           11.2/s
  bad-offset                             0            0.0/s
  fragment                             102            0.0/s
  short                                  0            0.0/s
  normalize                              2            0.0/s
  memory                                68            0.0/s
  bad-timestamp                          0            0.0/s
  congestion                             0            0.0/s
  ip-option                              0            0.0/s
  proto-cksum                            0            0.0/s
  state-mismatch                     12655            0.2/s
  state-insert                           0            0.0/s
  state-limit                            0            0.0/s
  src-limit                              2            0.0/s
  synproxy

Spekulationen

kern/95180 klingt von den Symptomen beängstigend ähnlich, automatische Core-Dumps hatte ich allerdings noch nicht eingerichtet. und möglicherweise wartete der Server auch mit einer Panik auf Benutzereingabe und war deshalb unerreichbar. Auch DDB war noch nicht aktiviert, wahrscheinlich blieb die serielle Console deshalb stumm.

Hardware-Fehler könnten zwar zu den gleichen Symptomen führen, ich gehe aber davon aus, dass Strato den Server vor der Übergabe getestet hat.

Zweiter Versuch

Der neue Kernel ist bereits installiert, im zweiten Anlauf führt hoffentlich auch make buildworld zum Erfolg. Die Last scheint bis jetzt keine Probleme zu machen:

last pid: 90289;  load averages:  1.23,  1.19,  1.00    up 0+02:40:36  16:20:19
54 processes:  3 running, 51 sleeping
CPU states: 70.4% user,  0.0% nice, 20.6% system,  8.9% interrupt,  0.0% idle
Mem: 133M Active, 205M Inact, 108M Wired, 12M Cache, 60M Buf, 36M Free
Swap: 1024M Total, 1024M Free

  PID USERNAME  THR PRI NICE   SIZE    RES STATE    TIME   WCPU COMMAND
  814 _tor       13 107    0 82528K 79624K RUN     19:58  0.00% tor
  440 bind        1  96    0 33156K 31888K select   0:18  0.00% named
72116 fk          1  96    0  6292K  2460K select   0:03  0.00% sshd
76652 fk          1  96    0  2344K  1612K RUN      0:01  0.00% top
  254 _pflogd     1 -58    0  1548K  1044K bpf      0:01  0.00% pflogd
  513 root        1  96    0  2920K  1432K select   0:01  0.00% ntpd
72056 fk          1  96    0  6080K  2328K select   0:01  0.00% sshd
89651 fk          1   8    0  4600K  4460K wait     0:00  0.00% make
  370 root        1  96    0  1300K   852K select   0:00  0.00% syslogd
72057 fk          1   8    0  3132K  1704K wait     0:00  0.00% bash
90288 fk          1 122    0  5932K  5172K RUN      0:00  0.00% cc1
72117 fk          1   8    0  3132K  1752K wait     0:00  0.00% bash
  558 root        1   8    0  1312K   908K nanslp   0:00  0.00% cron
72053 root        1   4    0  6104K  2336K sbwait   0:00  0.00% sshd
  608 fk          1   5    0  3120K  1568K ttyin    0:00  0.00% bash
72113 root        1   4    0  6104K  2340K sbwait   0:00  0.00% sshd
  865 root        1   8    0  1312K   788K nanslp   0:00  0.00% cron
77987 fk          1   8    0   764K   620K wait     0:00  0.00% make
  793 root        1  96    0  1300K   764K select   0:00  0.00% syslogd
  607 root        1   8    0  1620K  1108K wait     0:00  0.00% login
87296 fk          1   8    0   756K   612K wait     0:00  0.00% make
89642 fk          1   8    0   580K   436K wait     0:00  0.00% make
77870 fk          1   8    0   536K   384K wait     0:00  0.00% make
  249 root        1   4    0  1484K   972K sbwait   0:00  0.00% pflogd
  535 root        1  96    0  3356K  2008K select   0:00  0.00% sshd
89643 fk          1   8    0  1636K  1208K wait     0:00  0.00% sh
88555 fk          1   8    0  1632K  1204K wait     0:00  0.00% sh
77985 fk          1   8    0  1636K  1228K wait     0:00  0.00% sh
  600 root        1   5    0  1268K   784K ttyin    0:00  0.00% getty
  599 root        1   5    0  1268K   784K ttyin    0:00  0.00% getty