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

L

Lun4r

New Member
Jun 17, 2025
12
2
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 bzw. dann hat er die gleiche wie vor dem Update:
Aktuell nach der Cache/RAM-Leerung, er scheint aber gerade wieder den RAM zu befüllen ab 21:05:
1750362787087.png
Laufzeit ohne Cache: 4% -> 24min
1750362850670.png

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
1750363874741.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.
1750364659318.png
 
You must log in or register to reply here.
Top Bottom