[SOLVED] proxmox-backup-client hangs for days and fill up ZFS storage on backup server

[mathilde]

Hi,

I recently encountered a problem with Proxmox Backup Client, a task was stuck for days on two hosts. I had to kill the process, but in the meantime the snapshot requested filled up the ZFS storage on the backup server. Usually a snapshot weight between 10 and 20GiB but the datastore storage grew up by almost 1.2TiB.



I waited for the usual maintenance tasks (garbage collection and pruning) to be done but no storage space was freed. I finally deleted the two incriminated snapshots, waited again for garbage collection and pruning but no luck...

Here is some informations about my setup server side:

proxmox-backup: not correctly installed (running kernel: 5.4.103-1-pve)
proxmox-backup-server: 1.0.9-1 (running version: 1.0.9)
pve-kernel-5.4: 6.3-7
pve-kernel-5.4.103-1-pve: 5.4.103-1
pve-kernel-5.4.98-1-pve: 5.4.98-1
ifupdown2: 3.0.0-1+pve3
libjs-extjs: 6.0.1-10
proxmox-backup-docs: 1.0.9-1
proxmox-backup-client: not correctly installed
proxmox-mini-journalreader: 1.1-1
proxmox-widget-toolkit: 2.4-6
pve-xtermjs: 4.7.0-3
smartmontools: 7.2-pve2
zfsutils-linux: 0.8.5-pve1

And client side:

$ proxmox-backup-client version
client version: 1.0.9

Thanks in advance for your help.
Best,

 

[fabian]

please post the garbage collection log..

 

[mathilde]

Hello Fabian,

Thank you for answering.
Here is the full log of the task after killing the process on the two hosts:

2021-03-24T08:52:09+01:00: starting garbage collection on store local
2021-03-24T08:52:09+01:00: Start GC phase1 (mark used chunks)
2021-03-24T08:52:10+01:00: marked 1% (5 of 480 index files)
2021-03-24T08:52:10+01:00: marked 2% (10 of 480 index files)
2021-03-24T08:52:11+01:00: marked 3% (15 of 480 index files)
2021-03-24T08:52:11+01:00: marked 4% (20 of 480 index files)
2021-03-24T08:52:11+01:00: marked 5% (24 of 480 index files)
2021-03-24T08:52:11+01:00: marked 6% (29 of 480 index files)
2021-03-24T08:52:11+01:00: marked 7% (34 of 480 index files)
2021-03-24T08:52:11+01:00: marked 8% (39 of 480 index files)
2021-03-24T08:52:11+01:00: marked 9% (44 of 480 index files)
2021-03-24T08:52:11+01:00: marked 10% (48 of 480 index files)
2021-03-24T08:52:11+01:00: marked 11% (53 of 480 index files)
2021-03-24T08:55:26+01:00: marked 12% (58 of 480 index files)
2021-03-24T08:57:13+01:00: marked 13% (63 of 480 index files)
2021-03-24T08:57:13+01:00: marked 14% (68 of 480 index files)
2021-03-24T08:57:15+01:00: marked 15% (72 of 480 index files)
2021-03-24T08:57:15+01:00: marked 16% (77 of 480 index files)
2021-03-24T08:57:16+01:00: marked 17% (82 of 480 index files)
2021-03-24T09:00:48+01:00: marked 18% (87 of 480 index files)
2021-03-24T09:00:48+01:00: marked 19% (92 of 480 index files)
2021-03-24T09:00:48+01:00: marked 20% (96 of 480 index files)
2021-03-24T09:00:49+01:00: marked 21% (101 of 480 index files)
2021-03-24T09:00:49+01:00: marked 22% (106 of 480 index files)
2021-03-24T09:00:49+01:00: marked 23% (111 of 480 index files)
2021-03-24T09:00:50+01:00: marked 24% (116 of 480 index files)
2021-03-24T09:00:50+01:00: marked 25% (120 of 480 index files)
2021-03-24T09:03:50+01:00: marked 26% (125 of 480 index files)
2021-03-24T09:03:50+01:00: marked 27% (130 of 480 index files)
2021-03-24T09:03:52+01:00: marked 28% (135 of 480 index files)
2021-03-24T09:03:53+01:00: marked 29% (140 of 480 index files)
2021-03-24T09:03:53+01:00: marked 30% (144 of 480 index files)
2021-03-24T09:03:53+01:00: marked 31% (149 of 480 index files)
2021-03-24T09:03:56+01:00: marked 32% (154 of 480 index files)
2021-03-24T09:08:53+01:00: marked 33% (159 of 480 index files)
2021-03-24T09:08:53+01:00: marked 34% (164 of 480 index files)
2021-03-24T09:08:54+01:00: marked 35% (168 of 480 index files)
2021-03-24T09:18:27+01:00: marked 36% (173 of 480 index files)
2021-03-24T09:18:31+01:00: marked 37% (178 of 480 index files)
2021-03-24T09:18:33+01:00: marked 38% (183 of 480 index files)
2021-03-24T09:18:34+01:00: marked 39% (188 of 480 index files)
2021-03-24T09:18:36+01:00: marked 40% (192 of 480 index files)
2021-03-24T09:18:37+01:00: marked 41% (197 of 480 index files)
2021-03-24T09:19:52+01:00: marked 42% (202 of 480 index files)
2021-03-24T09:33:12+01:00: marked 43% (207 of 480 index files)
2021-03-24T09:33:15+01:00: marked 44% (212 of 480 index files)
2021-03-24T09:33:15+01:00: marked 45% (216 of 480 index files)
2021-03-24T09:33:16+01:00: marked 46% (221 of 480 index files)
2021-03-24T09:34:36+01:00: marked 47% (226 of 480 index files)
2021-03-24T09:35:37+01:00: marked 48% (231 of 480 index files)
2021-03-24T09:35:41+01:00: marked 49% (236 of 480 index files)
2021-03-24T09:38:04+01:00: marked 50% (240 of 480 index files)
2021-03-24T09:38:04+01:00: marked 51% (245 of 480 index files)
2021-03-24T09:38:05+01:00: marked 52% (250 of 480 index files)
2021-03-24T09:38:05+01:00: marked 53% (255 of 480 index files)
2021-03-24T09:38:05+01:00: marked 54% (260 of 480 index files)
2021-03-24T09:38:05+01:00: marked 55% (264 of 480 index files)
2021-03-24T09:39:31+01:00: marked 56% (269 of 480 index files)
2021-03-24T09:40:41+01:00: marked 57% (274 of 480 index files)
2021-03-24T09:40:41+01:00: marked 58% (279 of 480 index files)
2021-03-24T09:40:41+01:00: marked 59% (284 of 480 index files)
2021-03-24T09:40:44+01:00: marked 60% (288 of 480 index files)
2021-03-24T09:40:44+01:00: marked 61% (293 of 480 index files)
2021-03-24T09:40:44+01:00: marked 62% (298 of 480 index files)
2021-03-24T09:43:02+01:00: marked 63% (303 of 480 index files)
2021-03-24T09:43:02+01:00: marked 64% (308 of 480 index files)
2021-03-24T09:43:02+01:00: marked 65% (312 of 480 index files)
2021-03-24T09:43:11+01:00: marked 66% (317 of 480 index files)
2021-03-24T09:56:40+01:00: marked 67% (322 of 480 index files)
2021-03-24T10:01:45+01:00: marked 68% (327 of 480 index files)
2021-03-24T10:01:46+01:00: marked 69% (332 of 480 index files)
2021-03-24T10:04:42+01:00: marked 70% (336 of 480 index files)
2021-03-24T10:04:42+01:00: marked 71% (341 of 480 index files)
2021-03-24T10:04:43+01:00: marked 72% (346 of 480 index files)
2021-03-24T10:04:43+01:00: marked 73% (351 of 480 index files)
2021-03-24T10:04:43+01:00: marked 74% (356 of 480 index files)
2021-03-24T10:04:44+01:00: marked 75% (360 of 480 index files)
2021-03-24T10:04:44+01:00: marked 76% (365 of 480 index files)
2021-03-24T10:04:45+01:00: marked 77% (370 of 480 index files)
2021-03-24T10:07:28+01:00: marked 78% (375 of 480 index files)
2021-03-24T10:07:28+01:00: marked 79% (380 of 480 index files)
2021-03-24T10:07:29+01:00: marked 80% (384 of 480 index files)
2021-03-24T10:07:29+01:00: marked 81% (389 of 480 index files)
2021-03-24T10:07:30+01:00: marked 82% (394 of 480 index files)
2021-03-24T10:07:30+01:00: marked 83% (399 of 480 index files)
2021-03-24T10:07:31+01:00: marked 84% (404 of 480 index files)
2021-03-24T10:07:31+01:00: marked 85% (408 of 480 index files)
2021-03-24T10:07:31+01:00: marked 86% (413 of 480 index files)
2021-03-24T10:07:31+01:00: marked 87% (418 of 480 index files)
2021-03-24T10:07:31+01:00: marked 88% (423 of 480 index files)
2021-03-24T10:07:31+01:00: marked 89% (428 of 480 index files)
2021-03-24T10:07:31+01:00: marked 90% (432 of 480 index files)
2021-03-24T10:07:31+01:00: marked 91% (437 of 480 index files)
2021-03-24T10:07:32+01:00: marked 92% (442 of 480 index files)
2021-03-24T10:07:32+01:00: marked 93% (447 of 480 index files)
2021-03-24T10:07:32+01:00: marked 94% (452 of 480 index files)
2021-03-24T10:07:32+01:00: marked 95% (456 of 480 index files)
2021-03-24T10:07:32+01:00: marked 96% (461 of 480 index files)
2021-03-24T10:07:32+01:00: marked 97% (466 of 480 index files)
2021-03-24T10:07:32+01:00: marked 98% (471 of 480 index files)
2021-03-24T10:07:32+01:00: marked 99% (476 of 480 index files)
2021-03-24T10:07:32+01:00: marked 100% (480 of 480 index files)
2021-03-24T10:07:32+01:00: Start GC phase2 (sweep unused chunks)
2021-03-24T10:07:42+01:00: processed 1% (6856 chunks)
2021-03-24T10:07:51+01:00: processed 2% (13776 chunks)
2021-03-24T10:08:00+01:00: processed 3% (20385 chunks)
2021-03-24T10:08:09+01:00: processed 4% (27174 chunks)
2021-03-24T10:08:18+01:00: processed 5% (33905 chunks)
2021-03-24T10:08:26+01:00: processed 6% (40597 chunks)
2021-03-24T10:08:35+01:00: processed 7% (47408 chunks)
2021-03-24T10:08:44+01:00: processed 8% (54193 chunks)
2021-03-24T10:08:53+01:00: processed 9% (61056 chunks)
2021-03-24T10:09:02+01:00: processed 10% (67811 chunks)
2021-03-24T10:09:10+01:00: processed 11% (74704 chunks)
2021-03-24T10:09:19+01:00: processed 12% (81507 chunks)
2021-03-24T10:09:29+01:00: processed 13% (88419 chunks)
2021-03-24T10:09:39+01:00: processed 14% (95243 chunks)
2021-03-24T10:09:49+01:00: processed 15% (102143 chunks)
2021-03-24T10:09:59+01:00: processed 16% (108800 chunks)
2021-03-24T10:10:08+01:00: processed 17% (115532 chunks)
2021-03-24T10:10:18+01:00: processed 18% (122312 chunks)
2021-03-24T10:10:29+01:00: processed 19% (129120 chunks)
2021-03-24T10:10:39+01:00: processed 20% (136002 chunks)
2021-03-24T10:10:49+01:00: processed 21% (142564 chunks)
2021-03-24T10:10:58+01:00: processed 22% (149282 chunks)
2021-03-24T10:11:07+01:00: processed 23% (156065 chunks)
2021-03-24T10:11:17+01:00: processed 24% (162763 chunks)
2021-03-24T10:11:27+01:00: processed 25% (169452 chunks)
2021-03-24T10:11:36+01:00: processed 26% (176162 chunks)
2021-03-24T10:11:46+01:00: processed 27% (182959 chunks)
2021-03-24T10:11:56+01:00: processed 28% (189680 chunks)
2021-03-24T10:12:05+01:00: processed 29% (196469 chunks)
2021-03-24T10:12:15+01:00: processed 30% (203133 chunks)
2021-03-24T10:12:24+01:00: processed 31% (209858 chunks)
2021-03-24T10:12:34+01:00: processed 32% (216540 chunks)
2021-03-24T10:12:44+01:00: processed 33% (223274 chunks)
2021-03-24T10:12:54+01:00: processed 34% (230183 chunks)
2021-03-24T10:13:04+01:00: processed 35% (237023 chunks)
2021-03-24T10:13:13+01:00: processed 36% (243828 chunks)
2021-03-24T10:13:22+01:00: processed 37% (250632 chunks)
2021-03-24T10:13:32+01:00: processed 38% (257436 chunks)
2021-03-24T10:13:42+01:00: processed 39% (264397 chunks)
2021-03-24T10:13:51+01:00: processed 40% (271106 chunks)
2021-03-24T10:14:00+01:00: processed 41% (277885 chunks)
2021-03-24T10:14:10+01:00: processed 42% (284523 chunks)
2021-03-24T10:14:18+01:00: processed 43% (291295 chunks)
2021-03-24T10:14:28+01:00: processed 44% (298153 chunks)
2021-03-24T10:14:37+01:00: processed 45% (304794 chunks)
2021-03-24T10:14:47+01:00: processed 46% (311579 chunks)
2021-03-24T10:14:57+01:00: processed 47% (318226 chunks)
2021-03-24T10:15:06+01:00: processed 48% (324850 chunks)
2021-03-24T10:15:16+01:00: processed 49% (331656 chunks)
2021-03-24T10:15:25+01:00: processed 50% (338516 chunks)
2021-03-24T10:15:34+01:00: processed 51% (345275 chunks)
2021-03-24T10:15:43+01:00: processed 52% (352072 chunks)
2021-03-24T10:15:52+01:00: processed 53% (358928 chunks)
2021-03-24T10:16:02+01:00: processed 54% (365746 chunks)
2021-03-24T10:16:10+01:00: processed 55% (372411 chunks)
2021-03-24T10:16:20+01:00: processed 56% (379128 chunks)
2021-03-24T10:16:29+01:00: processed 57% (385940 chunks)
2021-03-24T10:16:38+01:00: processed 58% (392656 chunks)
2021-03-24T10:16:48+01:00: processed 59% (399406 chunks)
2021-03-24T10:16:57+01:00: processed 60% (406191 chunks)
2021-03-24T10:17:07+01:00: processed 61% (412950 chunks)
2021-03-24T10:17:16+01:00: processed 62% (419736 chunks)
2021-03-24T10:17:26+01:00: processed 63% (426534 chunks)
2021-03-24T10:17:35+01:00: processed 64% (433279 chunks)
2021-03-24T10:17:44+01:00: processed 65% (439999 chunks)
2021-03-24T10:17:53+01:00: processed 66% (446791 chunks)
2021-03-24T10:18:02+01:00: processed 67% (453523 chunks)
2021-03-24T10:18:11+01:00: processed 68% (460243 chunks)
2021-03-24T10:18:20+01:00: processed 69% (467246 chunks)
2021-03-24T10:18:29+01:00: processed 70% (473896 chunks)
2021-03-24T10:18:39+01:00: processed 71% (480567 chunks)
2021-03-24T10:18:47+01:00: processed 72% (487346 chunks)
2021-03-24T10:18:56+01:00: processed 73% (494075 chunks)
2021-03-24T10:19:06+01:00: processed 74% (500900 chunks)
2021-03-24T10:19:15+01:00: processed 75% (507660 chunks)
2021-03-24T10:19:24+01:00: processed 76% (514488 chunks)
2021-03-24T10:19:33+01:00: processed 77% (521268 chunks)
2021-03-24T10:19:43+01:00: processed 78% (528053 chunks)
2021-03-24T10:19:51+01:00: processed 79% (534884 chunks)
2021-03-24T10:20:00+01:00: processed 80% (541687 chunks)
2021-03-24T10:20:09+01:00: processed 81% (548573 chunks)
2021-03-24T10:20:18+01:00: processed 82% (555233 chunks)
2021-03-24T10:20:26+01:00: processed 83% (562023 chunks)
2021-03-24T10:20:35+01:00: processed 84% (568831 chunks)
2021-03-24T10:20:45+01:00: processed 85% (575729 chunks)
2021-03-24T10:20:54+01:00: processed 86% (582382 chunks)
2021-03-24T10:21:02+01:00: processed 87% (589204 chunks)
2021-03-24T10:21:10+01:00: processed 88% (596049 chunks)
2021-03-24T10:21:19+01:00: processed 89% (602757 chunks)
2021-03-24T10:21:28+01:00: processed 90% (609559 chunks)
2021-03-24T10:21:37+01:00: processed 91% (616285 chunks)
2021-03-24T10:21:46+01:00: processed 92% (623164 chunks)
2021-03-24T10:21:55+01:00: processed 93% (630056 chunks)
2021-03-24T10:22:04+01:00: processed 94% (636959 chunks)
2021-03-24T10:22:13+01:00: processed 95% (643758 chunks)
2021-03-24T10:22:22+01:00: processed 96% (650478 chunks)
2021-03-24T10:22:31+01:00: processed 97% (657320 chunks)
2021-03-24T10:22:40+01:00: processed 98% (663966 chunks)
2021-03-24T10:22:49+01:00: processed 99% (670705 chunks)
2021-03-24T10:22:58+01:00: Removed garbage: 71.44 GiB
2021-03-24T10:22:58+01:00: Removed chunks: 31027
2021-03-24T10:22:58+01:00: Original data usage: 8.62 TiB
2021-03-24T10:22:58+01:00: On-Disk usage: 2.01 TiB (23.37%)
2021-03-24T10:22:58+01:00: On-Disk chunks: 646374
2021-03-24T10:22:58+01:00: Deduplication factor: 4.28
2021-03-24T10:22:58+01:00: Average chunk size: 3.27 MiB
2021-03-24T10:22:58+01:00: TASK OK

 

[mathilde]

And the one after removing the two snapshots:

2021-03-24T10:27:09+01:00: starting garbage collection on store local
2021-03-24T10:27:09+01:00: Start GC phase1 (mark used chunks)
2021-03-24T10:27:09+01:00: marked 1% (5 of 475 index files)
2021-03-24T10:27:09+01:00: marked 2% (10 of 475 index files)
2021-03-24T10:27:10+01:00: marked 3% (15 of 475 index files)
2021-03-24T10:27:10+01:00: marked 4% (19 of 475 index files)
2021-03-24T10:27:10+01:00: marked 5% (24 of 475 index files)
2021-03-24T10:27:10+01:00: marked 6% (29 of 475 index files)
2021-03-24T10:27:10+01:00: marked 7% (34 of 475 index files)
2021-03-24T10:27:10+01:00: marked 8% (38 of 475 index files)
2021-03-24T10:27:10+01:00: marked 9% (43 of 475 index files)
2021-03-24T10:27:10+01:00: marked 10% (48 of 475 index files)
2021-03-24T10:27:11+01:00: marked 11% (53 of 475 index files)
2021-03-24T10:27:11+01:00: marked 12% (57 of 475 index files)
2021-03-24T10:27:11+01:00: marked 13% (62 of 475 index files)
2021-03-24T10:27:11+01:00: marked 14% (67 of 475 index files)
2021-03-24T10:27:12+01:00: marked 15% (72 of 475 index files)
2021-03-24T10:27:12+01:00: marked 16% (76 of 475 index files)
2021-03-24T10:27:13+01:00: marked 17% (81 of 475 index files)
2021-03-24T10:27:13+01:00: marked 18% (86 of 475 index files)
2021-03-24T10:27:14+01:00: marked 19% (91 of 475 index files)
2021-03-24T10:27:14+01:00: marked 20% (95 of 475 index files)
2021-03-24T10:27:14+01:00: marked 21% (100 of 475 index files)
2021-03-24T10:27:15+01:00: marked 22% (105 of 475 index files)
2021-03-24T10:27:15+01:00: marked 23% (110 of 475 index files)
2021-03-24T10:27:15+01:00: marked 24% (114 of 475 index files)
2021-03-24T10:27:16+01:00: marked 25% (119 of 475 index files)
2021-03-24T10:27:16+01:00: marked 26% (124 of 475 index files)
2021-03-24T10:27:16+01:00: marked 27% (129 of 475 index files)
2021-03-24T10:27:17+01:00: marked 28% (133 of 475 index files)
2021-03-24T10:27:17+01:00: marked 29% (138 of 475 index files)
2021-03-24T10:27:17+01:00: marked 30% (143 of 475 index files)
2021-03-24T10:27:18+01:00: marked 31% (148 of 475 index files)
2021-03-24T10:27:19+01:00: marked 32% (152 of 475 index files)
2021-03-24T10:27:19+01:00: marked 33% (157 of 475 index files)
2021-03-24T10:27:19+01:00: marked 34% (162 of 475 index files)
2021-03-24T10:27:20+01:00: marked 35% (167 of 475 index files)
2021-03-24T10:27:20+01:00: marked 36% (171 of 475 index files)
2021-03-24T10:27:21+01:00: marked 37% (176 of 475 index files)
2021-03-24T10:27:21+01:00: marked 38% (181 of 475 index files)
2021-03-24T10:27:21+01:00: marked 39% (186 of 475 index files)
2021-03-24T10:27:22+01:00: marked 40% (190 of 475 index files)
2021-03-24T10:27:22+01:00: marked 41% (195 of 475 index files)
2021-03-24T10:27:22+01:00: marked 42% (200 of 475 index files)
2021-03-24T10:27:23+01:00: marked 43% (205 of 475 index files)
2021-03-24T10:27:23+01:00: marked 44% (209 of 475 index files)
2021-03-24T10:27:24+01:00: marked 45% (214 of 475 index files)
2021-03-24T10:27:24+01:00: marked 46% (219 of 475 index files)
2021-03-24T10:27:24+01:00: marked 47% (224 of 475 index files)
2021-03-24T10:27:24+01:00: marked 48% (228 of 475 index files)
2021-03-24T10:27:25+01:00: marked 49% (233 of 475 index files)
2021-03-24T10:27:25+01:00: marked 50% (238 of 475 index files)
2021-03-24T10:27:25+01:00: marked 51% (243 of 475 index files)
2021-03-24T10:27:25+01:00: marked 52% (247 of 475 index files)
2021-03-24T10:27:25+01:00: marked 53% (252 of 475 index files)
2021-03-24T10:27:25+01:00: marked 54% (257 of 475 index files)
2021-03-24T10:27:26+01:00: marked 55% (262 of 475 index files)
2021-03-24T10:27:26+01:00: marked 56% (266 of 475 index files)
2021-03-24T10:27:26+01:00: marked 57% (271 of 475 index files)
2021-03-24T10:27:26+01:00: marked 58% (276 of 475 index files)
2021-03-24T10:27:26+01:00: marked 59% (281 of 475 index files)
2021-03-24T10:27:26+01:00: marked 60% (285 of 475 index files)
2021-03-24T10:27:26+01:00: marked 61% (290 of 475 index files)
2021-03-24T10:27:26+01:00: marked 62% (295 of 475 index files)
2021-03-24T10:27:27+01:00: marked 63% (300 of 475 index files)
2021-03-24T10:27:27+01:00: marked 64% (304 of 475 index files)
2021-03-24T10:27:27+01:00: marked 65% (309 of 475 index files)
2021-03-24T10:27:27+01:00: marked 66% (314 of 475 index files)
2021-03-24T10:27:28+01:00: marked 67% (319 of 475 index files)
2021-03-24T10:27:28+01:00: marked 68% (323 of 475 index files)
2021-03-24T10:27:28+01:00: marked 69% (328 of 475 index files)
2021-03-24T10:27:29+01:00: marked 70% (333 of 475 index files)
2021-03-24T10:27:29+01:00: marked 71% (338 of 475 index files)
2021-03-24T10:27:29+01:00: marked 72% (342 of 475 index files)
2021-03-24T10:27:29+01:00: marked 73% (347 of 475 index files)
2021-03-24T10:27:30+01:00: marked 74% (352 of 475 index files)
2021-03-24T10:27:30+01:00: marked 75% (357 of 475 index files)
2021-03-24T10:27:30+01:00: marked 76% (361 of 475 index files)
2021-03-24T10:27:31+01:00: marked 77% (366 of 475 index files)
2021-03-24T10:27:31+01:00: marked 78% (371 of 475 index files)
2021-03-24T10:27:31+01:00: marked 79% (376 of 475 index files)
2021-03-24T10:27:32+01:00: marked 80% (380 of 475 index files)
2021-03-24T10:27:32+01:00: marked 81% (385 of 475 index files)
2021-03-24T10:27:32+01:00: marked 82% (390 of 475 index files)
2021-03-24T10:27:33+01:00: marked 83% (395 of 475 index files)
2021-03-24T10:27:33+01:00: marked 84% (399 of 475 index files)
2021-03-24T10:27:33+01:00: marked 85% (404 of 475 index files)
2021-03-24T10:27:33+01:00: marked 86% (409 of 475 index files)
2021-03-24T10:27:33+01:00: marked 87% (414 of 475 index files)
2021-03-24T10:27:33+01:00: marked 88% (418 of 475 index files)
2021-03-24T10:27:33+01:00: marked 89% (423 of 475 index files)
2021-03-24T10:27:33+01:00: marked 90% (428 of 475 index files)
2021-03-24T10:27:33+01:00: marked 91% (433 of 475 index files)
2021-03-24T10:27:33+01:00: marked 92% (437 of 475 index files)
2021-03-24T10:27:33+01:00: marked 93% (442 of 475 index files)
2021-03-24T10:27:33+01:00: marked 94% (447 of 475 index files)
2021-03-24T10:27:33+01:00: marked 95% (452 of 475 index files)
2021-03-24T10:27:33+01:00: marked 96% (456 of 475 index files)
2021-03-24T10:27:33+01:00: marked 97% (461 of 475 index files)
2021-03-24T10:27:34+01:00: marked 98% (466 of 475 index files)
2021-03-24T10:27:34+01:00: marked 99% (471 of 475 index files)
2021-03-24T10:27:34+01:00: marked 100% (475 of 475 index files)
2021-03-24T10:27:34+01:00: Start GC phase2 (sweep unused chunks)
2021-03-24T10:27:34+01:00: processed 1% (6557 chunks)
2021-03-24T10:27:34+01:00: processed 2% (13135 chunks)
2021-03-24T10:27:34+01:00: processed 3% (19454 chunks)
2021-03-24T10:27:34+01:00: processed 4% (25952 chunks)
2021-03-24T10:27:34+01:00: processed 5% (32387 chunks)
2021-03-24T10:27:34+01:00: processed 6% (38765 chunks)
2021-03-24T10:27:34+01:00: processed 7% (45235 chunks)
2021-03-24T10:27:34+01:00: processed 8% (51704 chunks)
2021-03-24T10:27:34+01:00: processed 9% (58217 chunks)
2021-03-24T10:27:34+01:00: processed 10% (64660 chunks)
2021-03-24T10:27:34+01:00: processed 11% (71232 chunks)
2021-03-24T10:27:34+01:00: processed 12% (77760 chunks)
2021-03-24T10:27:34+01:00: processed 13% (84343 chunks)
2021-03-24T10:27:35+01:00: processed 14% (90847 chunks)
2021-03-24T10:27:35+01:00: processed 15% (97428 chunks)
2021-03-24T10:27:35+01:00: processed 16% (103760 chunks)
2021-03-24T10:27:35+01:00: processed 17% (110192 chunks)
2021-03-24T10:27:35+01:00: processed 18% (116640 chunks)
2021-03-24T10:27:35+01:00: processed 19% (123117 chunks)
2021-03-24T10:27:35+01:00: processed 20% (129678 chunks)
2021-03-24T10:27:35+01:00: processed 21% (135926 chunks)
2021-03-24T10:27:35+01:00: processed 22% (142364 chunks)
2021-03-24T10:27:35+01:00: processed 23% (148849 chunks)
2021-03-24T10:27:35+01:00: processed 24% (155241 chunks)
2021-03-24T10:27:35+01:00: processed 25% (161634 chunks)
2021-03-24T10:27:35+01:00: processed 26% (168036 chunks)
2021-03-24T10:27:35+01:00: processed 27% (174528 chunks)
2021-03-24T10:27:35+01:00: processed 28% (180918 chunks)
2021-03-24T10:27:35+01:00: processed 29% (187382 chunks)
2021-03-24T10:27:35+01:00: processed 30% (193753 chunks)
2021-03-24T10:27:36+01:00: processed 31% (200179 chunks)
2021-03-24T10:27:36+01:00: processed 32% (206523 chunks)
2021-03-24T10:27:36+01:00: processed 33% (212926 chunks)
2021-03-24T10:27:36+01:00: processed 34% (219513 chunks)
2021-03-24T10:27:36+01:00: processed 35% (226039 chunks)
2021-03-24T10:27:36+01:00: processed 36% (232533 chunks)
2021-03-24T10:27:36+01:00: processed 37% (239035 chunks)
2021-03-24T10:27:36+01:00: processed 38% (245502 chunks)
2021-03-24T10:27:36+01:00: processed 39% (252149 chunks)
2021-03-24T10:27:36+01:00: processed 40% (258543 chunks)
2021-03-24T10:27:36+01:00: processed 41% (265046 chunks)
2021-03-24T10:27:36+01:00: processed 42% (271370 chunks)
2021-03-24T10:27:36+01:00: processed 43% (277835 chunks)
2021-03-24T10:27:36+01:00: processed 44% (284399 chunks)
2021-03-24T10:27:36+01:00: processed 45% (290738 chunks)
2021-03-24T10:27:36+01:00: processed 46% (297230 chunks)
2021-03-24T10:27:37+01:00: processed 47% (303584 chunks)
2021-03-24T10:27:37+01:00: processed 48% (309888 chunks)
2021-03-24T10:27:37+01:00: processed 49% (316389 chunks)
2021-03-24T10:27:37+01:00: processed 50% (322953 chunks)
2021-03-24T10:27:37+01:00: processed 51% (329425 chunks)
2021-03-24T10:27:37+01:00: processed 52% (335951 chunks)
2021-03-24T10:27:37+01:00: processed 53% (342514 chunks)
2021-03-24T10:27:37+01:00: processed 54% (349013 chunks)
2021-03-24T10:27:37+01:00: processed 55% (355400 chunks)
2021-03-24T10:27:37+01:00: processed 56% (361830 chunks)
2021-03-24T10:27:37+01:00: processed 57% (368329 chunks)
2021-03-24T10:27:37+01:00: processed 58% (374733 chunks)
2021-03-24T10:27:37+01:00: processed 59% (381177 chunks)
2021-03-24T10:27:37+01:00: processed 60% (387634 chunks)
2021-03-24T10:27:37+01:00: processed 61% (394083 chunks)
2021-03-24T10:27:37+01:00: processed 62% (400562 chunks)
2021-03-24T10:27:38+01:00: processed 63% (407038 chunks)
2021-03-24T10:27:38+01:00: processed 64% (413491 chunks)
2021-03-24T10:27:38+01:00: processed 65% (419922 chunks)
2021-03-24T10:27:38+01:00: processed 66% (426412 chunks)
2021-03-24T10:27:38+01:00: processed 67% (432847 chunks)
2021-03-24T10:27:38+01:00: processed 68% (439252 chunks)
2021-03-24T10:27:38+01:00: processed 69% (445899 chunks)
2021-03-24T10:27:38+01:00: processed 70% (452240 chunks)
2021-03-24T10:27:38+01:00: processed 71% (458593 chunks)
2021-03-24T10:27:38+01:00: processed 72% (465079 chunks)
2021-03-24T10:27:38+01:00: processed 73% (471514 chunks)
2021-03-24T10:27:38+01:00: processed 74% (478011 chunks)
2021-03-24T10:27:38+01:00: processed 75% (484473 chunks)
2021-03-24T10:27:38+01:00: processed 76% (490992 chunks)
2021-03-24T10:27:38+01:00: processed 77% (497433 chunks)
2021-03-24T10:27:38+01:00: processed 78% (503898 chunks)
2021-03-24T10:27:39+01:00: processed 79% (510404 chunks)
2021-03-24T10:27:39+01:00: processed 80% (516878 chunks)
2021-03-24T10:27:39+01:00: processed 81% (523445 chunks)
2021-03-24T10:27:39+01:00: processed 82% (529786 chunks)
2021-03-24T10:27:39+01:00: processed 83% (536261 chunks)
2021-03-24T10:27:39+01:00: processed 84% (542760 chunks)
2021-03-24T10:27:39+01:00: processed 85% (549319 chunks)
2021-03-24T10:27:39+01:00: processed 86% (555669 chunks)
2021-03-24T10:27:39+01:00: processed 87% (562200 chunks)
2021-03-24T10:27:39+01:00: processed 88% (568766 chunks)
2021-03-24T10:27:39+01:00: processed 89% (575147 chunks)
2021-03-24T10:27:39+01:00: processed 90% (581632 chunks)
2021-03-24T10:27:39+01:00: processed 91% (588037 chunks)
2021-03-24T10:27:39+01:00: processed 92% (594615 chunks)
2021-03-24T10:27:39+01:00: processed 93% (601182 chunks)
2021-03-24T10:27:39+01:00: processed 94% (607740 chunks)
2021-03-24T10:27:40+01:00: processed 95% (614225 chunks)
2021-03-24T10:27:40+01:00: processed 96% (620642 chunks)
2021-03-24T10:27:40+01:00: processed 97% (627178 chunks)
2021-03-24T10:27:40+01:00: processed 98% (633530 chunks)
2021-03-24T10:27:40+01:00: processed 99% (639966 chunks)
2021-03-24T10:27:40+01:00: Removed garbage: 0 B
2021-03-24T10:27:40+01:00: Removed chunks: 0
2021-03-24T10:27:40+01:00: Pending removals: 108.81 MiB (in 108 chunks)
2021-03-24T10:27:40+01:00: Original data usage: 8.59 TiB
2021-03-24T10:27:40+01:00: On-Disk usage: 2.01 TiB (23.44%)
2021-03-24T10:27:40+01:00: On-Disk chunks: 646266
2021-03-24T10:27:40+01:00: Deduplication factor: 4.27
2021-03-24T10:27:40+01:00: Average chunk size: 3.27 MiB
2021-03-24T10:27:40+01:00: TASK OK

 

[fabian]

so those two snapshots were not responsible for the size increase.. it's possible you are affected by a bug affecting CT and host backups that can affect deduplication (fixed by https://git.proxmox.com/?p=pxar.git;a=commit;h=180186c5676d34e6f969ef223241bdbaa01f5f44 which is contained in proxmox-backup-client >=1.0.11-1) - did you see a sharp decrease in deduplication factors (visible in the backup client output/log)? if so, upgrading to 1.0.11-1 should fix future backups. to free the space, all the affected backup snapshots (made with 1.0.9 and .10) need to be pruned followed by a GC

 

[mathilde]

Thanks for your answer.

Here is the logs from the host backup made of a server impacted by the hang up proxmox-backup-client process (the day before the process froze actually):

2021-03-14T02:05:02+01:00: starting new backup on datastore 'local': "host/crld-web-01/2021-03-14T01:05:01Z"
2021-03-14T02:05:02+01:00: download 'index.json.blob' from previous backup.
2021-03-14T02:05:02+01:00: created new dynamic index 1 ("host/crld-web-01/2021-03-14T01:05:01Z/catalog.pcat1.didx")
2021-03-14T02:05:02+01:00: register chunks in 'root.pxar.didx' from previous backup.
2021-03-14T02:05:02+01:00: download 'root.pxar.didx' from previous backup.
2021-03-14T02:05:02+01:00: created new dynamic index 2 ("host/crld-web-01/2021-03-14T01:05:01Z/root.pxar.didx")
2021-03-14T02:07:38+01:00: Upload statistics for 'root.pxar.didx'
2021-03-14T02:07:38+01:00: UUID: 01f36492c3964df8908e94ec4c165faf
2021-03-14T02:07:38+01:00: Checksum: 985e9ee695fdff4c7ee8813916c9e4f28d4995af94c060916a52f6b557bb7b42
2021-03-14T02:07:38+01:00: Size: 12765556014
2021-03-14T02:07:38+01:00: Chunk count: 1778
2021-03-14T02:07:38+01:00: Upload size: 308749685 (2%)
2021-03-14T02:07:38+01:00: Duplicates: 1730+0 (97%)
2021-03-14T02:07:38+01:00: Compression: 9%
2021-03-14T02:07:38+01:00: successfully closed dynamic index 2
2021-03-14T02:07:38+01:00: register chunks in 'mnt.pxar.didx' from previous backup.
2021-03-14T02:07:38+01:00: download 'mnt.pxar.didx' from previous backup.
2021-03-14T02:07:38+01:00: created new dynamic index 3 ("host/crld-web-01/2021-03-14T01:05:01Z/mnt.pxar.didx")
2021-03-14T02:09:26+01:00: Upload statistics for 'mnt.pxar.didx'
2021-03-14T02:09:26+01:00: UUID: 1fb423fad23544de9d934f750e36adea
2021-03-14T02:09:26+01:00: Checksum: 41e9fe4f95cf87d5355058e24921ed339c73765b6bef5b6450156a36d4be0f8d
2021-03-14T02:09:26+01:00: Size: 6300278341
2021-03-14T02:09:26+01:00: Chunk count: 1156
2021-03-14T02:09:26+01:00: Upload size: 17538651 (0%)
2021-03-14T02:09:26+01:00: Duplicates: 1152+0 (99%)
2021-03-14T02:09:26+01:00: Compression: 79%
2021-03-14T02:09:26+01:00: successfully closed dynamic index 3
2021-03-14T02:09:26+01:00: Upload statistics for 'catalog.pcat1.didx'
2021-03-14T02:09:26+01:00: UUID: 92a38a75d00a417888fe25e7a76ec828
2021-03-14T02:09:26+01:00: Checksum: d5c46b9a117954d0b0487b94408d97df261807c4bba00a864864c6e34eada24f
2021-03-14T02:09:26+01:00: Size: 3224867
2021-03-14T02:09:26+01:00: Chunk count: 6
2021-03-14T02:09:26+01:00: Upload size: 3224867 (100%)
2021-03-14T02:09:26+01:00: Duplicates: 0+2 (33%)
2021-03-14T02:09:26+01:00: Compression: 34%
2021-03-14T02:09:26+01:00: successfully closed dynamic index 1
2021-03-14T02:09:26+01:00: add blob "/mnt/datastore/local/host/crld-web-01/2021-03-14T01:05:01Z/index.json.blob" (377 bytes, comp: 377)
2021-03-14T02:09:26+01:00: successfully finished backup
2021-03-14T02:09:26+01:00: backup finished successfully
2021-03-14T02:09:26+01:00: TASK OK

 

[mathilde]

The one from the other host looks fine too:

2021-03-14T02:05:01+01:00: starting new backup on datastore 'local': "host/dif-web-01/2021-03-14T01:05:01Z"
2021-03-14T02:05:01+01:00: download 'index.json.blob' from previous backup.
2021-03-14T02:05:01+01:00: created new dynamic index 1 ("host/dif-web-01/2021-03-14T01:05:01Z/catalog.pcat1.didx")
2021-03-14T02:05:01+01:00: register chunks in 'root.pxar.didx' from previous backup.
2021-03-14T02:05:01+01:00: download 'root.pxar.didx' from previous backup.
2021-03-14T02:05:01+01:00: created new dynamic index 2 ("host/dif-web-01/2021-03-14T01:05:01Z/root.pxar.didx")
2021-03-14T02:09:18+01:00: Upload statistics for 'root.pxar.didx'
2021-03-14T02:09:18+01:00: UUID: 9ce693362b874fd89b260e927ca792e2
2021-03-14T02:09:18+01:00: Checksum: e75623cae15eed24fffc180c0a1238d75452bff09c60b0c0cc9029f2fa017dc8
2021-03-14T02:09:18+01:00: Size: 10308896905
2021-03-14T02:09:18+01:00: Chunk count: 2404
2021-03-14T02:09:18+01:00: Upload size: 299506333 (2%)
2021-03-14T02:09:18+01:00: Duplicates: 2355+1 (98%)
2021-03-14T02:09:18+01:00: Compression: 22%
2021-03-14T02:09:18+01:00: successfully closed dynamic index 2
2021-03-14T02:09:18+01:00: Upload statistics for 'catalog.pcat1.didx'
2021-03-14T02:09:18+01:00: UUID: 857fa52826e242fb81d4c6ebebf53de8
2021-03-14T02:09:18+01:00: Checksum: d9fa498b5b34838f254f762bc9c3087c7367cd11b6a674e2c5947d8cf55aee80
2021-03-14T02:09:18+01:00: Size: 3405676
2021-03-14T02:09:18+01:00: Chunk count: 7
2021-03-14T02:09:18+01:00: Upload size: 3405676 (100%)
2021-03-14T02:09:18+01:00: Duplicates: 0+3 (42%)
2021-03-14T02:09:18+01:00: Compression: 36%
2021-03-14T02:09:18+01:00: successfully closed dynamic index 1
2021-03-14T02:09:18+01:00: add blob "/mnt/datastore/local/host/dif-web-01/2021-03-14T01:05:01Z/index.json.blob" (324 bytes, comp: 324)
2021-03-14T02:09:18+01:00: successfully finished backup
2021-03-14T02:09:18+01:00: backup finished successfully
2021-03-14T02:09:18+01:00: TASK OK

 

[fabian]

that one looks okay (97/99% deduplication). you need to check others and see whether there are backup groups that went from high duplication to low duplication. if no such groups exists, then the increased storage usage must have some other source (is the datastore on its own ZFS dataset? or is it shared with something else that might account for the additional usage?)

 

[mathilde]

Thanks for answering.

I checked the other backups and duplication hasn't changed at all. The datastore is on its own ZFS dataset, it's simply two 3TiB mirrored disks directly plugged in the server.

 

[fabian]

can you check the timestamp of the start of the slope? can you cross-reference it with upgrades on the client side (/var/log/apt/history.log) and see whether it relates to a change in proxmox-backup-client version? are you doing mainly host/ct or VM backups?

 

[mathilde]

can you check the timestamp of the start of the slope? can you cross-reference it with upgrades on the client side (/var/log/apt/history.log) and see whether it relates to a change in proxmox-backup-client version? are you doing mainly host/ct or VM backups?

It started by Tuesday March 16th, following the hang up backup of two host on Monday March 15th. It's only host backups, not CT or VM.

I'll check the APT updates on both hosts right away.

 

[mathilde]

proxmox-backup-client got indeed updated on both hosts Monday March 15th:

Start-Date: 2021-03-15  18:58:25
Commandline: apt upgrade
Requested-By: REDACTED (1004)
Upgrade: php-common:amd64 (2:81+0~20210223.34+debian10~1.gbpf52eb0, 2:82+0~20210313.35+debian10~1.gbpa8195f), proxmox-backup-client:amd64 (1.0.8-1, 1.0.9-1), libtiff5:amd64 (4.1.0+git191117-2~deb10u1, 4.1.0+git191117-2~deb10u2), nginx:amd64 (1.19.7-1~buster, 1.19.8-1~buster)
End-Date: 2021-03-15  18:58:33

 

[fabian]

and your logs are from BEFORE that upgrade - check the logs from afterwards?

 

[mathilde]

and your logs are from BEFORE that upgrade - check the logs from afterwards?

You were indeed right, I checked the logs from the others hosts (the one's not impacted by the hang up) and the duplication sucks since Monday March 15th.

I'll update proxmox-backup-client on the hosts and check if it's fixed.

 

[mathilde]

Hi @fabian,

There seems to be two distinct problems here:

1. The storage was eaten up by duplication problems
2. Two clients still hang up when trying to backup

For the first point it seems to be related to the bug in the client that have been fixed. However I would like to be sure that I got it correctly: to free up space I now need to delete all snapshots made with impacted versions of proxmox-backup-client (v1.0.9 & v1.0.10)?

On the second point, the problem still occurs. Tonight's backups didn't complete for the same two hosts, it's stuck at this part: download 'index.json.blob' from previous backup..

See full log bellow:

2021-03-25T02:05:01+01:00: starting new backup on datastore 'local': "host/crld-web-01/2021-03-25T01:05:01Z"
2021-03-25T02:05:01+01:00: download 'index.json.blob' from previous backup.
2021-03-25T08:29:00+01:00: received abort request ...
2021-03-25T08:29:00+01:00: backup failed: task aborted
2021-03-25T08:29:00+01:00: removing failed backup
2021-03-25T08:29:00+01:00: TASK ERROR: task aborted

 

[fabian]

Hi @fabian,

There seems to be two distinct problems here:

1. The storage was eaten up by duplication problems
2. Two clients still hang up when trying to backup

For the first point it seems to be related to the bug in the client that have been fixed. However I would like to be sure that I got it correctly: to free up space I now need to delete all snapshots made with impacted versions of proxmox-backup-client (v1.0.9 & v1.0.10)?

correct. or wait until they are rotated out by your backup+prune schedule if you can afford to temporarily "waste" that space.

On the second point, the problem still occurs. Tonight's backups didn't complete for the same two hosts, it's stuck at this part: download 'index.json.blob' from previous backup..

See full log bellow:

2021-03-25T02:05:01+01:00: starting new backup on datastore 'local': "host/crld-web-01/2021-03-25T01:05:01Z"
2021-03-25T02:05:01+01:00: download 'index.json.blob' from previous backup.
2021-03-25T08:29:00+01:00: received abort request ...
2021-03-25T08:29:00+01:00: backup failed: task aborted
2021-03-25T08:29:00+01:00: removing failed backup
2021-03-25T08:29:00+01:00: TASK ERROR: task aborted

is the host doing the backup a single-core machine(/VM/..)? if so, there is a hanging bug for such systems which has been fixed in git, but not yet released in a packaged version. if not, we'd need some more information - logs from the server side for that task, added "--verbose" to the client command, information about network and hardware of both sides. thanks!

 

[mathilde]

correct. or wait until they are rotated out by your backup+prune schedule if you can afford to temporarily "waste" that space.

Okay, thank you for confirming this.

is the host doing the backup a single-core machine(/VM/..)? if so, there is a hanging bug for such systems which has been fixed in git, but not yet released in a packaged version. if not, we'd need some more information - logs from the server side for that task, added "--verbose" to the client command, information about network and hardware of both sides. thanks!

Yes it is, both hosts are small single-core machines. Do you have any idea when it will be released?

Many thanks for your help.

 

[fabian]

Yes it is, both hosts are small single-core machines. Do you have any idea when it will be released?

no. but you can watch the git repo for a new version being cut - usually it doesn't take long after that for a package to show up in our public test repository, unless we found some blocking issue in our internal testing.

 

[mathilde]

no. but you can watch the git repo for a new version being cut - usually it doesn't take long after that for a package to show up in our public test repository, unless we found some blocking issue in our internal testing.

Okay, I'll wait for this. I keep this thread open until it's fixed, hope soon.

Thanks again!

 

[mathilde]

Seems to be fixed by v1.0.13-1 release. Upgraded the package on both hosts and the backups are flowing again, thanks for fixing this bug.

However, can't wait for the static binary to be available!