Disk usage discrepancy?

Perhaps we forgot to update a description? :thinking: @Andrii

1 Like

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.

1 Like

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 :point_up: 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.


image

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:

  1. 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.
  2. TTL cleanup didn’t substract the size. Will be fixed starting with the v1.107 release and higher.
  3. 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.

1 Like

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.

1 Like

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 :nerd_face:

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.

1 Like

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.