raba34
Goto Top

Mdadm: Check dauert lange und verlangsamt Anwendungen

Hallo,

ich verwalte einen gemieteten dedizierten Server unter Ubuntu 20.04.4 LTS.

In ihm laufen zwei Platten mit einer Kapazität von jeweils 4 TB. Die beiden Partitionen md0 und md1 bilden jeweils ein RAID1-Array. md0 ist Bootpartition und hat eine Größe von ca. 1 GB. Den gewaltigen Rest von fast 4 TB bildet die Partition md1.

Am vergangenen Sonntag (6. März) bemerkte ich einen stark verlangsamten Aufbau der Webseiten. Ich fand heraus, dass ein Check der Festplatten begonnen hatte.

Nun habe ich im Internet ( https://www.thomas-krenn.com/de/wiki/Mdadm_checkarray ) den Hinweis gefunden, dass an jedem ersten Sonntag im Monat ein solcher Check durchführt wird. Das passt zusammen, wenngleich der Check nicht um 00:57 startete.

So weit, so (vielleicht) normal.

Jetzt kommt das, was mir auffällt

1.: Der Check dauerte fast ewig (von Sonntag 15:08 bis Dienstag 08:23), allerdings mit Unterbrechungen.
2.: Der Aufbau von Webseiten war während der Check-Zeit stark verlangsamt. (Shellzugriff war jedoch ohne Verzögerung möglich.)
3.: Der Server läuft seit Mitte Oktober 2021 ohne Unterbrechung. In der Zwischenzeit hat es schon viermal erste Sonntage im Monat gegeben. Eine so starke Beeinträchtigung hätte ich doch schon früher bemerken müssen.
4.: Ich finde im Bereich /etc/crontab keine Eintragungen für diesen Check.

Unten habe ich die betreffenden Zeilen aus der syslog zusammengestellt.

Wenn nicht in dieser Woche wegen des heutigen Feiertags in Berlin (Internationaler Frauentag) und des "Brückentags" gestern der Betrieb sehr ruhig gewesen wäre, hätte es bestimmt Anfragen gegeben, was denn los sei. Gegen den Check an sich ist nichts zu sagen. Aber dann darf die Performance doch nicht so stark zurückgehen. Soll ich die Nutzer etwa in einem Monat schon mal vorwarnen? Das kann doch wohl nicht sein.

Was meint ihr zu dem ganzen?

Gruß
Ralph

Mar 6 15:08:37 root: mdcheck start checking /dev/md0
Mar 6 15:08:37 kernel: [11811476.735370] md: data-check of RAID array md0
Mar 6 15:08:37 root: mdcheck start checking /dev/md1
Mar 6 15:08:37 kernel: [11811477.169149] md: delaying data-check of md1 until md0 has finished (they share one or more physical units)
Mar 6 15:08:44 kernel: [11811483.687029] md: md0: data-check done.
Mar 6 15:08:44 kernel: [11811483.700166] md: data-check of RAID array md1
Mar 6 15:10:37 root: mdcheck finished checking /dev/md0
Mar 6 21:08:52 kernel: [11833091.890776] md: md1: data-check interrupted.
Mar 6 21:08:52 root: pause checking /dev/md1 at 4168563968
Mar 7 05:17:27 root: mdcheck continue checking /dev/md1 from 4168563968
Mar 7 05:17:27 kernel: [11862406.477532] md: data-check of RAID array md1
Mar 7 11:17:48 kernel: [11884027.501836] md: md1: data-check interrupted.
Mar 7 11:17:48 root: pause checking /dev/md1 at 6919332096
Mar 8 04:57:33 root: mdcheck continue checking /dev/md1 from 6919332096
Mar 8 04:57:33 kernel: [11947613.320726] md: data-check of RAID array md1
Mar 8 08:22:51 kernel: [11959930.762606] md: md1: data-check done.
Mar 8 08:23:45 root: mdcheck finished checking /dev/md1

Content-Key: 2091499034

Url: https://administrator.de/contentid/2091499034

Printed on: May 8, 2024 at 18:05 o'clock

Member: Lochkartenstanzer
Lochkartenstanzer Mar 08, 2022 updated at 09:47:12 (UTC)
Goto Top
Moin,

Hast Du denn geprüft, ob die lange Dauer des Checks die Ursache oder das Symptom des Problems ist?

Check mal die Smartwerte der Laufwerke, ob die vielleicht erhöhte Lesefehlerraten haben.

Oder läuft gerade ein anderer Job, der durch Festplattenzugriffe sowohl den Check als auch die Webseiten bremst, z.B. Malware im Hintergrund.

Wie immer gilt: wer eine Korrelation findet, darf die Kausalität nicht frei heraussuchen, sondern muß erst prüfen ob wirklich eine Kausalität besteht oder eine gemeinsame Ursache.

lks

PS: Die Ursache kann auch andersherum sein: die Webseitenzugriffe bremsen den Check, so daß dieser länger braucht.

PPS: Meine Kristallkugel sagt übrigens, daß die lange Dauer des Checks Symptom und nicht Ursache des Problems ist.


Edit: Typo
Mitglied: 117471
117471 Mar 08, 2022 at 09:01:36 (UTC)
Goto Top
Hallo,

ich meine dazu, dass ich mich gerade eingelesen habe und seitdem stark zu LVM tendiere.

Alleine schon wegen der Abhängigkeit zur Hardware.

Gruß,
Jörg
Member: raba34
raba34 Mar 08, 2022 at 09:23:23 (UTC)
Goto Top
Zitat von @117471:

Hallo,

ich meine dazu, dass ich mich gerade eingelesen habe und seitdem stark zu LVM tendiere.

Alleine schon wegen der Abhängigkeit zur Hardware.

Gruß,
Jörg

@117471: Versehentlich falsch gepostet?
Member: Lochkartenstanzer
Lochkartenstanzer Mar 08, 2022 at 09:26:35 (UTC)
Goto Top
Zitat von @raba34:

Zitat von @117471:


@altmeier: Versehentlich falsch gepostet?

Nein, nur am Thema vorbei. face-smile

lks
Mitglied: 1915348599
1915348599 Mar 08, 2022 updated at 09:52:33 (UTC)
Goto Top
Zitat von @Lochkartenstanzer:
PPS: Meine Kristallkugel sagt übrigens, daß die lange Dauer des Checks Symptom und nicht Ursache des Problems ist.
Würde ich mich anschließen, zumal checkarray nur Idle-Zeit verbrät und die Arbeit unterbricht sobald wieder andere Arbeit ansteht.
Member: raba34
raba34 Mar 08, 2022 at 10:39:31 (UTC)
Goto Top
Hallo Lochkartenstanzer,

Zitat von @Lochkartenstanzer:

Moin,

Hast Du denn feprüft, ob die lange Dauer des Checks die Ursache oder das Symptom des Problems ist?

Check Mal die Smartwerte der Laufwerke, ob die vielleicht erhöhte Lesefehlerraten haben.

Oder läuft gerade ein anderer Job, der durch Festplattenzugriffe sowohl den Check als auch die Webseiten bremst, z.B. Malware im Hintergrund.

Wie immer gilt: wer eine Korrelation findet, darf die Kausalität nicht frei heraussuchen, sondern muß erst prüfen ob wirklich eine Kausalität besteht oder eine gemeinsame Ursache.

lks

PS: Die Ursache kann auch andersherum Hein: die Webseitenzugriffe bremsen den Check, so daß dieser länger braucht.

PPS: Meine Kristallkugel sagt übrigens, daß die lange Dauer des Checks Symptom und nicht Ursache des Problems ist.

Leider hatte ich eine Zeile vergessen:

Mar  6 15:08:37  systemd[1]: Starting MD array scrubbing...

Das brachte mich darauf, nach "scrub" zu suchen. Unter /etc/systemd/system/mdmonitor.service.wants/ fand ich dann die Datei, die den Vorgang am ersten Sonntag im Monat startet, und zwar mit einer zufallsbedingten Verschiebung um maximal 24 Stunden. Außerdem die Datei, die einen unterbrochenen Check fortsetzt. Der Datei /usr/share/mdadm/mdcheck wird mit der Option "--duration" die Dauer des Checks übertragen. Dies scheint standardmäßig 6 Stunden zu sein.

Damit ist geklärt, warum der Check überhaupt gestartet wurde und dass es ok ist, dass er nach genau 6 Stunden unterbrochen und später wieder fortgesetzt wird.

Soweit ist alles normal und geplant und keine Folge einer Unregelmäßigkeit.

Nicht geklärt bisher ist, ob es ok ist, dass der Check so lange dauert (15 Stunden für 4 TB). Und dass die Seitenaufrufe sich so schwer tun. Ich hatte nur Moodle ausprobiert. Vielleicht ist das ein Sonderfall eines besonders heftigen Plattenzugriffs.

Ich habe bisher keine spezielle SMART-Routine installiert. In den Dateien kern.log und syslog sowie bei dmesg finden sich keine Hinweise auf fehlerhafte Platten.

Einige Eintragungen kann ich allerdings nicht erklären, erscheinen mir aber auch unverdächtig. Was bedeutet beispielsweise dies:

 +11,360140] session_init(service_process,1168137): OK. kdev=9:0, bs=4096.
[  +0,155347] register_make_request(service_process,1168137): OK. kdev=9:0, mq=0.
[  +5,898300] session_stat(service_process,1168137): dev=9:0 state=6 blksize=4096 mmapsize=262144
[  +0,000004] session_stat(service_process,1168137): psize=2046848 pstrt=0 mshft=0 ioctls=394
[  +0,000003] session_stat(service_process,1168137): bhpgs=0 bhcnt=0 abhs=340 fbhs=340 dbhs=0
[  +0,000004] session_stat(service_process,1168137): gpgs=32168 ppgs=32168 emmax=32019 emmin=30018 emcur=0 cached=0
[  +0,000003] session_stat(service_process,1168137): rblk=5036 cblk=9 rcblk=10 rc2blk=0 mcblk=8 rwcolls=2
[  +0,000003] session_stat(service_process,1168137): sync=0 async=9 aretr=0 mipr=0 iprcnt=0
[  +0,000002] session_stat(service_process,1168137): mbio=0 ioctlcnt=394 ioctlpid=393
[  +0,000003] session_stat(service_process,1168137): rccalls=5052 maxrcdepth=0 rcdepthcnts=(0, 0, 0, 0)
[  +0,000002] session_stat(service_process,1168137): flags=0
[  +1,492638] session_init(service_process,1168137): OK. kdev=9:1, bs=4096.
[  +3,768640] register_make_request(service_process,1168137): OK. kdev=9:1, mq=0.

Gruß und vielen Dank für die Unterstützung

Ralph
Member: raba34
raba34 Apr 02, 2022 at 12:36:07 (UTC)
Goto Top
Morgen ist wieder ein erster Sonntag im Monat und ich bin gespannt, ob der Check wieder so lange dauert und alles wieder so stark verlangsamt ist.
Member: raba34
raba34 Apr 04, 2022 at 10:43:56 (UTC)
Goto Top
Gestern am Sonntag, 3. April begann der Check um 18:21. Die Verlangsamung ist spürbar. Immerhin ist der Check jetzt, einen Tag danach kurz vor 13 Uhr schon zu fast 75 Prozent durch. Das scheint schneller abzulaufen als vor einem Monat.
Member: raba34
raba34 Nov 06, 2023 at 10:09:26 (UTC)
Goto Top
Hallo ihr alle,

nach über einem Jahr und Umstieg auf einen anderen Server wieder dasselbe Bild:

Personalities : [raid1] [raid0] [linear] [multipath] [raid6] [raid5] [raid4] [raid10]
md1 : active raid1 sda4[0] sdb4[1]
3901859840 blocks super 1.2 [2/2] [UU]
[===============>.....] check = 77.8% (3037569344/3901859840) finish=142.9min speed=100780K/sec
bitmap: 10/30 pages [40KB], 65536KB chunk

md0 : active raid1 sdb2[1] sda2[0]
1022976 blocks super 1.2 [2/2] [UU]

Und der Server reagiert wieder extrem langsam. Heute ist wieder der Montag nach dem ersten Wochenende im Monat. Die Platte hat 4 TB, entsprechend lange dauert der Check.

Meiner Meinung liegt es wirklich am Check und nicht an irgendwelchen anderen Problemen, wie zuvor angedeutet.
Member: raba34
raba34 Nov 06, 2023 at 12:10:35 (UTC)
Goto Top
Inzwischen habe ich die Stelle im System gefunden, die diesen Check auslöst. Es findet nicht im üblichen Bereich des cron statt, sondern unter

/etc/systemd/system/mdmonitor.service.wants

Dort stehen (als Symlinks) die Dateien

mdmonitor-oneshot.timer
mdcheck_start.timer
mdcheck_continue.timer

In mdcheck_start.timer steht zurzeit

OnCalendar=Sun *-*-1..7 1:00:00

womit mdmonitor.service aufgerufen wird.

Ich denke, dass man hier eingreifen und die Häufigkeit und den Zeitpunkt des Checks einstellen kann.
Member: raba34
Solution raba34 Nov 07, 2023 at 20:01:21 (UTC)
Goto Top
Für mich ist das Problem damit gelöst. Ich weiß, wo ich eingreifen muss, um diesen (durchaus sinnvollen) Check in einer zu verlegen, wo er nicht so entsetzlich nervt.

Allerdings wundere ich mich, dass ihr offenbar gar nicht davon betroffen seid.