Root-Server hängt wiederholt mit I/O errors im Kernellog

  • Seit Donnerstag-Nacht nach dem ich lokal ein größeren Verzeichnis kopiert habe, hängt der Server jetzt öfter, mal für Minuten, mal für Stunden. In dieser Zeit ist nicht einmal das Server Control Panel erreichbar. Laut Support liegt keine Störung am Node vor. Er behauptet das Problem liegt wahrscheinlich eher auf meiner Seite.



    e2fsck lieferte keine Fehler.




    Da ich einen Cron-Job habe, der jede Minute läuft, und auch der Cron-Job selbst um Stunden verzögert wird, kann man die Störungen gut nachvollziehen.
    Gestern hing er von 8:42 bis 9:46, von 14:28 bis 18:08, heute von 6:28 bis 8:58 von 10:50 bis 11:02 und gerade eben von 11:17 nochmal.


    Ich benutze Ubuntu 16.04.1 LTS, Kernel ist GNU/Linux 4.4.0-72-generic x86_64


    Im Kernel Log gibt es mehrere verdächtige Logs, die jetzt immer wieder auftreten, vorher aber noch nie aufgetreten sind:


    Die folgenden Meldungen erscheinen fast ständig:

    Code
    1. kernel: [ 1796.261789] sd 2:0:0:0: [sda] tag#46 abortkernel: [ 1796.261805] sd 2:0:0:0: [sda] tag#45 abortkernel: [ 1796.261821] sd 2:0:0:0: [sda] tag#44 abortkernel: [ 1796.261837] sd 2:0:0:0: [sda] tag#43 abortkernel: [ 1796.261853] sd 2:0:0:0: [sda] tag#42 abortkernel: [ 1796.261864] sd 2:0:0:0: [sda] tag#41 abort




    Ab und zu auch:

    Code
    1. kernel: [690458.738413] sd 2:0:0:0: [sda] tag#70 abortkernel: [690458.741982] sd 2:0:0:0: [sda] tag#70 FAILED Result: hostbyte=DID_TIME_OUT driverbyte=DRIVER_OKkernel: [690458.741988] sd 2:0:0:0: [sda] tag#70 CDB: Read(10) 28 00 00 ba 68 70 00 00 08 00kernel: [690458.741990] blk_update_request: I/O error, dev sda, sector 12216432kernel: [690458.742191] sd 2:0:0:0: [sda] tag#69 abortkernel: [690458.742229] sd 2:0:0:0: [sda] tag#69 FAILED Result: hostbyte=DID_TIME_OUT driverbyte=DRIVER_OKkernel: [690458.742232] sd 2:0:0:0: [sda] tag#69 CDB: Read(10) 28 00 00 ba 68 68 00 00 08 00kernel: [690458.742234] blk_update_request: I/O error, dev sda, sector 12216424kernel: [690458.742600] sd 2:0:0:0: [sda] tag#68 abortkernel: [690458.742628] sd 2:0:0:0: [sda] tag#68 FAILED Result: hostbyte=DID_TIME_OUT driverbyte=DRIVER_OKkernel: [690458.742631] sd 2:0:0:0: [sda] tag#68 CDB: Read(10) 28 00 00 ba 68 60 00 00 08 00kernel: [690458.742632] blk_update_request: I/O error, dev sda, sector 12216416kernel: [690458.742827] sd 2:0:0:0: [sda] tag#67 abortkernel: [690458.742852] sd 2:0:0:0: [sda] tag#67 FAILED Result: hostbyte=DID_TIME_OUT driverbyte=DRIVER_OKkernel: [690458.742854] sd 2:0:0:0: [sda] tag#67 CDB: Read(10) 28 00 00 ba 68 58 00 00 08 00kernel: [690458.742856] blk_update_request: I/O error, dev sda, sector 12216408


    Häufig sind auch Logs über hängende Prozesse:

    Code
    1. kernel: [ 1920.303408] INFO: task perl:4916 blocked for more than 120 seconds.kernel: [ 1920.303464] Not tainted 4.4.0-72-generic #93-Ubuntukernel: [ 1920.303503] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.kernel: [ 1920.303564] perl D ffff8801b63cf538 0 4916 4860 0x00000002kernel: [ 1920.303568] ffff8801b63cf538 ffff8800b81ced70 ffff8800b80ec600 ffff8801b4652a00kernel: [ 1920.303572] ffff8801b63d0000 ffff8801bfc16dc0 7fffffffffffffff ffffffff81838d60kernel: [ 1920.303576] ffff8801b63cf698 ffff8801b63cf550 ffffffff81838565 0000000000000000kernel: [ 1920.303579] Call Trace:kernel: [ 1920.303583] [<ffffffff81838d60>] ? bit_wait+0x60/0x60kernel: [ 1920.303586] [<ffffffff81838565>] schedule+0x35/0x80kernel: [ 1920.303589] [<ffffffff8183b6b5>] schedule_timeout+0x1b5/0x270kernel: [ 1920.303595] [<ffffffff813c4189>] ? queue_unplugged+0x39/0xb0kernel: [ 1920.303598] [<ffffffff8106428e>] ? kvm_clock_get_cycles+0x1e/0x20kernel: [ 1920.303600] [<ffffffff81838d60>] ? bit_wait+0x60/0x60kernel: [ 1920.303603] [<ffffffff81837a94>] io_schedule_timeout+0xa4/0x110kernel: [ 1920.303605] [<ffffffff81838d7b>] bit_wait_io+0x1b/0x70kernel: [ 1920.303607] [<ffffffff8183890d>] __wait_on_bit+0x5d/0x90kernel: [ 1920.303610] [<ffffffff81838d60>] ? bit_wait+0x60/0x60kernel: [ 1920.303612] [<ffffffff818389c2>] out_of_line_wait_on_bit+0x82/0xb0kernel: [ 1920.303615] [<ffffffff810c4250>] ? autoremove_wake_function+0x40/0x40kernel: [ 1920.303619] [<ffffffff812467f2>] __wait_on_buffer+0x32/0x40kernel: [ 1920.303621] [<ffffffff81292477>] ext4_wait_block_bitmap+0x47/0xa0kernel: [ 1920.303627] [<ffffffff812d30c5>] ext4_mb_init_cache+0x205/0x770kernel: [ 1920.303630] [<ffffffff812d3745>] ext4_mb_init_group+0x115/0x210kernel: [ 1920.303632] [<ffffffff812d3cce>] ext4_mb_load_buddy_gfp+0x30e/0x340kernel: [ 1920.303635] [<ffffffff811918f5>] ? mempool_alloc_slab+0x15/0x20kernel: [ 1920.303638] [<ffffffff812d5a67>] ext4_mb_find_by_goal+0xb7/0x2e0


    Während ich es schreibe gab es weiter I/O error, die zum Read-Only mounten des Dateisystems führten:


    Code
    1. [127882.837484] sd 2:0:0:0: [sda] tag#57 FAILED Result: hostbyte=DID_TIME_OUT driverbyte=DRIVER_OK[127882.837487] sd 2:0:0:0: [sda] tag#57 CDB: Read(10) 28 00 00 7a 3e 78 00 00 08 00[127882.837489] blk_update_request: I/O error, dev sda, sector 8011384[127882.837597] sd 2:0:0:0: [sda] tag#56 abort[127882.837669] sd 2:0:0:0: [sda] tag#56 FAILED Result: hostbyte=DID_TIME_OUT driverbyte=DRIVER_OK[127882.837672] sd 2:0:0:0: [sda] tag#56 CDB: Read(10) 28 00 00 7a 3e 70 00 00 08 00[127882.837674] blk_update_request: I/O error, dev sda, sector 8011376[...][127882.851970] Aborting journal on device sda3-8.[127882.875877] EXT4-fs (sda3): Remounting filesystem read-only[127882.875945] EXT4-fs error (device sda3) in ext4_reserve_inode_write:5128: IO failure[127882.883124] EXT4-fs error (device sda3) in ext4_dirty_inode:5251: IO failure



    PS: Die Zeilenumbrüche wurden automatisch von der Forensoftware entfernt. Ich habe es nochmal besser formatiert angehängt.

  • Was hast Du denn schon alles überprüft und als Fehlerursache ausgeschlossen?
    - Platte voll?
    - Minütlicher Cron: darf der sich überschneiden? Stauen sich da ggf. hunderte Crons auf und legen das System lahm?
    - mal alles abgeschaltet um zu sehen ob der Fehler dann noch auftritt?
    - munin installiert um die Systemwerte durchgehend nachvollziehen zu können?
    - welche Prozesse laufen?
    - was verursacht ggf. i/o-wait?



    Google spuckt für einige der Logeinträge durchaus auch kaputte Platten aber auch QEMU-Bugs als Ursache aus.
    Leider kommt man hier wegen QEMU mit smartctl & co nicht weiter.
    Ich vermute aber mal, dass NetCUP, das gleiche Setup hier 10000e mal im Einsatz hat und bei so grundlegenden Problemen dies schon bemerkt hätte. Erfahrungsgemäß sind erstaunlich viele "Ausfälle" selbst gemacht.

  • Die Hauptlast auf dem Server ist durch einen bitcoin full node erzeugt. Für vier Monate lief die Konfiguration nahezu problemlos (es gab allerdings einen kompletten Node-Ausfalll am 18. März, der ohne, dass ich es melden musste, von netcup behoben wurde). Jetzt tritt das Problem immer wieder alle paar Stunden auf. Währenddessen hängen auch Bereiche des SCP-Panels vor allem der Medien-Tab hängt häufig. Dann scheint wieder für ein paar Stunden alles zu funktionieren.


    Festplatte ist zu 50 % frei auf beiden Partitionen


    Ich versuche gerade ohne Last (ohne bitcoin node und ohne cron job) eine Weile laufen zu lassen, aber er fühlt sich auch jetzt träge an.


    Da das Problem von selbst wieder nach einiger Zeit verschwindet, ist es schwierig, es genau zu fassen. Ich habe auch im Rettungssystem die Fehler gehabt, nachdem ich mit resize2fs ordentlich Last erzeugt habe (im Nachhinein eine blöde Idee, jetzt muss ich hoffen, dass es das Dateisystem nicht zerschossen hat, nachdem es Stunden später abgebrochen ist).


    hdparm liefert im Rettungssystem nur 9-30 MB/sec:


    Code
    1. v22016103144138861:~# hdparm -tT /dev/sda/dev/sda: Timing cached reads: 17048 MB in 2.00 seconds = 8533.55 MB/sec Timing buffered disk reads: 52 MB in 3.11 seconds = 16.72 MB/secv22016103144138861:~# hdparm -tT /dev/sda/dev/sda: Timing cached reads: 17460 MB in 2.00 seconds = 8744.19 MB/sec Timing buffered disk reads: 52 MB in 3.15 seconds = 16.51 MB/secv22016103144138861:~# hdparm -tT --direct /dev/sda/dev/sda: Timing O_DIRECT cached reads: 4244 MB in 2.00 seconds = 2121.93 MB/sec Timing O_DIRECT disk reads: 78 MB in 3.01 seconds = 25.88 MB/secv22016103144138861:~# hdparm -tT --direct /dev/sda/dev/sda: Timing O_DIRECT cached reads: 3622 MB in 2.00 seconds = 1811.12 MB/sec Timing O_DIRECT disk reads: 74 MB in 3.00 seconds = 24.66 MB/sec


  • ohne viel hier beitragen zu können würde mich mal interessieren welches Root-Server produkt du hier einsetzt?


    edit: benutzt du den korrekten disktreiber?


    mir ist soeben aufgefallen, dass einer meiner älteren RS L SSD auf virtio lief und ähnlich bescheidene ergebnisse produzierte..

    Code
    1. sudo hdparm -tT --direct /dev/vda1
    2. /dev/vda1:
    3. Timing O_DIRECT cached reads: 1142 MB in 2.00 seconds = 570.65 MB/sec
    4. Timing O_DIRECT disk reads: 54 MB in 3.29 seconds = 16.40 MB/sec


    nach wechsel auf den empfohlenen scsi treiber sah es dann besser aus (würde ein backup empfehlen)

    Code
    1. hdparm -tT --direct /dev/sda2
    2. /dev/sda2:
    3. Timing O_DIRECT cached reads: 1800 MB in 2.01 seconds = 896.30 MB/sec
    4. Timing O_DIRECT disk reads: 466 MB in 0.23 seconds = 2042.78 MB/sec
  • den Treiber kannst du im SCP beim jeweiligen Server unter Medien umstellen.


    Ah, danke für die Info.


    Aber warum kann man den Treiber überhaupt umstellen, wenn SCSI die klare Empfehlung ist? Oder hängt die Empfehlung vom installierten Betriebssystem ab?


    Bei meinem Root-Server M SSD v6 ist aktuell VIRTIO eingestellt. Kann ich den Server einfach runterfahren, die Einstellung ändern und den Server dann wieder starten? Oder muß unter Debian 8.7 dazu irgendwas umkonfiguriert werden?

  • Ich denke es gibt Spezialfälle, wo auch VirtIO Sinn macht.
    Die Umstellung sollte so funktionieren, SCSI wird ja vom System nativ unterstützt, eine Treiberaktivierung sollte also von Debian beim Neustart automatisch erfolgen. Falls es doch nicht funktioniert, kannst du ja wieder auf VirtIO zurückstellen.

  • Je nach OS werden bestimmte Treiber gar nicht unterstützt oder sind verbuggt. Deshalb wurde diese Einstellungsmöglichkeit geschaffen.


    Wenn Du UUIDs in der /etc/fstab verwendest, sollte es bei der Umstellung zu keinen Problemen kommen. Besondere Sonderfälle oder Konfiguration mit fixen Gerätenamen einmal ausgenommen, aber die kennt man als Admin normalerweise eh.



    MfG Christian

  • Seit dem ich mal ein


    Code
    1. fstrim -v /home


    ausgeführt habe, läuft der Server jetzt wieder einigermaßen stabil (seit drei Tagen keine Hänger mehr). Die 'hdparm -t /dev/sda' Performance ist allerdings immer noch nicht gut.
    Merkwürdigerweise haben /dev/sda, /dev/sda3 und /dev/sda4 stark unterschiedliche Werte (15, 30 und 110 MB/sec).


    fstrim sagt ja dem Host-Betriebssystem, welche Blöcke der simulierten HDD es nicht zu speichern braucht, weil diese nicht (mehr) mit Daten belegt sind. Das 'fstrim -v' Kommando kenne ich noch gut von meiner alten SSD, bei der die Schreibperformance durch dieses Kommando zumindest kurzfristig wiederhergestellt werden konnte. Sonst kam es vor, dass beim abspeichern einer wenige KB großen Datei der Rechner für Minuten hing.

  • Seit dem ich mal ein

    Code
    1. fstrim -v /home


    ausgeführt habe, läuft der Server jetzt wieder einigermaßen stabil (seit drei Tagen keine Hänger mehr).


    Dann kannst du ja das Dateisystem zumindest zusätzlich mit der Option "discard" mounten, was die eigenständige, regelmäßige Ausführung von "fstrim" hinfällig lassen werden sollte.

  • Ich denke das Hauptproblem war, dass mein Cron-Job der minütlich Statistiken geführt hat, ziemlich viel auf die Platte geschrieben hat.


    Er hat jede Minute die Webseite mit der Statistik aktualisiert (damit er die Seiten dann statisch ausliefern kann). Mit allem drum und dran und temporären Dateien, die ebenfalls auf die Platte geschrieben wurden waren es am Ende um die 100 MB pro Minute also 1 TB pro Woche, was der Host auf Dauer wohl nicht so sehr mochte. Die vorherigen Dateien wurden überschrieben, die Platte wurde also nicht gefüllt. Es erklärt jetzt auch, warum fstrim soviel freigeben konnte. Ich war ein wenig überrascht über die atop-Statistik, dass es soviel schreibt.


    Ich habe jetzt alles optimiert und schreibe die dynamischen Seiten (jetzt nur noch 4MB) nach /dev/shm, sodass der Cron-Job fast überhaupt keine Plattenschreibzugriffe mehr macht (bis auf die paar Bytes, die dauerhaft in die Datenbank eingetragen werden).


    Fazit: Wenn man dynamische Webseiten statisch jede Minute neu generiert, dann am besten nach /dev/shm ;)