Garbage collect takes > 9h

[vikozo]

hallo

why sometimes the Garbage collect takes > 9h to clean up, but most of the time just a couple of Minute <30min?
In my case it just runs every houer the GC task!

have anice day
vinc

 

[vikozo]

the longest needed 19h
normaly this GC is called every houer so why did id needed so long this time?

 

[t.lamprecht]

Hi,

does the mark or the sweep phase needs that long (check the task log), or is it evenly distributed to the whole task?

What's the specs of this system, CPU type, memory, underlying storage?

Is there some other load on the system during such long time?
You could check the pressure stall information, head /proc/pressure/* - those show you if some or more processes are stalled due to either IO, memory or CPU starvation.

 

[meichthys]

@t.lamprecht & @vikozo

I'm also seeing this on my proxmox backup server:
Some background information:
- PBS is running in a VM on one of the nodes in my 3 node cluster (I know this isn't ideal)
- Node running PBS VM is a Dell T410 Tower server
- Storage at all points is ZFS (On VM, Host node, and PBS)

Since a picture is worth a thousand words here's a few of the dashboard that tipped me off to the long running task:

Here's a screenshot of the `top` command from the PBS VM:


Here's a screenshot of the garbage collection task summary. As you'll see the slowdown happened sometime after 2021-04-08T19:33 which was about 3.5 hours before the other currently running tasks even started.



The slow down seems to be near the end of the log. It still seems to be making progress albeit verrrry slowly:
```
2021-04-08T16:32:00-04:00: starting garbage collection on store backup2
2021-04-08T16:32:00-04:00: task triggered by schedule 'daily'
2021-04-08T16:32:00-04:00: Start GC phase1 (mark used chunks)
2021-04-08T16:33:08-04:00: percentage done: phase1 1% (3 of 229 index files)
2021-04-08T16:34:00-04:00: percentage done: phase1 2% (5 of 229 index files)
2021-04-08T16:36:05-04:00: percentage done: phase1 3% (7 of 229 index files)
2021-04-08T16:40:38-04:00: percentage done: phase1 4% (10 of 229 index files)
2021-04-08T16:42:39-04:00: percentage done: phase1 5% (12 of 229 index files)
2021-04-08T16:44:21-04:00: percentage done: phase1 6% (14 of 229 index files)
2021-04-08T16:54:01-04:00: percentage done: phase1 7% (17 of 229 index files)
2021-04-08T16:56:33-04:00: percentage done: phase1 8% (19 of 229 index files)
2021-04-08T16:58:31-04:00: percentage done: phase1 9% (21 of 229 index files)
2021-04-08T17:00:19-04:00: percentage done: phase1 10% (23 of 229 index files)
2021-04-08T17:02:00-04:00: percentage done: phase1 11% (26 of 229 index files)
2021-04-08T17:08:07-04:00: percentage done: phase1 12% (28 of 229 index files)
2021-04-08T17:15:46-04:00: percentage done: phase1 13% (30 of 229 index files)
2021-04-08T17:18:44-04:00: percentage done: phase1 14% (33 of 229 index files)
2021-04-08T17:26:10-04:00: percentage done: phase1 15% (35 of 229 index files)
2021-04-08T17:27:25-04:00: percentage done: phase1 16% (37 of 229 index files)
2021-04-08T17:33:24-04:00: percentage done: phase1 17% (39 of 229 index files)
2021-04-08T17:43:05-04:00: percentage done: phase1 18% (42 of 229 index files)
2021-04-08T17:45:24-04:00: percentage done: phase1 19% (44 of 229 index files)
2021-04-08T17:49:11-04:00: percentage done: phase1 20% (46 of 229 index files)
2021-04-08T17:54:33-04:00: percentage done: phase1 21% (49 of 229 index files)
2021-04-08T17:57:10-04:00: percentage done: phase1 22% (51 of 229 index files)
2021-04-08T17:59:14-04:00: percentage done: phase1 23% (53 of 229 index files)
2021-04-08T17:59:14-04:00: percentage done: phase1 24% (55 of 229 index files)
2021-04-08T18:02:00-04:00: percentage done: phase1 25% (58 of 229 index files)
2021-04-08T18:06:11-04:00: percentage done: phase1 26% (60 of 229 index files)
2021-04-08T18:08:03-04:00: percentage done: phase1 27% (62 of 229 index files)
2021-04-08T18:09:18-04:00: percentage done: phase1 28% (65 of 229 index files)
2021-04-08T18:11:05-04:00: percentage done: phase1 29% (67 of 229 index files)
2021-04-08T18:14:11-04:00: percentage done: phase1 30% (69 of 229 index files)
2021-04-08T18:14:11-04:00: percentage done: phase1 31% (71 of 229 index files)
2021-04-08T18:28:28-04:00: percentage done: phase1 32% (74 of 229 index files)
2021-04-08T18:33:28-04:00: percentage done: phase1 33% (76 of 229 index files)
2021-04-08T18:37:27-04:00: percentage done: phase1 34% (78 of 229 index files)
2021-04-08T18:40:09-04:00: percentage done: phase1 35% (81 of 229 index files)
2021-04-08T18:46:22-04:00: percentage done: phase1 36% (83 of 229 index files)
2021-04-08T18:46:22-04:00: percentage done: phase1 37% (85 of 229 index files)
2021-04-08T19:00:55-04:00: percentage done: phase1 38% (88 of 229 index files)
2021-04-08T19:06:21-04:00: percentage done: phase1 39% (90 of 229 index files)
2021-04-08T19:09:05-04:00: percentage done: phase1 40% (92 of 229 index files)
2021-04-08T19:10:12-04:00: percentage done: phase1 41% (94 of 229 index files)
2021-04-08T19:12:17-04:00: percentage done: phase1 42% (97 of 229 index files)
2021-04-08T19:16:55-04:00: percentage done: phase1 43% (99 of 229 index files)
2021-04-08T19:16:55-04:00: percentage done: phase1 44% (101 of 229 index files)
2021-04-08T19:19:12-04:00: percentage done: phase1 45% (104 of 229 index files)
2021-04-08T19:20:31-04:00: percentage done: phase1 46% (106 of 229 index files)
2021-04-08T19:21:23-04:00: percentage done: phase1 47% (108 of 229 index files)
2021-04-08T19:22:37-04:00: percentage done: phase1 48% (110 of 229 index files)
2021-04-08T19:24:49-04:00: percentage done: phase1 49% (113 of 229 index files)
2021-04-08T19:25:25-04:00: percentage done: phase1 50% (115 of 229 index files)
2021-04-08T19:27:05-04:00: percentage done: phase1 51% (117 of 229 index files)
2021-04-08T19:28:09-04:00: percentage done: phase1 52% (120 of 229 index files)
2021-04-08T19:28:31-04:00: percentage done: phase1 53% (122 of 229 index files)
2021-04-08T19:28:32-04:00: percentage done: phase1 54% (124 of 229 index files)
2021-04-08T19:29:00-04:00: percentage done: phase1 55% (126 of 229 index files)
2021-04-08T19:29:31-04:00: percentage done: phase1 56% (129 of 229 index files)
2021-04-08T19:29:55-04:00: percentage done: phase1 57% (131 of 229 index files)
2021-04-08T19:30:09-04:00: percentage done: phase1 58% (133 of 229 index files)
2021-04-08T19:30:50-04:00: percentage done: phase1 59% (136 of 229 index files)
2021-04-08T19:31:05-04:00: percentage done: phase1 60% (138 of 229 index files)
2021-04-08T19:31:30-04:00: percentage done: phase1 61% (140 of 229 index files)
2021-04-08T19:31:37-04:00: percentage done: phase1 62% (142 of 229 index files)
2021-04-08T19:31:45-04:00: percentage done: phase1 63% (145 of 229 index files)
2021-04-08T19:32:00-04:00: percentage done: phase1 64% (147 of 229 index files)
2021-04-08T19:32:11-04:00: percentage done: phase1 65% (149 of 229 index files)
2021-04-08T19:33:38-04:00: percentage done: phase1 66% (152 of 229 index files)
2021-04-08T19:53:27-04:00: percentage done: phase1 67% (154 of 229 index files)
2021-04-08T20:42:17-04:00: percentage done: phase1 68% (156 of 229 index files)
2021-04-08T22:24:05-04:00: percentage done: phase1 69% (159 of 229 index files)
2021-04-08T23:24:35-04:00: percentage done: phase1 70% (161 of 229 index files)
2021-04-09T00:44:58-04:00: percentage done: phase1 71% (163 of 229 index files)
2021-04-09T07:12:03-04:00: percentage done: phase1 72% (165 of 229 index files)
```

 

[fabian]

you have 4! running verification tasks on the same datastore.. those will definitely get into eachother's and GC's way.

 

[meichthys]

Yes, that's a problem that resulted from me forgetting to setup verification tasks when i setup the backups (now i'm trying to catch up by getting all backups verified).
From what i can tell, the garbage collection task hung about 3.5 hours before the other running verification tasks even started. It could be ,however, that there were other verification tasks which finished already but were running when it hung. I'll try stop a few of the verification tasks to see if it helps on the garbage cleanup.