[Garbage Collection] RAM Cache Verhalten seit Update 3.4 Bug?

L

Lun4r

New Member
Jun 17, 2025
20
6
3
Hi,
die Garbage Collection hält ja jetzt Daten im RAM vor für Step 1 und ist dadurch extrem viel schneller.
Sau gute Arbeit!
Bei uns von 4,5h auf ca. 30min, wenn vorgechached wurde.
Nun ist mir aufgefallen das er, nicht ganz nachvollziehbar warum und gefühlt random, den Cache wieder leert zwischen ca. 5:00 und 7:00 und somit dann beim nächsten GC wieder 4,5h braucht.
Der Abstand über wieviele Tage er ihn "hält" schwankt ebenso.
  • 2 Wochen ware es 2 Tage und 8h nach dem letzten GC oder falls der letzte GC irrelevant ist -> Montag früh zwischen 5 und 7.
  • gestern habe ich den Cache von manuell eingestellten 4Millionen Chunks wieder auf default (ca 1 Mille Chunks) gestellt da es keine zusätzliche Verbesserung brachte. Der GC lief fix durch in 35min aber heute früh hat er wieder unverhofft den Cache geleert
Mein Ziel ist es das er ihn 24/7 hält und nur aktualisiert da ich genug RAM habe.

Wisst ihr unter welchen Bedingungen die Cache"bereinigung" bzw. komplette Cacheleerung ausgeführt wird und ich vielleicht was verkonfiguriert habe oder ist das evtl. ein Bug?
  • feste verstrichene Zeit zwischen den GC´s relevant? -> eigentlich ausgeschlossen durch das Beispiel heute früh
  • reicht da vielleicht auch schon ein umconfigurieren der Cachegröße?
  • Haben andere Jobs auswirkungen auf den Cache (verify, Prune....) -> sehr unwahrscheinlich
  • alles was mir nicht einfällt :)

Rot = vor Update
Grün = nach Update
orange = GC Cache komplett geleert
gelb = GC (Länge des Strichs = Laufzeit. Nicht RAM Belegung)

1750318884690.png

Heute vergrößert:

1750319275038.png

GC Tuning Options:

1750319431256.png
 
Last edited:
Hallo,
Lun4r said:
Hi,
die Garbage Collection hält ja jetzt Daten im RAM vor für Step 1 und ist dadurch extrem viel schneller.
Sau gute Arbeit!
Bei uns von 4,5h auf ca. 30min, wenn vorgechached wurde.
Click to expand...
Achtung, hier muss zwischen verschiedenen Sachverhalten unterschieden werden. Zum einen werden files und deren Metadaten vom Kernel gecached wenn auf diese zugegriffen wird, darauffolgende Zugriffe sind daher stets schneller da diese bereits in memory sind und nicht mehr von der disk gelesen werden. Das hat aber nichts mit der Optimierung der GC zu tun welche mit version 3.4 in PBS eingeflossen ist.

Bei der optimierung handelt es sich um eine least recently used cache (LRU) welche zu beginn der garbage collection alloziert wird und sich im wesentlichen merkt welche chunks bereits gesehen wurden, um multiple syscalls auf den selben chunk und den damit verbundenen overhead zu eliminieren. Diese LRU cache wird nach der garbage collection aber wieder freigegeben, beim nächsten mal muss ja wieder zumindest einmal auf den chunk zugegriffen werden um diesen als in Verwendung zu markieren.

Um den Effekt der GC Optimierung zu messen muss man also am besten den cold cache state vergleichen , also die caches im Kernel vorher stets leeren (oder den reinen hot state, wenn die Filesystem caches ausreichen um alle chunk metadaten zu cachen). Ansonsten vergleicht man hier verschiedene Cache Effekte, der Filesystem Cache ist stets dominant weil Disk IO verhindert wrid!

Lun4r said:
Nun ist mir aufgefallen das er, nicht ganz nachvollziehbar warum und gefühlt random, den Cache wieder leert zwischen ca. 5:00 und 7:00 und somit dann beim nächsten GC wieder 4,5h braucht.
Der Abstand über wieviele Tage er ihn "hält" schwankt ebenso.
  • 2 Wochen ware es 2 Tage und 8h nach dem letzten GC oder falls der letzte GC irrelevant ist -> Montag früh zwischen 5 und 7.
  • gestern habe ich den Cache von manuell eingestellten 4Millionen Chunks wieder auf default (ca 1 Mille Chunks) gestellt da es keine zusätzliche Verbesserung brachte. Der GC lief fix durch in 35min aber heute früh hat er wieder unverhofft den Cache geleert
Mein Ziel ist es das er ihn 24/7 hält und nur aktualisiert da ich genug RAM habe.

Wisst ihr unter welchen Bedingungen die Cache"bereinigung" bzw. komplette Cacheleerung ausgeführt wird und ich vielleicht was verkonfiguriert habe oder ist das evtl. ein Bug?
Click to expand...
Kein bug, die chunk LRU cache existiert nur während der GC runtime wie oben beschrieben. Welcher caches ansonsten wann freigegeben werden hängt von vielen weiteren Faktoren ab.

Lun4r said:
  • feste verstrichene Zeit zwischen den GC´s relevant? -> eigentlich ausgeschlossen durch das Beispiel heute früh
Click to expand...
Nicht für die chunk LRU cache, sehr wohl aber für die filesystem caches.
 
  • Like
Reactions: Lun4r
Ich beobachte mal ob der GC sich nun heute Abend wieder in die Länge zieht.

Könnte es eine Möglichkeit sein den (filesystem-)cache aufzubohren (zu vergrößern oder die Zeit des aufhebens zu verlängern) oder ist der zu speziell/automatisiert bzw. im System verankert, sodas ein rumconfigurieren zu instabilitäten im Gesamtkonstrukt führen könnte?
Hintergrund ist das wir ein RAID 6 aus 18TB HDDs mit xfs haben. Ich würde also gerne soviel wie möglich meiner ungenutzten Resourcen (RAM) für das Cachen bereitstellen um Zugriffe "von dem RAID wegzuhalten".
 
Last edited:
Lun4r said:
Ich beobachte mal ob der GC sich nun heute Abend wieder in die Länge zieht.

Könnte es eine Möglichkeit sein den (filesystem-)cache aufzubohren (zu vergrößern oder die Zeit des aufhebens zu verlängern) oder ist der zu speziell/automatisiert bzw. im System verankert, sodas ein rumconfigurieren zu instabilitäten im Gesamtkonstrukt führen könnte?
Hintergrund ist das wir ein RAID 6 aus 18TB HDDs mit xfs haben. Ich würde also gerne soviel wie möglich meiner ungenutzten Resourcen (RAM) für das Cachen bereitstellen um Zugriffe "von dem RAID wegzuhalten".
Click to expand...
Das ist ein sehr komplexes Thema und ich erlaube mir hier keine Empfehlungen abzugeben.

Suchbegriffe hierzu sind dcache und inode cache sowie slab cache, siehe dazu auch die Linux Kernel Dokumentation https://www.kernel.org/doc/html/next/filesystems/vfs.html

slabtop erlaubt den cache state zu monitoren.
 
  • Like
Reactions: Lun4r
Lun4r said:
Nun ist mir aufgefallen das er, nicht ganz nachvollziehbar warum und gefühlt random, den Cache wieder leert zwischen ca. 5:00 und 7:00 und somit dann beim nächsten GC wieder 4,5h braucht.
Click to expand...
P.S.: hatte noch vergessen zu erwähnen, dass auch wenn dieses Verhalten nichts mit der GC per se zu tun hat, wäre es dennoch von Interesse zu verstehen was hier passiert, und warum die memory usage diesen drop hat. Gibt es dazu vielleicht Log-Einträge im systemd journal? journalctl --since <DATETIME> --until <DATETIME> > journal.txt mit dem entsprechenden Zeitintervall sollte mehr infos liefern.
 
Ich kann da leider nichts erkennen.

Cachedrop bei Mon Jun 16 2025 05:56:32 GMT +0200
Cachedrop bei Thu Jun 19 2025 05:57:06 GMT +0200

Code: 
Jun 16 00:00:00 pbs proxmox-backup-proxy[1205]: rotated access log, telling daemons to re-open log file
Jun 16 04:10:44 pbs chronyd[1182]: Source 141.144.246.224 replaced with 148.251.5.46 (2.debian.pool.ntp.org)
Jun 16 04:17:01 pbs CRON[30962]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Jun 16 04:17:01 pbs CRON[30963]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Jun 16 04:17:01 pbs CRON[30962]: pam_unix(cron:session): session closed for user root
Jun 16 04:18:06 pbs proxmox-backup-proxy[1205]: rrd journal successfully committed (25 files in 0.015 seconds)
Jun 16 04:45:02 pbs chronyd[1182]: Source 46.38.244.94 replaced with 157.90.24.29 (2.debian.pool.ntp.org)
Jun 16 04:48:07 pbs proxmox-backup-proxy[1205]: rrd journal successfully committed (25 files in 0.010 seconds)
Jun 16 04:54:24 pbs proxmox-backup-api[1095]: notified via target `mail-to-root`
Jun 16 05:16:36 pbs chronyd[1182]: Source 185.248.188.98 replaced with 130.162.237.177 (2.debian.pool.ntp.org)
Jun 16 05:17:01 pbs CRON[31017]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Jun 16 05:17:01 pbs CRON[31018]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Jun 16 05:17:01 pbs CRON[31017]: pam_unix(cron:session): session closed for user root
Jun 16 05:18:07 pbs proxmox-backup-proxy[1205]: rrd journal successfully committed (25 files in 0.010 seconds)
Jun 16 05:48:07 pbs proxmox-backup-proxy[1205]: rrd journal successfully committed (25 files in 0.011 seconds)
Jun 16 05:49:47 pbs chronyd[1182]: Source 128.140.37.196 replaced with 194.164.164.175 (2.debian.pool.ntp.org)
Jun 16 06:00:16 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.21: "ns/cluster1/vm/204/2025-06-16T04:00:04Z"
Jun 16 06:00:28 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.34: "ns/cluster1/vm/202/2025-06-16T04:00:13Z"
Jun 16 06:00:46 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/203/2025-06-16T04:00:02Z"
Jun 16 06:01:23 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/203/2025-06-16T04:00:02Z/client.log.blob
Jun 16 06:01:26 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/204/2025-06-16T04:00:04Z/client.log.blob
Jun 16 06:01:26 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.21: "ns/cluster1/vm/205/2025-06-16T04:01:14Z"
Jun 16 06:01:36 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/208/2025-06-16T04:00:40Z"
Jun 16 06:06:37 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/205/2025-06-16T04:01:14Z/client.log.blob
Jun 16 06:07:03 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/202/2025-06-16T04:00:13Z/client.log.blob
Jun 16 06:07:09 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.34: "ns/cluster1/vm/207/2025-06-16T04:06:52Z"
Jun 16 06:16:21 pbs systemd[1]: Starting apt-daily-upgrade.service - Daily apt upgrade and clean activities...
Jun 16 06:16:22 pbs systemd[1]: apt-daily-upgrade.service: Deactivated successfully.
Jun 16 06:16:22 pbs systemd[1]: Finished apt-daily-upgrade.service - Daily apt upgrade and clean activities.
Jun 16 06:17:01 pbs CRON[31405]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Jun 16 06:17:01 pbs CRON[31406]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Jun 16 06:17:01 pbs CRON[31405]: pam_unix(cron:session): session closed for user root
Jun 16 06:18:07 pbs proxmox-backup-proxy[1205]: rrd journal successfully committed (25 files in 0.017 seconds)
Jun 16 06:25:01 pbs CRON[31413]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Jun 16 06:25:01 pbs CRON[31414]: (root) CMD (test -x /usr/sbin/anacron || { cd / && run-parts --report /etc/cron.daily; })
Jun 16 06:25:01 pbs CRON[31413]: pam_unix(cron:session): session closed for user root
Jun 16 06:25:46 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/207/2025-06-16T04:06:52Z/client.log.blob
Jun 16 06:27:00 pbs chronyd[1182]: Source 195.201.19.162 replaced with 62.113.219.231 (2.debian.pool.ntp.org)
Jun 16 06:36:59 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/208/2025-06-16T04:00:40Z/client.log.blob
Jun 16 06:37:04 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/209/2025-06-16T04:36:16Z"
Jun 16 06:48:07 pbs proxmox-backup-proxy[1205]: rrd journal successfully committed (25 files in 0.015 seconds)
Jun 16 07:00:17 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.21: "ns/cluster1/vm/204/2025-06-16T05:00:04Z"
Jun 16 07:00:30 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.34: "ns/cluster1/vm/202/2025-06-16T05:00:15Z"
Jun 16 07:00:56 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/204/2025-06-16T05:00:04Z/client.log.blob
Jun 16 07:01:03 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.21: "ns/cluster1/vm/205/2025-06-16T05:00:45Z"
Jun 16 07:01:21 pbs systemd[1]: Starting apt-daily.service - Daily apt download activities...
Jun 16 07:01:21 pbs systemd[1]: apt-daily.service: Deactivated successfully.
Jun 16 07:01:21 pbs systemd[1]: Finished apt-daily.service - Daily apt download activities.
Jun 16 07:01:49 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/202/2025-06-16T05:00:15Z/client.log.blob
Jun 16 07:01:49 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/205/2025-06-16T05:00:45Z/client.log.blob
Jun 16 07:01:54 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.34: "ns/cluster1/vm/207/2025-06-16T05:01:37Z"
Jun 16 07:02:55 pbs chronyd[1182]: Source 148.251.5.46 replaced with 141.144.246.224 (2.debian.pool.ntp.org)
Jun 16 07:03:36 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/207/2025-06-16T05:01:37Z/client.log.blob
Jun 16 07:17:01 pbs CRON[32080]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Jun 16 07:17:01 pbs CRON[32081]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Jun 16 07:17:01 pbs CRON[32080]: pam_unix(cron:session): session closed for user root
Jun 16 07:18:08 pbs proxmox-backup-proxy[1205]: rrd journal successfully committed (25 files in 0.015 seconds)
Jun 16 07:28:31 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/209/2025-06-16T04:36:16Z/client.log.blob
Jun 16 07:28:34 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/216/2025-06-16T05:27:48Z"
Jun 16 07:32:35 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/216/2025-06-16T05:27:48Z/client.log.blob
Jun 16 07:32:36 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/217/2025-06-16T05:31:52Z"
Jun 16 07:34:16 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/217/2025-06-16T05:31:52Z/client.log.blob
Jun 16 07:34:16 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/306/2025-06-16T05:33:33Z"
Jun 16 07:34:19 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/306/2025-06-16T05:33:33Z/client.log.blob
Jun 16 07:34:23 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/307/2025-06-16T05:33:36Z"
Jun 16 07:36:18 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/307/2025-06-16T05:33:36Z/client.log.blob
Jun 16 07:36:45 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/203/2025-06-16T05:36:02Z"
Jun 16 07:36:50 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/203/2025-06-16T05:36:02Z/client.log.blob
Jun 16 07:37:03 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/208/2025-06-16T05:36:07Z"
Jun 16 07:37:28 pbs chronyd[1182]: Source 157.90.24.29 replaced with 88.99.101.252 (2.debian.pool.ntp.org)
Jun 16 07:38:04 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/208/2025-06-16T05:36:07Z/client.log.blob
Jun 16 07:38:07 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/209/2025-06-16T05:37:21Z"
Jun 16 07:40:00 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/209/2025-06-16T05:37:21Z/client.log.blob
Jun 16 07:40:02 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/216/2025-06-16T05:39:17Z"
Jun 16 07:40:08 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/216/2025-06-16T05:39:17Z/client.log.blob
Jun 16 07:40:09 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/217/2025-06-16T05:39:26Z"
Jun 16 07:40:11 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/217/2025-06-16T05:39:26Z/client.log.blob
Jun 16 07:40:11 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/306/2025-06-16T05:39:28Z"
Jun 16 07:40:13 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/306/2025-06-16T05:39:28Z/client.log.blob
Jun 16 07:40:14 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/307/2025-06-16T05:39:30Z"
Jun 16 07:40:22 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/307/2025-06-16T05:39:30Z/client.log.blob
Jun 16 07:48:11 pbs proxmox-backup-proxy[1205]: rrd journal successfully committed (25 files in 0.012 seconds)
 
Code: 
Jun 19 04:17:01 pbs CRON[53929]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)

Jun 19 04:17:01 pbs CRON[53930]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)

Jun 19 04:17:01 pbs CRON[53929]: pam_unix(cron:session): session closed for user root

Jun 19 04:19:28 pbs proxmox-backup-proxy[1205]: rrd journal successfully committed (25 files in 0.010 seconds)

Jun 19 04:34:42 pbs chronyd[1182]: Source 88.198.200.96 replaced with 168.119.211.223 (2.debian.pool.ntp.org)

Jun 19 04:49:21 pbs systemd[1]: Starting proxmox-backup-daily-update.service - Daily Proxmox Backup Server update and maintenance activities...

Jun 19 04:49:22 pbs systemd[1]: proxmox-backup-daily-update.service: Deactivated successfully.

Jun 19 04:49:22 pbs systemd[1]: Finished proxmox-backup-daily-update.service - Daily Proxmox Backup Server update and maintenance activities.

Jun 19 04:49:22 pbs systemd[1]: proxmox-backup-daily-update.service: Consumed 1.004s CPU time.

Jun 19 04:49:28 pbs proxmox-backup-proxy[1205]: rrd journal successfully committed (25 files in 0.010 seconds)

Jun 19 05:08:58 pbs chronyd[1182]: Source 5.75.181.179 replaced with 158.180.28.150 (2.debian.pool.ntp.org)

Jun 19 05:17:01 pbs CRON[54399]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)

Jun 19 05:17:01 pbs CRON[54400]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)

Jun 19 05:17:01 pbs CRON[54399]: pam_unix(cron:session): session closed for user root

Jun 19 05:19:28 pbs proxmox-backup-proxy[1205]: rrd journal successfully committed (25 files in 0.010 seconds)

Jun 19 05:39:23 pbs chronyd[1182]: Source 131.234.220.232 replaced with 188.245.32.133 (2.debian.pool.ntp.org)

Jun 19 05:49:28 pbs proxmox-backup-proxy[1205]: rrd journal successfully committed (25 files in 0.010 seconds)

Jun 19 06:00:14 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.21: "ns/cluster1/vm/204/2025-06-19T04:00:02Z"

Jun 19 06:00:15 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.34: "ns/cluster1/vm/202/2025-06-19T04:00:02Z"

Jun 19 06:00:40 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/204/2025-06-19T04:00:02Z/client.log.blob

Jun 19 06:00:41 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.21: "ns/cluster1/vm/205/2025-06-19T04:00:29Z"

Jun 19 06:00:44 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/203/2025-06-19T04:00:00Z"

Jun 19 06:01:03 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/203/2025-06-19T04:00:00Z/client.log.blob

Jun 19 06:01:16 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/208/2025-06-19T04:00:20Z"

Jun 19 06:01:23 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/205/2025-06-19T04:00:29Z/client.log.blob

Jun 19 06:02:07 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/202/2025-06-19T04:00:02Z/client.log.blob

Jun 19 06:02:13 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.34: "ns/cluster1/vm/207/2025-06-19T04:01:56Z"

Jun 19 06:11:21 pbs systemd[1]: Starting apt-daily-upgrade.service - Daily apt upgrade and clean activities...

Jun 19 06:11:22 pbs systemd[1]: apt-daily-upgrade.service: Deactivated successfully.

Jun 19 06:11:22 pbs systemd[1]: Finished apt-daily-upgrade.service - Daily apt upgrade and clean activities.

Jun 19 06:12:03 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/207/2025-06-19T04:01:56Z/client.log.blob

Jun 19 06:12:19 pbs chronyd[1182]: Source 172.104.138.148 replaced with 80.151.186.5 (2.debian.pool.ntp.org)

Jun 19 06:17:01 pbs CRON[54806]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)

Jun 19 06:17:01 pbs CRON[54807]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)

Jun 19 06:17:01 pbs CRON[54806]: pam_unix(cron:session): session closed for user root

Jun 19 06:19:28 pbs proxmox-backup-proxy[1205]: rrd journal successfully committed (25 files in 0.012 seconds)

Jun 19 06:20:05 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/208/2025-06-19T04:00:20Z/client.log.blob

Jun 19 06:20:08 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/209/2025-06-19T04:19:22Z"

Jun 19 06:25:01 pbs CRON[54921]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)

Jun 19 06:25:01 pbs CRON[54922]: (root) CMD (test -x /usr/sbin/anacron || { cd / && run-parts --report /etc/cron.daily; })

Jun 19 06:25:01 pbs CRON[54921]: pam_unix(cron:session): session closed for user root

Jun 19 06:44:48 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/209/2025-06-19T04:19:22Z/client.log.blob

Jun 19 06:44:51 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/216/2025-06-19T04:44:05Z"

Jun 19 06:46:42 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/216/2025-06-19T04:44:05Z/client.log.blob

Jun 19 06:46:43 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/217/2025-06-19T04:45:59Z"

Jun 19 06:47:41 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/217/2025-06-19T04:45:59Z/client.log.blob

Jun 19 06:47:42 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/306/2025-06-19T04:46:58Z"

Jun 19 06:47:43 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/306/2025-06-19T04:46:58Z/client.log.blob

Jun 19 06:47:48 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/307/2025-06-19T04:47:00Z"

Jun 19 06:48:52 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/307/2025-06-19T04:47:00Z/client.log.blob

Jun 19 06:49:29 pbs proxmox-backup-proxy[1205]: rrd journal successfully committed (25 files in 0.013 seconds)

Jun 19 06:52:23 pbs chronyd[1182]: Source 93.241.86.156 replaced with 173.249.58.145 (2.debian.pool.ntp.org)

Jun 19 07:00:15 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.21: "ns/cluster1/vm/204/2025-06-19T05:00:03Z"

Jun 19 07:00:18 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.34: "ns/cluster1/vm/202/2025-06-19T05:00:04Z"

Jun 19 07:00:28 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/204/2025-06-19T05:00:03Z/client.log.blob

Jun 19 07:00:29 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.21: "ns/cluster1/vm/205/2025-06-19T05:00:17Z"

Jun 19 07:00:47 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/203/2025-06-19T05:00:00Z"

Jun 19 07:00:48 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/205/2025-06-19T05:00:17Z/client.log.blob

Jun 19 07:00:52 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/202/2025-06-19T05:00:04Z/client.log.blob

Jun 19 07:00:55 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/203/2025-06-19T05:00:00Z/client.log.blob

Jun 19 07:00:56 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.34: "ns/cluster1/vm/207/2025-06-19T05:00:40Z"

Jun 19 07:01:07 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/208/2025-06-19T05:00:12Z"

Jun 19 07:01:29 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/207/2025-06-19T05:00:40Z/client.log.blob

Jun 19 07:02:32 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/208/2025-06-19T05:00:12Z/client.log.blob

Jun 19 07:02:35 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/209/2025-06-19T05:01:49Z"

Jun 19 07:04:08 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/209/2025-06-19T05:01:49Z/client.log.blob

Jun 19 07:04:10 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/216/2025-06-19T05:03:25Z"

Jun 19 07:04:30 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/216/2025-06-19T05:03:25Z/client.log.blob

Jun 19 07:04:30 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/217/2025-06-19T05:03:47Z"

Jun 19 07:04:34 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/217/2025-06-19T05:03:47Z/client.log.blob

Jun 19 07:04:34 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/306/2025-06-19T05:03:51Z"

Jun 19 07:04:36 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/306/2025-06-19T05:03:51Z/client.log.blob

Jun 19 07:04:39 pbs proxmox-backup-proxy[1205]: starting new backup on datastore 'backup' from ::ffff:192.168.160.30: "ns/cluster1/vm/307/2025-06-19T05:03:53Z"

Jun 19 07:04:48 pbs proxmox-backup-proxy[1205]: Upload backup log to datastore 'backup', namespace 'cluster1' vm/307/2025-06-19T05:03:53Z/client.log.blob

Jun 19 07:17:01 pbs CRON[55672]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)

Jun 19 07:17:01 pbs CRON[55673]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)

Jun 19 07:17:01 pbs CRON[55672]: pam_unix(cron:session): session closed for user root

Jun 19 07:19:29 pbs proxmox-backup-proxy[1205]: rrd journal successfully committed (25 files in 0.010 seconds)

Jun 19 07:26:50 pbs chronyd[1182]: Source 168.119.211.223 replaced with 85.215.166.214 (2.debian.pool.ntp.org)

Jun 19 07:40:21 pbs systemd[1]: Starting apt-daily.service - Daily apt download activities...

Jun 19 07:40:21 pbs systemd[1]: apt-daily.service: Deactivated successfully.

Jun 19 07:40:21 pbs systemd[1]: Finished apt-daily.service - Daily apt download activities.

Jun 19 07:49:29 pbs proxmox-backup-proxy[1205]: rrd journal successfully committed (25 files in 0.010 seconds)
 
Das hat immense Auswirkungen auf die Performance vom GC
Aktueller Lauf nach der Cache/RAM-Leerung heut früh, er scheint aber gerade wieder den RAM zu befüllen ab 21:05:
1750362787087.png
Laufzeit ohne vorher gehaltenen Cache: 4% -> 24min er beschleunigt aber hintenraus:

2025-06-19T21:05:01+02:00: Start GC phase1 (mark used chunks)
2025-06-19T21:05:01+02:00: marked 1% (19 of 1844 index files)
2025-06-19T21:08:12+02:00: marked 2% (37 of 1844 index files)
2025-06-19T21:16:25+02:00: marked 3% (56 of 1844 index files)
2025-06-19T21:29:13+02:00: marked 4% (74 of 1844 index files)
2025-06-19T21:56:35+02:00: marked 5% (93 of 1844 index files)
2025-06-19T21:57:45+02:00: marked 6% (111 of 1844 index files)
2025-06-19T21:58:57+02:00: marked 7% (130 of 1844 index files)
2025-06-19T22:02:50+02:00: marked 8% (148 of 1844 index files)
2025-06-19T22:06:02+02:00: marked 9% (166 of 1844 index files)
2025-06-19T22:09:32+02:00: marked 10% (185 of 1844 index files)
2025-06-19T22:15:06+02:00: marked 11% (203 of 1844 index files)
2025-06-19T22:18:45+02:00: marked 12% (222 of 1844 index files)
2025-06-19T22:24:38+02:00: marked 13% (240 of 1844 index files)
2025-06-19T22:31:49+02:00: marked 14% (259 of 1844 index files)
2025-06-19T22:36:02+02:00: marked 15% (277 of 1844 index files)
2025-06-19T22:36:15+02:00: marked 16% (296 of 1844 index files)
2025-06-19T22:43:17+02:00: marked 17% (314 of 1844 index files)
2025-06-19T22:45:05+02:00: marked 18% (332 of 1844 index files)
2025-06-19T22:46:59+02:00: marked 19% (351 of 1844 index files)
2025-06-19T22:50:49+02:00: marked 20% (369 of 1844 index files)
2025-06-19T22:53:13+02:00: marked 21% (388 of 1844 index files)
2025-06-19T23:04:08+02:00: marked 22% (406 of 1844 index files)
2025-06-19T23:09:04+02:00: marked 23% (425 of 1844 index files)
2025-06-19T23:10:05+02:00: marked 24% (443 of 1844 index files)
2025-06-19T23:10:06+02:00: marked 25% (461 of 1844 index files)
2025-06-19T23:10:08+02:00: marked 26% (480 of 1844 index files)
2025-06-19T23:11:14+02:00: marked 27% (498 of 1844 index files)
2025-06-19T23:11:43+02:00: marked 28% (517 of 1844 index files)
2025-06-19T23:11:45+02:00: marked 29% (535 of 1844 index files)
2025-06-19T23:11:46+02:00: marked 30% (554 of 1844 index files)
2025-06-19T23:12:01+02:00: marked 31% (572 of 1844 index files)
2025-06-19T23:16:40+02:00: marked 32% (591 of 1844 index files)
2025-06-19T23:17:03+02:00: marked 33% (609 of 1844 index files)
2025-06-19T23:17:11+02:00: marked 34% (627 of 1844 index files)
2025-06-19T23:17:17+02:00: marked 35% (646 of 1844 index files)
2025-06-19T23:17:39+02:00: marked 36% (664 of 1844 index files)
2025-06-19T23:20:29+02:00: marked 37% (683 of 1844 index files)
2025-06-19T23:20:39+02:00: marked 38% (701 of 1844 index files)
2025-06-19T23:20:39+02:00: marked 39% (720 of 1844 index files)
2025-06-19T23:21:25+02:00: marked 40% (738 of 1844 index files)
2025-06-19T23:21:48+02:00: marked 41% (757 of 1844 index files)
2025-06-19T23:22:01+02:00: marked 42% (775 of 1844 index files)
2025-06-19T23:22:07+02:00: marked 43% (793 of 1844 index files)
2025-06-19T23:22:16+02:00: marked 44% (812 of 1844 index files)
2025-06-19T23:22:22+02:00: marked 45% (830 of 1844 index files)
2025-06-19T23:22:56+02:00: marked 46% (849 of 1844 index files)
2025-06-19T23:23:06+02:00: marked 47% (867 of 1844 index files)
2025-06-19T23:23:30+02:00: marked 48% (886 of 1844 index files)
2025-06-19T23:23:49+02:00: marked 49% (904 of 1844 index files)
2025-06-19T23:24:11+02:00: marked 50% (922 of 1844 index files)
2025-06-19T23:24:29+02:00: marked 51% (941 of 1844 index files)
2025-06-19T23:24:34+02:00: marked 52% (959 of 1844 index files)
2025-06-19T23:24:50+02:00: marked 53% (978 of 1844 index files)
2025-06-19T23:24:52+02:00: marked 54% (996 of 1844 index files)
2025-06-19T23:24:56+02:00: marked 55% (1015 of 1844 index files)
2025-06-19T23:24:59+02:00: marked 56% (1033 of 1844 index files)
2025-06-19T23:25:09+02:00: marked 57% (1052 of 1844 index files)
2025-06-19T23:25:12+02:00: marked 58% (1070 of 1844 index files)
2025-06-19T23:25:22+02:00: marked 59% (1088 of 1844 index files)
2025-06-19T23:25:28+02:00: marked 60% (1107 of 1844 index files)
2025-06-19T23:25:39+02:00: marked 61% (1125 of 1844 index files)
2025-06-19T23:25:54+02:00: marked 62% (1144 of 1844 index files)
2025-06-19T23:26:01+02:00: marked 63% (1162 of 1844 index files)
2025-06-19T23:26:33+02:00: marked 64% (1181 of 1844 index files)
2025-06-19T23:26:46+02:00: marked 65% (1199 of 1844 index files)
2025-06-19T23:26:48+02:00: marked 66% (1218 of 1844 index files)
2025-06-19T23:27:03+02:00: marked 67% (1236 of 1844 index files)
2025-06-19T23:27:04+02:00: marked 68% (1254 of 1844 index files)
2025-06-19T23:27:16+02:00: marked 69% (1273 of 1844 index files)
2025-06-19T23:27:32+02:00: marked 70% (1291 of 1844 index files)
2025-06-19T23:27:41+02:00: marked 71% (1310 of 1844 index files)
2025-06-19T23:27:54+02:00: marked 72% (1328 of 1844 index files)
2025-06-19T23:27:58+02:00: marked 73% (1347 of 1844 index files)
2025-06-19T23:28:08+02:00: marked 74% (1365 of 1844 index files)
2025-06-19T23:28:09+02:00: marked 75% (1383 of 1844 index files)
2025-06-19T23:28:10+02:00: marked 76% (1402 of 1844 index files)
2025-06-19T23:28:18+02:00: marked 77% (1420 of 1844 index files)
2025-06-19T23:28:24+02:00: marked 78% (1439 of 1844 index files)
2025-06-19T23:28:30+02:00: marked 79% (1457 of 1844 index files)
2025-06-19T23:28:36+02:00: marked 80% (1476 of 1844 index files)
2025-06-19T23:28:37+02:00: marked 81% (1494 of 1844 index files)
2025-06-19T23:28:46+02:00: marked 82% (1513 of 1844 index files)
2025-06-19T23:29:15+02:00: marked 83% (1531 of 1844 index files)
2025-06-19T23:29:21+02:00: marked 84% (1549 of 1844 index files)
2025-06-19T23:29:25+02:00: marked 85% (1568 of 1844 index files)
2025-06-19T23:29:33+02:00: marked 86% (1586 of 1844 index files)
2025-06-19T23:29:44+02:00: marked 87% (1605 of 1844 index files)
2025-06-19T23:29:54+02:00: marked 88% (1623 of 1844 index files)
2025-06-19T23:30:11+02:00: marked 89% (1642 of 1844 index files)
2025-06-19T23:30:17+02:00: marked 90% (1660 of 1844 index files)
2025-06-19T23:30:31+02:00: marked 91% (1679 of 1844 index files)
2025-06-19T23:30:40+02:00: marked 92% (1697 of 1844 index files)
2025-06-19T23:30:48+02:00: marked 93% (1715 of 1844 index files)
2025-06-19T23:31:01+02:00: marked 94% (1734 of 1844 index files)
2025-06-19T23:31:20+02:00: marked 95% (1752 of 1844 index files)
2025-06-19T23:31:32+02:00: marked 96% (1771 of 1844 index files)
2025-06-19T23:31:43+02:00: marked 97% (1789 of 1844 index files)
2025-06-19T23:32:02+02:00: marked 98% (1808 of 1844 index files)
2025-06-19T23:32:05+02:00: marked 99% (1826 of 1844 index files)
2025-06-19T23:32:14+02:00: marked 100% (1844 of 1844 index files)

Laufzeit mit "vollem" Cache: 4% -> 5s
Komplett fertig in 37min mit 1844 Indexfiles und 15 Millionen Chunks und das mit nem "billo" HDD RAID 6 aus 8x18TB. Das ist mega!
Es scheint also möglich zu sein, in einem gewissen "Gesamtzustand des Systems", das er so schnell ist.
1750362927300.png

1750411126662.png



aktuelle Cachebelegung bei langsamen GC:
Da scheint mir sehr viel in der nähe 100% zu laufen -> ich habe Gesamt 64GB RAM -> noch ca. 40GB frei mit paar GB Puffer für Unvorhergesehenes und dem was jetzt belegt ist.

Wenn ich das hier richtig lese sind ja Gesamt nur 4GB Cache dort auslesbar -> das würde zur Grundlinie, unter die er nie groß drunterfällt passen.
Dann wird es spannend welche Prozesse da über den 4GB RAM belegen -> die werden dann vmtl. im
Code: 
slabtop
nicht zu sehen sein.

1750363451073.png
 
Last edited:
Planmäßig der 1. Verify parallel automatisch gestartet da der GC eigentlich schon durch sein sollte.
Bewusst jetzt aufeinander laufen lassen um zu schauen wie die sich jetzt gegenseitig bremsen/reagieren in ihren Laufzeiten.
Es schaut auch so aus als läge nicht viel Last auf dem Raid während des GC.
Ich habe da schon Spitzen von 7,5K IOPS und 120ms IO Delay gesehen.

Load (Screenshots sind leicht zueinander verschoben durch den Zoom):
1750408442939.png



1750364659318.png
 
Last edited:
Garbage Collection vor Update: >4,5h
Garbage Collection nach Update ohne gehaltenen Daten im ?-Cache: 2,5h
Garbage Collection nach Update mit gehaltenen Daten im ?-Cache: 30-40min

Wieder RAM Drop um 6:00 von 13GB auf 5,6GB.
1750406697495.png
 
Last edited:
Ich gehe mit unserem Linuxspezi jetzt mal die Grundkonfiguration von dem PBS durch ob da alles korrekt ist.
Wir haben das System "übernommen" und selbst nicht grundkonfiguriert.
Das versuchen wir komplett seit nem halben Jahr "gerade zu ziehen" in allen Belangen.

Nächster Schritt unsererseits ist es die Kernelcaches zu checken auf max. Wert und diesen zu erhöhen sowie und die Pressure zu verringern damit er Daten länger vorhält für Inode/Dentry.
https://manhart.blog/2020/04/linux-leistungsverbesserungen/
 
Last edited:
Was mir jetzt anhand des RAM Verhaltens als Idee gekommen ist:
Kann es sein das der LRU Cache nicht wie geplant geleert wird nach Abschluss und wir deshalb "durch Zufall" den Performancezuwachs hatten weil er auf diesen wieder zugegreifen konnte?
Nach dem was du oben beschrieben hast wie er funktioniert, wäre ja der normale Lauf mit leeren LRU Cache beim Start was dem 2,5h Lauf entsprechen sollte der dann ab ca. 40% bei uns schneller wird durch den nun gefüllten LRU Cache, was er vor dem Update nicht gemacht hat.
Oder wird wärend des GCs noch ein anderer Cache befüllt?

Gibt es eine Möglichkeit das zu monitoren/auszulesen?
 
Last edited:
Lun4r said:
Was mir jetzt anhand des RAM Verhaltens als Idee gekommen ist:
Kann es sein das der LRU Cache nicht wie geplant geleert wird nach Abschluss und wir deshalb "durch Zufall" den Performancezuwachs hatten weil er auf diesen wieder zugegreifen konnte?
Click to expand...
Nein, dieser Speicher wird sicher noch während der GC freigegeben.

Lun4r said:
Nach dem was du oben beschrieben hast wie er funktioniert, wäre ja der normale Lauf mit leeren LRU Cache beim Start was dem 2,5h Lauf entsprechen sollte der dann ab ca. 40% bei uns schneller wird, was er vor dem Update nicht gemacht hat.
Oder wird wärend des GCs noch ein anderer Cache befüllt?
Click to expand...
Nein, die LRU cache MUSS beim Start stets leer sein, das würde sonst keinen Sinn machen. Nach Start der garbage collection muss mindestens einmal pro chunk auf das Filesystem zugegriffen werden um den chunk für den aktuellen garabage collection run als in Verwendung zu markieren.

Lun4r said:
Gibt es eine Möglichkeit das zu monitoren/auszulesen?
Click to expand...
Nein, was man jedoch monitoren kann ist die Anzahl der LInux syscalls für die atime update Zugriffe wia strace, siehe dazu https://forum.proxmox.com/threads/proxmox-backup-server-3-4-released.164869/post-762993
 
Last edited:
  • Like
Reactions: Lun4r
Bin jetzt eine Woche im Urlaub.
Wir haben den PBS ins Grafana gehoben und können den (Cache/) Server bis ins kleinste Detail monitoren.
Ich mach dann mal ne Auswertung übernächste Woche.
Einen Hinweis gibt es schon welcher Cache ist der um 6:00 geleert wird und aber nicht durch welchen Job/Auslöser die Leerung erfolgt:

14:00 startet verify tägliche Backups -> der scheint auch direkt in den/einen LRU list Cache zu schreiben. Screenshot 3
16:08 fertig verify tägliche Backups -> LRU List Cache wird nicht geleert
21:01 Prune
21:05 GC (Cache vmtl. in Screenshot 5 sichtbar)
22:00 start verify stündliche Backups
23:39 GC fertig
06:00 LRU Cache wird geleert (warum auch immer -> immer gegen 6)
06:00 start stündliche Backups -> läuft jeden Tag um 6 los, aber der LRU Cache wurde nicht jeden Tag um 6 geleert wie eingangs beschrieben -> kann nicht der Auslöser sein.
09:20 fertig verify stündliche Backups

1750496630893.png

1750496490879.png

gefiltert:
1750495546897.png
ohne Filter:
1750496727156.png

Das hier scheint der GC Cache zu sein von den Zeiten her.
Wie du beschrieben hast -> er wird neu aufgebaut und direkt danach geleert.
1750496455656.png

1750496549466.png

1750496570177.png
 
Last edited:
Auch von Interesse wäre die PSI zu monitoren, siehe https://docs.kernel.org/accounting/psi.html

Korrelieren die memory drops im "ohne Filter" graph oben mit backup jobs? Vermutlich verdrängen verification und backup jobs Teilweise die GC Metadaten aus dem cache. Man könnte auch eine Nacht ohne verify job machen, und sehen ob dies etwas am verhalten der Caches ändert.

Mittels vfs_cache_pressure kann man versuchen den Kernel dahingehend zu bewegen, inode und dentry Objekte eher im cache zu halten.
 
  • Like
Reactions: Johannes S
Hi,
wir lassen die Daten aus dem PSI mitlaufen im Grafana.
Nach meinem Urlaub bau ich dann mal nen Diagram daraus.
1750708086895.png

vfs_Cache_pressure hat ich von 100 auf 50 gestellt und keine Änderung feststellen können -> habe jetzt nochmal auf 25 reduziert.

Ja das mit dem Backupstart um 6 würde dazu passen zum aktuellen Verhalten aber es passt nicht zu 100% (siehe Di und Mi).
Das meinte ich beim 1. Screenshot ganz oben mit "random".
Auch passt dazu das er trotz laufenden Verify den Cache löscht auf einen Schlag -> also kann es kein Verifyprozess sein.
Was allerdings auch interessant ist das er das nicht jede Stunde macht wenn die stündlichen Backups wieder reinkommen.
Wenn man das natürlich "provozieren" könnte das er den Cache hält hätten wir ein großes Improvement für den GC.

Ich tippe gerade auch darauf das man Glück mit dem Cache haben muss das die Daten über den Tag hinweg gelesen wurden damit sie dann zum GC noch im Cache sind.....Heute lief zum Beispiel kein Verify der schonmal paar Daten vorlädt und der GC ist entsprechend nochmal nen Stück langsamer als ab Dienstag (als der GC noch täglich lief).


1750708811174.png

Dazu der Laufplan:
1750709054531.png

Mo-Sa
1750708928444.png

Sa- So Full-Re-Verify der stündlichen und täglichen Backups und mit Tapeout (Laufzeiten vor Update)
1750709594179.png

Thema Verifys weglassen und dann schauen -> das sollten wir morgen früh sehen da heute nach neuem Plan (siehe unten) nur Prune und GC läuft.
An einem 2. tag kann ich auch die stündlichen backups einfach um 5 schon starten lassen und schauen ob es den RAM Drop ebenfalls verschiebt.

Aktuell habe ich jetzt von GC täglich auf nur noch einmal die Woche und die Re-verifyzeiten angehoben auf 90 Tage (um die Last zu dritteln) umgestellt und das Problem damit erstmal umgangen und genug Puffer für Unvorhergesehenes.

1750712995177.png

PS: LTO9 Tapeout schiebt seit dem Update mit konstanten 300MB/s bei einem Tapeout-Job aufs Band (1TB/h) statt wie vorher mit im Schnitt 0,2-0,3TB/h. Super Arbeit!
 
Last edited:
  • Like
Reactions: Johannes S
Kein RAM Drop heute früh im "RAM Used"
  • der Cache+Buffer war aber auch nicht am Maximum (da könnte hypothetisch auch ein Auslöser sein wenn das Backup anfängt).
  • oder/und weil kein verify ihn vollgeschrieben hat
1750755299959.png

Auch wenn der RAM Drop im RAM Used nicht da ist ist er im RAM Cahe+Buffer genau um 6 wieder:
1750756316606.png



GC Tuning Option wieder auf Standardwert gestellt um am nähesten an die Ausgangslage zu kommen in der der Cache behalten wurde.
1750755821770.png

Next Steps:
1. Eine Woche so laufen lassen.
1.1 Grundschema erstellen mit Monitoringwerten
2. stündliche Backups von um 6 auf um 5 als Startzeit vorziehen -> eine Woche laufen lassen
2.1 Auswertung dazu
3 64GB RAM nachrüsten und eine Woche laufen lassen
3.1 Auswertung dazu
4. vfs_Cache_pressure von 25 wieder auf 100 (Standardwert) stellen und eine Woche laufen lassen
4.1 Auswertung dazu

Wir lesen uns ca. in einem Monat wieder ;)
 
Last edited:
  • Like
Reactions: Johannes S and Chris
You must log in or register to reply here.
Top Bottom