Garbage Collection bricht ab in Phase1

T

t0mc@

Well-Known Member
Nov 27, 2017
94
14
48
47
Hallo zusammen,

ich habe festgestellt, dass seit einiger Zeit die Garbage Collection des Backup Servers fehl schlägt.
Zum Testen starte ich die per Hand auf der Konsole:

Code: 
root@backup:~# proxmox-backup-manager garbage-collection start backup

mit dem Ergebnis, dass die Phase1 plötzlich und ohne jegliche Meldung bei 19% abbricht:

Code: 
starting garbage collection on store backup
Start GC phase1 (mark used chunks)
marked 1% (19 of 1847 index files)
marked 2% (37 of 1847 index files)
marked 3% (56 of 1847 index files)
marked 4% (74 of 1847 index files)
marked 5% (93 of 1847 index files)
marked 6% (111 of 1847 index files)
marked 7% (130 of 1847 index files)
marked 8% (148 of 1847 index files)
marked 9% (167 of 1847 index files)
marked 10% (185 of 1847 index files)
marked 11% (204 of 1847 index files)
marked 12% (222 of 1847 index files)
marked 13% (241 of 1847 index files)
marked 14% (259 of 1847 index files)
marked 15% (278 of 1847 index files)
marked 16% (296 of 1847 index files)
marked 17% (314 of 1847 index files)
marked 18% (333 of 1847 index files)
marked 19% (351 of 1847 index files)


Hat jmd. ne Idee? Gibts irgendwo Logs oder so?

Danke schon mal!
T0mc@
 
mhm.. normal ist das nicht... kommt tatsächlich nichts mehr nach der 'marked 19%' zeile?

was steht denn im syslog (journalctl) zu der zeit?
 
Ja, da kommt tatsächlich nichts mehr. Im syslog steht auch nichts auffälliges.

Allerdings habe ich die Ursache offenbar - zufällig - gefunden.

Der Backup DataStore liegt auf einem ZFS Pool. Und ein Blick in "zpool status" offenbarte, dass offenbar 3 .idx Dateien unreparierbar defekt sind. Da diese alte Sicherungen waren, habe ich die entsprechenden Backups in der Proxmox GUI gelöscht.
Seitdem läuft der Garbage Collect weiter.

Trotzdem irgendwie ungünstig, dass so gar kein Hinweis kommt und der Prozess stillschweigend abbricht.
 
ah ok offenbar bricht er nicht ab, sondern hängt? das lässt sich leider nicht so einfach abfangen, da ein im kernel hängender prozess nicht wirklich was tun kann...
 
Nein, der bricht wirklich hart ab und hängt nicht fest. Es erscheint wieder ein normaler Prompt...
 
t0mc@ said:
Seitdem läuft der Garbage Collect weiter.
Click to expand...
das klingt so als ob er dann weiter macht? oder war es so gemeint dass ein neuer Garbage collect über diesen punkt hinauskommt?
 
Nein, wenn es zu diesem Problem kommt, bricht der Job hart ab, es erscheint ein Prompt.
Nachdem ich die defekten .idx Files gelöscht hatte, hab ich den Job auf der Commandline neu gestartet, danach lief er normal über den Punkt hinaus weiter.

Man kann auch in der GUI die abgebrochenen Jobs (sowohl händisch, als auch per cron gestartet) nachvollziehen. Die stehen dann im Status "stopped: unknown":

1643122339795.png

1643122360205.png
 
ok, sry, dann hab ich nur den satz misverstanden...

das klingt nicht normal, kannst du mal das journal von dem zeitpunkt posten?
 
Du meinst das systemd Journal (journalctl)?
Hab dafür einen passenden Zeitraum zum Screenshot oben genommen:

Code: 
root@backup:~# journalctl -S "2022-01-20 22:20:00" -U "2022-01-20 22:35:00"
-- Journal begins at Sat 2021-12-25 20:40:10 CET, ends at Tue 2022-01-25 17:35:47 CET. --
Jan 20 22:31:33 backup zed[1969123]: eid=301 class=data pool='rpool' priority=0 err=52 flags=0x880 bookmark=142:5917974:0:4
Jan 20 22:31:33 backup zed[1969134]: eid=302 class=checksum pool='rpool' vdev=scsi-350004cf211605c29-part3 size=20480 offset=810476998656 priority=0 err=52 flags=0x100880 bookmark=142:5917974:0:4
Jan 20 22:31:33 backup zed[1969139]: eid=303 class=checksum pool='rpool' vdev=scsi-350004cf21160653a-part2 size=20480 offset=810476998656 priority=0 err=52 flags=0x100880 bookmark=142:5917974:0:4
Jan 20 22:31:33 backup zed[1969142]: eid=304 class=checksum pool='rpool' vdev=scsi-350014ee268d43298-part1 size=20480 offset=810476998656 priority=0 err=52 flags=0x100880 bookmark=142:5917974:0:4
Jan 20 22:31:33 backup zed[1969145]: eid=305 class=checksum pool='rpool' vdev=scsi-350004cf211200226-part3 size=20480 offset=810476998656 priority=0 err=52 flags=0x100880 bookmark=142:5917974:0:4
Jan 20 22:31:33 backup zed[1969148]: eid=306 class=checksum pool='rpool' vdev=scsi-350004cf211605aa1-part3 size=24576 offset=810476998656 priority=0 err=52 flags=0x100880 bookmark=142:5917974:0:4
Jan 20 22:31:33 backup zed[1969151]: eid=307 class=checksum pool='rpool' vdev=scsi-350014ee213810b88-part1 size=24576 offset=810476994560 priority=0 err=52 flags=0x100880 bookmark=142:5917974:0:4
Jan 20 22:31:33 backup zed[1969153]: eid=308 class=checksum pool='rpool' vdev=scsi-350014ee268d433ca-part1 size=24576 offset=810476998656 priority=0 err=52 flags=0x100880 bookmark=142:5917974:0:4
Jan 20 22:31:34 backup zed[1969898]: eid=309 class=data pool='rpool' priority=0 err=52 flags=0x880 bookmark=142:5917974:0:4
Jan 20 22:31:34 backup zed[1970486]: eid=310 class=data pool='rpool' priority=0 err=52 flags=0x880 bookmark=142:5917974:0:4
Jan 20 22:31:35 backup systemd[1]: proxmox-backup-proxy.service: Main process exited, code=killed, status=7/BUS
Jan 20 22:31:35 backup systemd[1]: proxmox-backup-proxy.service: Failed with result 'signal'.
Jan 20 22:31:35 backup zed[1971037]: eid=311 class=data pool='rpool' priority=0 err=52 flags=0x880 bookmark=142:5917974:0:4
Jan 20 22:31:35 backup systemd[1]: proxmox-backup-proxy.service: Consumed 8min 3.058s CPU time.
Jan 20 22:31:35 backup systemd[1]: proxmox-backup-proxy.service: Scheduled restart job, restart counter is at 13.
Jan 20 22:31:35 backup systemd[1]: Stopped Proxmox Backup API Proxy Server.
Jan 20 22:31:35 backup systemd[1]: proxmox-backup-proxy.service: Consumed 8min 3.058s CPU time.
Jan 20 22:31:35 backup systemd[1]: Starting Proxmox Backup API Proxy Server...
Jan 20 22:31:35 backup proxmox-backup-proxy[1971732]: service is ready
Jan 20 22:31:35 backup systemd[1]: Started Proxmox Backup API Proxy Server.
Jan 20 22:31:35 backup proxmox-backup-proxy[1971732]: applied rrd journal (3083 entries in 0.012 seconds)
Jan 20 22:31:35 backup proxmox-backup-proxy[1971732]: write rrd data back to disk
Jan 20 22:31:35 backup proxmox-backup-proxy[1971732]: starting rrd data sync
Jan 20 22:31:35 backup proxmox-backup-proxy[1971732]: rrd journal successfully committed (23 files in 0.014 seconds)

Da ist tatsächlich ein Hinweis auf die ZFS Fehler zu sehen....
 
t0mc@ said:
Du meinst das systemd Journal (journalctl)?
Click to expand...
ja genau, danke fürs posten...

ein paar minuten früher wären im log auch noch interessant. dass der proxmox-backup-proxy gekillt wird sollte eigentlich nicht passieren, dh. mich interessiert ob es noch hinweise gibt warum das genau passiert...
der darunterliegende grund wird das zfs problem sein, aber trotzdem sollte der prozess nicht abgeschossen werden...
 
Es gibt ein paar minuten vorher nichts im Log, ich hatte den Startzeitpunkt bei journalctl ja auf 22:20 gesetzt, trotzdem ist der erste Eintrag erst um 22:31.

Hier auch noch mal der entsprechende Auszug direkt aus "/var/log/syslog.1":
Code: 
Jan 20 22:09:29 backup proxmox-backup-proxy[1429759]: write rrd data back to disk
Jan 20 22:09:29 backup proxmox-backup-proxy[1429759]: starting rrd data sync
Jan 20 22:09:29 backup proxmox-backup-proxy[1429759]: rrd journal successfully committed (23 files in 0.013 seconds)
Jan 20 22:12:42 backup systemd[1]: Starting Cleanup of Temporary Directories...
Jan 20 22:12:42 backup systemd[1]: systemd-tmpfiles-clean.service: Succeeded.
Jan 20 22:12:42 backup systemd[1]: Finished Cleanup of Temporary Directories.
Jan 20 22:17:01 backup CRON[1616670]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jan 20 22:31:33 backup zed: eid=301 class=data pool='rpool' priority=0 err=52 flags=0x880 bookmark=142:5917974:0:4
Jan 20 22:31:33 backup zed: eid=302 class=checksum pool='rpool' vdev=scsi-350004cf211605c29-part3 size=20480 offset=810476998656 priority=0 err=52 flags=0x100880 bookmark=142:5917974:0:4
Jan 20 22:31:33 backup zed: eid=303 class=checksum pool='rpool' vdev=scsi-350004cf21160653a-part2 size=20480 offset=810476998656 priority=0 err=52 flags=0x100880 bookmark=142:5917974:0:4
Jan 20 22:31:33 backup zed: eid=304 class=checksum pool='rpool' vdev=scsi-350014ee268d43298-part1 size=20480 offset=810476998656 priority=0 err=52 flags=0x100880 bookmark=142:5917974:0:4
Jan 20 22:31:33 backup zed: eid=305 class=checksum pool='rpool' vdev=scsi-350004cf211200226-part3 size=20480 offset=810476998656 priority=0 err=52 flags=0x100880 bookmark=142:5917974:0:4
Jan 20 22:31:33 backup zed: eid=306 class=checksum pool='rpool' vdev=scsi-350004cf211605aa1-part3 size=24576 offset=810476998656 priority=0 err=52 flags=0x100880 bookmark=142:5917974:0:4
Jan 20 22:31:33 backup zed: eid=307 class=checksum pool='rpool' vdev=scsi-350014ee213810b88-part1 size=24576 offset=810476994560 priority=0 err=52 flags=0x100880 bookmark=142:5917974:0:4
Jan 20 22:31:33 backup zed: eid=308 class=checksum pool='rpool' vdev=scsi-350014ee268d433ca-part1 size=24576 offset=810476998656 priority=0 err=52 flags=0x100880 bookmark=142:5917974:0:4
Jan 20 22:31:34 backup zed: eid=309 class=data pool='rpool' priority=0 err=52 flags=0x880 bookmark=142:5917974:0:4
Jan 20 22:31:34 backup zed: eid=310 class=data pool='rpool' priority=0 err=52 flags=0x880 bookmark=142:5917974:0:4
Jan 20 22:31:35 backup systemd[1]: proxmox-backup-proxy.service: Main process exited, code=killed, status=7/BUS
Jan 20 22:31:35 backup systemd[1]: proxmox-backup-proxy.service: Failed with result 'signal'.
Jan 20 22:31:35 backup zed: eid=311 class=data pool='rpool' priority=0 err=52 flags=0x880 bookmark=142:5917974:0:4
Jan 20 22:31:35 backup systemd[1]: proxmox-backup-proxy.service: Consumed 8min 3.058s CPU time.
Jan 20 22:31:35 backup systemd[1]: proxmox-backup-proxy.service: Scheduled restart job, restart counter is at 13.
Jan 20 22:31:35 backup systemd[1]: Stopped Proxmox Backup API Proxy Server.
Jan 20 22:31:35 backup systemd[1]: proxmox-backup-proxy.service: Consumed 8min 3.058s CPU time.
Jan 20 22:31:35 backup systemd[1]: Starting Proxmox Backup API Proxy Server...
Jan 20 22:31:35 backup proxmox-backup-proxy[1971732]: service is ready
Jan 20 22:31:35 backup systemd[1]: Started Proxmox Backup API Proxy Server.
Jan 20 22:31:35 backup proxmox-backup-proxy[1971732]: applied rrd journal (3083 entries in 0.012 seconds)
Jan 20 22:31:35 backup proxmox-backup-proxy[1971732]: write rrd data back to disk
Jan 20 22:31:35 backup proxmox-backup-proxy[1971732]: starting rrd data sync
Jan 20 22:31:35 backup proxmox-backup-proxy[1971732]: rrd journal successfully committed (23 files in 0.014 seconds)
Jan 20 23:01:35 backup proxmox-backup-proxy[1971732]: write rrd data back to disk
Jan 20 23:01:35 backup proxmox-backup-proxy[1971732]: starting rrd data sync
Jan 20 23:01:35 backup proxmox-backup-proxy[1971732]: rrd journal successfully committed (23 files in 0.013 seconds)
Jan 20 23:17:01 backup CRON[2635929]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jan 20 23:31:35 backup proxmox-backup-proxy[1971732]: write rrd data back to disk
Jan 20 23:31:35 backup proxmox-backup-proxy[1971732]: starting rrd data sync
Jan 20 23:31:35 backup proxmox-backup-proxy[1971732]: rrd journal successfully committed (23 files in 0.012 seconds)
Jan 21 00:00:08 backup proxmox-backup-proxy[1971732]: rotated auth log, telling daemons to re-open log file
Jan 21 00:00:08 backup proxmox-backup-proxy[1971732]: re-opening auth-log file
Jan 21 00:00:08 backup proxmox-backup-api[2424530]: re-opening auth-log file
 
mhmm... SIGBUS (status = 7/BUS) sieht nicht normal aus... wie gehts denn der hardware? vielleicht mal dmesg ouput posten und einen (langen) memtest machen?
 
Das passierte reproduzierbar dann, so lange defekte idx Files im ZFS vorhanden waren. Seitdem die raus sind, läuft der GC durch. Wenn es Hardware wäre, dürfte es ja nicht so exakt reproduzierbar sein bzw. jetzt auch nicht ohne Probleme durch laufen.

Im dmesg Output finden sich solche Einträge:
Code: 
[Jan25 04:33] INFO: task txg_sync:873 blocked for more than 120 seconds.
[  +0.000200]       Tainted: P          IO      5.13.19-2-pve #1
[  +0.000170] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  +0.000225] task:txg_sync        state:D stack:    0 pid:  873 ppid:     2 flags:0x00004000
[  +0.000004] Call Trace:
[  +0.000005]  __schedule+0x2fa/0x910
[  +0.000009]  schedule+0x4f/0xc0
[  +0.000004]  cv_wait_common+0xfd/0x130 [spl]
[  +0.000015]  ? wait_woken+0x80/0x80
[  +0.000003]  __cv_wait+0x15/0x20 [spl]
[  +0.000007]  arc_read+0x1eb/0x14f0 [zfs]
[  +0.000139]  ? arc_evict_cb_check+0x20/0x20 [zfs]
[  +0.000067]  dsl_scan_visitbp.isra.0+0x289/0xbf0 [zfs]
[  +0.000094]  dsl_scan_visitbp.isra.0+0x58c/0xbf0 [zfs]
[  +0.000095]  dsl_scan_visitbp.isra.0+0x314/0xbf0 [zfs]
[  +0.000094]  dsl_scan_visitbp.isra.0+0x314/0xbf0 [zfs]
[  +0.000094]  dsl_scan_visitbp.isra.0+0x314/0xbf0 [zfs]
[  +0.000095]  dsl_scan_visitbp.isra.0+0x314/0xbf0 [zfs]
[  +0.000094]  dsl_scan_visitbp.isra.0+0x314/0xbf0 [zfs]
[  +0.000095]  dsl_scan_visitbp.isra.0+0x7d3/0xbf0 [zfs]
[  +0.000095]  dsl_scan_visit_rootbp.isra.0+0x125/0x1b0 [zfs]
[  +0.000094]  dsl_scan_visitds+0x1a8/0x510 [zfs]
[  +0.000094]  ? slab_pre_alloc_hook.constprop.0+0x96/0xe0
[  +0.000005]  ? __kmalloc_node+0x169/0x300
[  +0.000003]  ? __raw_callee_save___native_queued_spin_unlock+0x15/0x23
[  +0.000004]  ? __raw_callee_save___native_queued_spin_unlock+0x15/0x23
[  +0.000002]  ? tsd_set+0x20d/0x4c0 [spl]
[  +0.000009]  ? __raw_callee_save___native_queued_spin_unlock+0x15/0x23
[  +0.000003]  ? rrw_enter_read_impl+0xd8/0x180 [zfs]
[  +0.000100]  dsl_scan_sync+0x885/0x13d0 [zfs]
[  +0.000095]  spa_sync+0x5cb/0xff0 [zfs]
[  +0.000101]  ? spa_txg_history_init_io+0x106/0x110 [zfs]
[  +0.000105]  txg_sync_thread+0x2d3/0x460 [zfs]
[  +0.000105]  ? txg_init+0x260/0x260 [zfs]
[  +0.000105]  thread_generic_wrapper+0x79/0x90 [spl]
[  +0.000009]  ? __thread_exit+0x20/0x20 [spl]
[  +0.000009]  kthread+0x12b/0x150
[  +0.000003]  ? set_kthread_struct+0x50/0x50
[  +0.000003]  ret_from_fork+0x22/0x30

Könnte das ein Hinweis sein, dass der Kernel den Task gekilled hat, weil der länger als 120s fest hing? Evtl. weil der GC in dem Moment am defekten .idx ankam und das nicht lesen konnte?
 
t0mc@ said:
Das passierte reproduzierbar dann, so lange defekte idx Files im ZFS vorhanden waren. Seitdem die raus sind, läuft der GC durch. Wenn es Hardware wäre, dürfte es ja nicht so exakt reproduzierbar sein bzw. jetzt auch nicht ohne Probleme durch laufen.
Click to expand...
natürlich kann die hw da defekt sein, zb wenn ein block geschrieben wird es zufällig in einem memory bereich mit einem 'stuck bit' liegt. das fällt erst dann auf wenn das file gelesen wird...

t0mc@ said:
Könnte das ein Hinweis sein, dass der Kernel den Task gekilled hat, weil der länger als 120s fest hing? Evtl. weil der GC in dem Moment am defekten .idx ankam und das nicht lesen konnte?
Click to expand...
nein normalerweise werden durch solche dinge nicht einfach prozesse gekillt (sie hängen dann im normalfall)

ich würde trotzdem die hw überprüfen da korruptes zfs üblicherweise auf kaputte(s) memory/disk/controller/kabel zurückzuführen sind...
 
Irgendwas ist da auf jeden Fall nicht ganz koscher... es ist ja schon allein ungewöhnlich, dass bei einem raidz1 - ZFS Pool aus 7 Platten mehrere Dateien so kaputt sind, dass noch nicht mal ZFS davor geschützt hat. Und es waren backups, die an komplett unterschiedlichen Tagen erstellt - sprich geschrieben - wurden
 
HDDs oder SSDs? An welchem Controller (Modell, Firmware, IT/IR Mode) sind diese angesteckt?
 
Sorry, mußte das erst in Erfahrung bringen... an die Hardware komme ich persönlich nicht direkt ran....

7x HDD SATA 2,5 2TB hängen an 2x HP Smart Array P420 - 1GB 633542-001 6Gb 2-Port SAS Controller Standard Profile - aktuelle firmware
Die Controller sind im HBA Mode

Dazu eine SSD für ZFS log und cache
 
BTW:
Der GarbageCollect läuft mittlerweile seit 3 Tagen... Sind zwar auch 8-10TB Daten, aber kommt mir trotzdem irgendwie lange vor
 
Auch wenns nichts hilft, ich hatte so ein Verhalten vor kurzem wegen einer sich langsam verabschiedende Disk (Backup-Storage).
Dauerte zwar etwas bist ich das gecheckt hatte (SMART zeigte nix an).
Hardwaredefekte sind unterschiedlich...
 
You must log in or register to reply here.

About

The Proxmox community has been around for many years and offers help and support for Proxmox VE, Proxmox Backup Server, and Proxmox Mail Gateway.
We think our community is one of the best thanks to people like you!

Quick Navigation

Home Get Subscription Wiki Downloads Proxmox Customer Portal About

Get your subscription!

The Proxmox team works very hard to make sure you are running the best software and getting stable updates and security enhancements, as well as quick enterprise support. Tens of thousands of happy customers have a Proxmox subscription. Get yours easily in our online shop.

Buy now!
Community platform by XenForo® © 2010-2024 XenForo Ltd.
Top Bottom