Perhaps we forgot to update a description? @Andrii
Do you also have a BF file in the retain
folder?
Or do you mean the trash filewalker?
Correct. Bloom filter has gone already, now it is deleting the files in the subfolders. It has proceed from v5 to xw since my last post.
Then it’s not related to processing of a BF, because pieces are not moved to the trash (this is what BF processing does), they are removed from the trash instead.
Heh, we have a lot of different filewalkers, often running in parallel…
Yes, the node is not processing the Bloom filter file anymore but the outcome from it. From the date folder 30th of June we can assume that these are the results of a Bloom filter from the 30th or even before that date which should have been deleted on the 8th of July. Toady is the 17th and it is still deleting files…
So my main point is, more frequent Bloom filters may not help at all.
I would agree. But it should move more garbage to the trash.
However, you are correct about deletion operations, perhaps they are to heavy too for your system.
I have no idea why it is taking so long on this node. It seems excessive.
Yes, it’s.
$ grep trash-filewalker /mnt/x/storagenode2/storagenode.log
2024-07-14T13:15:08Z INFO lazyfilewalker.trash-cleanup-filewalker.subprocess trash-filewalker started {"Process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode", "dateBefore": "2024-07-07T13:15:08Z"}
2024-07-15T05:16:23Z INFO lazyfilewalker.trash-cleanup-filewalker.subprocess trash-filewalker completed {"Process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "numKeysDeleted": 798418, "Process": "storagenode", "bytesDeleted": 281627838314}
What are numkeys
?
Edit: @littleskunk help with this please.
Number of pieces I suppose.
with these 2 its nothing . for the rest of 3 i have posted and its on-going
cat "f:\storagenode*.log" | sls "used-space-filewalker" | sls "started|finished | select -last 10"
2024-04-22T16:59:02+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-04-22T16:59:02+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
2024-04-22T16:59:02+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
2024-04-22T16:59:02+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-04-22T16:59:02+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-04-22T16:59:02+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}
2024-04-22T16:59:02+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}
2024-04-22T16:59:03+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-04-22T22:36:10+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-04-22T22:36:11+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode"}
2024-04-22T22:36:11+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode"}
2024-04-22T22:36:11+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-04-22T22:36:11+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-04-22T22:36:11+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
2024-04-22T22:36:11+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
2024-04-22T22:36:12+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-04-22T22:36:12+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-04-22T22:36:12+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}
2024-04-22T22:36:12+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}
2024-04-22T22:36:12+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-04-23T10:31:11+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-04-23T10:31:11+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode"}
2024-04-23T10:31:11+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode"}
2024-04-23T10:31:12+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-04-23T10:31:12+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-04-23T10:31:12+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
2024-04-23T10:31:12+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
2024-04-23T10:31:48+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-04-23T10:31:48+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-04-23T10:31:48+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}
2024-04-23T10:31:48+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}
2024-04-23T10:31:49+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-04-23T17:54:05+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-04-23T17:54:07+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode"}
2024-04-23T17:54:07+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode"}
2024-04-23T17:54:09+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-04-23T17:54:09+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-04-23T17:54:09+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
2024-04-23T17:54:09+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
2024-04-23T17:55:47+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-04-23T17:55:47+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-04-23T17:55:47+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}
2024-04-23T17:55:47+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}
2024-04-23T17:55:51+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-04-23T20:00:12+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-04-23T20:00:12+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode"}
2024-04-23T20:00:12+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode"}
2024-04-23T20:00:16+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-04-23T20:00:16+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-04-23T20:00:16+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
2024-04-23T20:00:16+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
2024-04-23T20:02:07+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-04-23T20:02:07+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-04-23T20:02:07+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}
2024-04-23T20:02:07+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}
2024-04-23T20:02:11+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-04-23T20:04:59+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-04-23T20:04:59+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode"}
2024-04-23T20:04:59+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode"}
2024-04-23T20:05:00+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-04-23T20:05:00+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-04-23T20:05:01+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
2024-04-23T20:05:01+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
2024-04-23T20:06:44+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-04-23T20:06:44+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-04-23T20:06:44+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}
2024-04-23T20:06:44+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}
2024-04-23T20:06:48+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-04-23T20:11:59+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-04-23T20:12:01+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode"}
2024-04-23T20:12:01+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode"}
2024-04-23T20:12:02+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-04-23T20:12:02+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-04-23T20:12:02+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
2024-04-23T20:12:02+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
2024-04-23T20:13:50+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-04-23T20:13:51+01:00 INFO lazyfilewalker.used-space-filewalker subprocess started {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-04-23T20:13:51+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess Database started {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}
2024-04-23T20:13:51+01:00 INFO lazyfilewalker.used-space-filewalker.subprocess used-space-filewalker started
{"satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}
2024-04-23T20:13:54+01:00 INFO lazyfilewalker.used-space-filewalker subprocess finished successfully {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
PS C:\Windows\system32> cat "f:\storagenode*.log" | sls "retain | select -last 10"
2024-04-25T03:14:02+01:00 INFO piecestore Retain job queued {"Satellite ID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-04-25T03:14:02+01:00 INFO retain Prepared to run a Retain request. {"cachePath": "F:\\/retain", "Created Before":
"2024-04-20T17:59:59Z", "Filter Size": 2384, "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-04-25T03:14:32+01:00 INFO retain Moved pieces to trash during retain {"cachePath": "F:\\/retain", "Deleted
pieces": 0, "Failed to delete": 0, "Pieces failed to read": 0, "Pieces count": 7556, "Satellite ID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Duration": "30.1126909s", "Retain Status": "enabled"}
2024-04-25T10:18:20+01:00 INFO piecestore Retain job queued {"Satellite ID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-04-25T10:18:20+01:00 INFO retain Prepared to run a Retain request. {"cachePath": "F:\\/retain", "Created Before":
"2024-04-21T17:59:59Z", "Filter Size": 45, "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-04-25T10:18:25+01:00 INFO retain Moved pieces to trash during retain {"cachePath": "F:\\/retain", "Deleted
pieces": 0, "Failed to delete": 0, "Pieces failed to read": 0, "Pieces count": 487, "Satellite ID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Duration": "4.6978268s", "Retain Status": "enabled"}
2024-04-27T09:08:20+01:00 INFO piecestore Retain job queued {"Satellite ID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-04-27T09:08:20+01:00 INFO retain Prepared to run a Retain request. {"cachePath": "F:\\/retain", "Created Before":
"2024-04-22T17:59:59Z", "Filter Size": 29569, "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-04-27T09:17:55+01:00 INFO retain Moved pieces to trash during retain {"cachePath": "F:\\/retain", "Deleted
pieces": 751, "Failed to delete": 0, "Pieces failed to read": 0, "Pieces count": 164886, "Satellite ID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Duration": "9m34.9561013s", "Retain Status": "enabled"}
2024-05-03T05:51:20+01:00 INFO piecestore Retain job queued {"Satellite ID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-05-03T05:51:20+01:00 INFO retain Prepared to run a Retain request. {"cachePath": "F:\\/retain", "Created Before":
"2024-04-23T17:59:59Z", "Filter Size": 45598, "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-05-03T06:01:30+01:00 INFO retain Moved pieces to trash during retain {"cachePath": "F:\\/retain", "Deleted
pieces": 9517, "Failed to delete": 0, "Pieces failed to read": 0, "Pieces count": 392779, "Satellite ID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Duration": "10m10.1359365s", "Retain Status": "enabled"}
2024-05-03T11:38:23+01:00 INFO piecestore Retain job queued {"Satellite ID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-05-03T11:38:23+01:00 INFO retain Prepared to run a Retain request. {"cachePath": "F:\\/retain", "Created Before":
"2024-04-29T17:59:59Z", "Filter Size": 713, "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-05-03T11:38:55+01:00 INFO retain Moved pieces to trash during retain {"cachePath": "F:\\/retain", "Deleted
pieces": 240, "Failed to delete": 0, "Pieces failed to read": 0, "Pieces count": 3306, "Satellite ID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Duration": "32.6588102s", "Retain Status": "enabled"}
2024-05-04T16:30:24+01:00 INFO piecestore Retain job queued {"Satellite ID":
"1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE"}
2024-05-04T16:30:24+01:00 INFO retain Prepared to run a Retain request. {"cachePath": "F:\\/retain", "Created Before":
"2024-04-27T13:50:43Z", "Filter Size": 5103, "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE"}
2024-05-04T16:30:32+01:00 INFO retain Moved pieces to trash during retain {"cachePath": "F:\\/retain", "Deleted
pieces": 26, "Failed to delete": 0, "Pieces failed to read": 0, "Pieces count": 8597, "Satellite ID":
"1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Duration": "7.9364388s", "Retain Status": "enabled"}
2024-06-06T12:32:20+01:00 ERROR retain retain pieces failed {"cachePath": "F:\\/retain", "error": "retain: filewalker:
context canceled", "errorVerbose": "retain: filewalker: context canceled\n\tstorj.io/storj/storagenode/pieces.(*FileWal
ker).WalkSatellitePieces:74\n\tstorj.io/storj/storagenode/pieces.(*FileWalker).WalkSatellitePiecesToTrash:178\n\tstorj.
io/storj/storagenode/pieces.(*Store).WalkSatellitePiecesToTrash:565\n\tstorj.io/storj/storagenode/retain.(*Service).ret
ainPieces:369\n\tstorj.io/storj/storagenode/retain.(*Service).Run.func2:258\n\tgolang.org/x/sync/errgroup.(*Group).Go.f
unc1:78"}
2024-06-06T12:32:20+01:00 ERROR retain retain pieces failed {"cachePath": "F:\\/retain", "error": "retain: filewalker:
context canceled", "errorVerbose": "retain: filewalker: context canceled\n\tstorj.io/storj/storagenode/pieces.(*FileWal
ker).WalkSatellitePieces:74\n\tstorj.io/storj/storagenode/pieces.(*FileWalker).WalkSatellitePiecesToTrash:178\n\tstorj.
io/storj/storagenode/pieces.(*Store).WalkSatellitePiecesToTrash:565\n\tstorj.io/storj/storagenode/retain.(*Service).ret
ainPieces:369\n\tstorj.io/storj/storagenode/retain.(*Service).Run.func2:258\n\tgolang.org/x/sync/errgroup.(*Group).Go.f
PS C:\Windows\system32> cat "f:\storagenode*.log" | sls "gc-filewalker" | sls "started|finished | select -last 10"
2024-04-25T03:14:02+01:00 INFO lazyfilewalker.gc-filewalker subprocess started {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-04-25T03:14:02+01:00 INFO lazyfilewalker.gc-filewalker.subprocess Database started {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}
2024-04-25T03:14:02+01:00 INFO lazyfilewalker.gc-filewalker.subprocess gc-filewalker started {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode", "createdBefore":
"2024-04-20T17:59:59Z", "bloomFilterSize": 2384}
2024-04-25T03:14:32+01:00 INFO lazyfilewalker.gc-filewalker subprocess finished successfully {"satelliteID":
"12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-04-25T10:18:20+01:00 INFO lazyfilewalker.gc-filewalker subprocess started {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-04-25T10:18:20+01:00 INFO lazyfilewalker.gc-filewalker.subprocess Database started {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode"}
2024-04-25T10:18:20+01:00 INFO lazyfilewalker.gc-filewalker.subprocess gc-filewalker started {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode", "createdBefore":
"2024-04-21T17:59:59Z", "bloomFilterSize": 45}
2024-04-25T10:18:25+01:00 INFO lazyfilewalker.gc-filewalker subprocess finished successfully {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-04-27T09:08:20+01:00 INFO lazyfilewalker.gc-filewalker subprocess started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-04-27T09:08:20+01:00 INFO lazyfilewalker.gc-filewalker.subprocess Database started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
2024-04-27T09:08:20+01:00 INFO lazyfilewalker.gc-filewalker.subprocess gc-filewalker started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode", "createdBefore":
"2024-04-22T17:59:59Z", "bloomFilterSize": 29569}
2024-04-27T09:17:55+01:00 INFO lazyfilewalker.gc-filewalker subprocess finished successfully {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-05-03T05:51:20+01:00 INFO lazyfilewalker.gc-filewalker subprocess started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-05-03T05:51:20+01:00 INFO lazyfilewalker.gc-filewalker.subprocess Database started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
2024-05-03T05:51:20+01:00 INFO lazyfilewalker.gc-filewalker.subprocess gc-filewalker started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode", "createdBefore":
"2024-04-23T17:59:59Z", "bloomFilterSize": 45598}
2024-05-03T06:01:30+01:00 INFO lazyfilewalker.gc-filewalker subprocess finished successfully {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-05-03T11:38:23+01:00 INFO lazyfilewalker.gc-filewalker subprocess started {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-05-03T11:38:23+01:00 INFO lazyfilewalker.gc-filewalker.subprocess Database started {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode"}
2024-05-03T11:38:23+01:00 INFO lazyfilewalker.gc-filewalker.subprocess gc-filewalker started {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode", "createdBefore":
"2024-04-29T17:59:59Z", "bloomFilterSize": 713}
2024-05-03T11:38:55+01:00 INFO lazyfilewalker.gc-filewalker subprocess finished successfully {"satelliteID":
"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-05-04T16:30:24+01:00 INFO lazyfilewalker.gc-filewalker subprocess started {"satelliteID":
"1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE"}
2024-05-04T16:30:24+01:00 INFO lazyfilewalker.gc-filewalker.subprocess Database started {"satelliteID":
"1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Process": "storagenode"}
2024-05-04T16:30:24+01:00 INFO lazyfilewalker.gc-filewalker.subprocess gc-filewalker started {"satelliteID":
"1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Process": "storagenode", "createdBefore":
"2024-04-27T13:50:43Z", "bloomFilterSize": 5103}
2024-05-04T16:30:32+01:00 INFO lazyfilewalker.gc-filewalker subprocess finished successfully {"satelliteID":
"1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE"}
2024-05-06T09:14:17+01:00 INFO lazyfilewalker.gc-filewalker subprocess started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-05-06T09:14:18+01:00 INFO lazyfilewalker.gc-filewalker.subprocess Database started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}
2024-05-06T09:14:18+01:00 INFO lazyfilewalker.gc-filewalker.subprocess gc-filewalker started {"satelliteID":
"12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode", "createdBefore":
"2024-04-27T17:59:59Z", "bloomFilterSize": 112086}
2024-05-06T09:36:48+01:00 INFO lazyfilewalker.gc-filewalker subprocess finished successfully {"satelliteID":
Another of my nodes thinks it has more data than actually on the drive.
I see errors like this every 1-3 minutes:
2024-07-17T13:10:14+02:00 ERROR piecestore upload internal error {"Process": "storagenode", "error": "manager closed: unexpected EOF", "errorVerbose": "manager closed: unexpected EOF\n\tgithub.com/jtolio/noiseconn.(*Conn).readMsg:225\n\tgithub.com/jtolio/noiseconn.(*Conn).Read:171\n\tstorj.io/drpc/drpcwire.(*Reader).read:68\n\tstorj.io/drpc/drpcwire.(*Reader).ReadPacketUsing:113\n\tstorj.io/drpc/drpcmanager.(*Manager).manageReader:229"}
2024-07-17T13:10:14+02:00 ERROR piecestore upload failed {"Process": "storagenode", "Piece ID": "LIPNVV2UO7E2MT5STA223Y47AVSBRODR7MKLZ55VUJGPHPV5O6PA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT", "Remote Address": "64.180.15.203:56368", "Size": 327680, "error": "manager closed: unexpected EOF", "errorVerbose": "manager closed: unexpected EOF\n\tgithub.com/jtolio/noiseconn.(*Conn).readMsg:225\n\tgithub.com/jtolio/noiseconn.(*Conn).Read:171\n\tstorj.io/drpc/drpcwire.(*Reader).read:68\n\tstorj.io/drpc/drpcwire.(*Reader).ReadPacketUsing:113\n\tstorj.io/drpc/drpcmanager.(*Manager).manageReader:229"}
What could cause that?
We had 3 bugs that let the used space numbers on the dashboard to differ from the space on disk:
- Trash cleanup didn’t substract the trash size. Was fixed a few releases ago and in your screenshot I don’t see a big amount of trash.
- TTL cleanup didn’t substract the size. Will be fixed starting with the v1.107 release and higher.
- Used space numbers are not persisted to disk until used space filewalker finished. Fix will be in the v1.109 release.
You are for sure affected by number 2 and maybe even by number 3.
In any case running the used space filewalker should correct the numbers. Depending on how urgent your situation is you might want to wait until v1.109 because of bug number 3.
Just for that single question? It shows the number of pieces. I feel like I am missing the context here. I assume this is the more interesting question:
You can trace it down with the debug endpoint. Here is one of my nodes that has problems with TTL deletes:
Step 1 get the function names. Best place to find them is the /mon/ps endpoint. Here I can see the TTL deletes are taking 39 hours:
[7686908397958843297,4471982582838189100] storj.io/storj/storagenode/collector.(*Service).Collect() (elapsed: 39h4m40.538834507s)
[8420948712339710239,4471982582838189100] storj.io/storj/storagenode/pieces.(*Store).GetExpired() (elapsed: 39h4m40.498883096s)
[196704945436148078,4471982582838189100] storj.io/storj/storagenode/storagenodedb.(*pieceExpirationDB).GetExpired() (elapsed: 39h4m40.49100903s)
[2519395167758259759,4471982582838189100] storj.io/storj/storagenode/pieces.(*Store).DeleteSkipV0() (elapsed: 4.70866ms)
[5734320982878913957,4471982582838189100] storj.io/storj/storagenode/blobstore/filestore.(*blobStore).Stat() (elapsed: 4.692031ms)
[8949246797999568154,4471982582838189100] storj.io/storj/storagenode/blobstore/filestore.(*Dir).Stat() (elapsed: 4.689568ms)
Step 2 take a look where most of the time is spend. /mon/funcs | less and search for the function names we discovered in step 1:
[5206022897219056041] storj.io/storj/storagenode/pieces.(*Store).GetExpired
parents: 1257056767717534902
current: 1, highwater: 1, success: 0, errors: 0, panics: 0
success times:
0.00: 0s
0.10: 0s
0.25: 0s
0.50: 0s
0.75: 0s
0.90: 0s
0.95: 0s
1.00: 0s
avg: 0s
ravg: 0s
recent: 0s
sum: 0s
failure times:
0.00: 0s
0.10: 0s
0.25: 0s
0.50: 0s
0.75: 0s
0.90: 0s
0.95: 0s
1.00: 0s
avg: 0s
ravg: 0s
recent: 0s
sum: 0s
[8203407707072696984] storj.io/storj/storagenode/pieces.(*Store).DeleteSkipV0
parents: 6205151167170269689
current: 1, highwater: 1, success: 2090541, errors: 1493563, panics: 0
error pieces error: 1493563
success times:
0.00: 515.463µs
0.10: 6.983024ms
0.25: 8.680552ms
0.50: 10.968776ms
0.75: 17.146502ms
0.90: 31.355619ms
0.95: 39.250311ms
1.00: 107.315896ms
avg: 34.754505ms
ravg: 16.52902ms
recent: 9.595417ms
sum: 20h10m55.719655415s
failure times:
0.00: 7.036271ms
0.10: 10.70683ms
0.25: 13.448824ms
0.50: 18.036566ms
0.75: 26.34265ms
0.90: 39.837481ms
0.95: 47.855419ms
1.00: 297.430464ms
avg: 46.47744ms
ravg: 28.940896ms
recent: 17.305965ms
sum: 19h16m56.985768897s
Step 3 now in this output we have parent IDs. Call /mon/funcs | less again and search by id 5206022897219056041 and 8203407707072696984. This will give us the following output:
[2616366893845762158] storj.io/storj/storagenode/blobstore/filestore.(*blobStore).Stat
parents: 6714491018480097924, 8203407707072696984
current: 1, highwater: 2, success: 5850956, errors: 1493563, panics: 0
error filestore error: 1493563
success times:
0.00: 2.343146ms
0.10: 4.897816ms
0.25: 8.442385ms
0.50: 11.428517ms
0.75: 19.834523ms
0.90: 28.260879ms
0.95: 36.104366ms
1.00: 69.827104ms
avg: 11.780226ms
ravg: 15.418772ms
recent: 8.90675ms
sum: 19h8m45.58703675s
failure times:
0.00: 3.553534ms
0.10: 10.766163ms
0.25: 13.976996ms
0.50: 18.198576ms
0.75: 23.228715ms
0.90: 37.75765ms
0.95: 40.890442ms
1.00: 276.106816ms
avg: 46.455894ms
ravg: 24.41656ms
recent: 17.290779ms
sum: 19h16m24.80581741s
[6705684800416914997] storj.io/storj/storagenode/blobstore/filestore.(*blobStore).DeleteWithStorageFormat
parents: 8203407707072696984
current: 0, highwater: 1, success: 2090541, errors: 0, panics: 0
success times:
0.00: 75.351µs
0.10: 82.175µs
0.25: 89.078µs
0.50: 101.537µs
0.75: 124.027µs
0.90: 148.787µs
0.95: 181.59µs
1.00: 351.055µs
avg: 132.278µs
ravg: 113.239µs
recent: 236.296µs
sum: 4m36.532929686s
failure times:
0.00: 0s
0.10: 0s
0.25: 0s
0.50: 0s
0.75: 0s
0.90: 0s
0.95: 0s
1.00: 0s
avg: 0s
ravg: 0s
recent: 0s
sum: 0s
Setp 4 create a github ticket with these information. In my case the stats call is slowing it down and the delete itself is very fast.
The naming of the variable didn’t make sense. Calling it piecesDeleted
would have been more “user friendly” in my opinion.
numKeysDeleted
would rather refer to something deleted from a database (Super Key, Candidate Key, Primary Key, Alternate Key, Composite Key, Unique Key) but then database has records/fields. I only call upon thee when I am super confused, not for small stuff
Also thank you for responding. I truly, madly and deeply appreciate it.
Yes and it is very hard to keep track of them.
It would be good if the would send clear log messages like suggested start and resumed.
But also status and progress updates that you can see it from the logs they are still running and where they are at.
To see which filewalkers are currently running and when they last ran (since node start) I can recommend this script.
But I agree with you that intermediate updates, be it in % or how many folders have already been processed, would be very useful.