1.115.5 used-space-filewalker starts every 3 seconds

Node Operators troubleshooting
1

I have 2 nodes already updated to 1.115.5 which start the used-space filewalker every 3 seconds

2024-11-02T19:05:32Z    INFO    pieces  used-space-filewalker started   {"Process": "storagenode", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-11-02T19:05:32Z    INFO    pieces  used-space-filewalker completed {"Process": "storagenode", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Lazy File Walker": false, "Total Pieces Size": 162425758456, "Total Pieces Content Size": 161772246776, "Total Pieces Count": 1276390, "Duration": "21.155071ms"}
2024-11-02T19:05:32Z    INFO    pieces  used-space-filewalker started   {"Process": "storagenode", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-11-02T19:05:32Z    INFO    pieces  used-space-filewalker completed {"Process": "storagenode", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Lazy File Walker": false, "Total Pieces Size": 7762985216, "Total Pieces Content Size": 7750394624, "Total Pieces Count": 24591, "Duration": "27.209889ms"}
2024-11-02T19:05:32Z    INFO    pieces  used-space-filewalker started   {"Process": "storagenode", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-11-02T19:05:32Z    INFO    pieces  used-space-filewalker completed {"Process": "storagenode", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Lazy File Walker": false, "Total Pieces Size": 63412933376, "Total Pieces Content Size": 63335810304, "Total Pieces Count": 150631, "Duration": "17.144513ms"}
2024-11-02T19:05:32Z    INFO    pieces  used-space-filewalker started   {"Process": "storagenode", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE"}
2024-11-02T19:05:32Z    INFO    pieces  used-space-filewalker completed {"Process": "storagenode", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Lazy File Walker": false, "Total Pieces Size": 667484672, "Total Pieces Content Size": 667060736, "Total Pieces Count": 828, "Duration": "15.675511ms"}
2024-11-02T19:05:35Z    INFO    pieces  used-space-filewalker started   {"Process": "storagenode", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-11-02T19:05:35Z    INFO    pieces  used-space-filewalker completed {"Process": "storagenode", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Lazy File Walker": false, "Total Pieces Size": 162425758456, "Total Pieces Content Size": 161772246776, "Total Pieces Count": 1276390, "Duration": "25.59741ms"}
2024-11-02T19:05:35Z    INFO    pieces  used-space-filewalker started   {"Process": "storagenode", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-11-02T19:05:35Z    INFO    pieces  used-space-filewalker completed {"Process": "storagenode", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Lazy File Walker": false, "Total Pieces Size": 7762985216, "Total Pieces Content Size": 7750394624, "Total Pieces Count": 24591, "Duration": "26.311416ms"}
2024-11-02T19:05:35Z    INFO    pieces  used-space-filewalker started   {"Process": "storagenode", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-11-02T19:05:35Z    INFO    pieces  used-space-filewalker completed {"Process": "storagenode", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Lazy File Walker": false, "Total Pieces Size": 63412933376, "Total Pieces Content Size": 63335810304, "Total Pieces Count": 150631, "Duration": "28.635879ms"}
2024-11-02T19:05:35Z    INFO    pieces  used-space-filewalker started   {"Process": "storagenode", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE"}
2024-11-02T19:05:35Z    INFO    pieces  used-space-filewalker completed {"Process": "storagenode", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Lazy File Walker": false, "Total Pieces Size": 667484672, "Total Pieces Content Size": 667060736, "Total Pieces Count": 828, "Duration": "14.701066ms"}
2024-11-02T19:05:39Z    INFO    pieces  used-space-filewalker started   {"Process": "storagenode", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2024-11-02T19:05:39Z    INFO    pieces  used-space-filewalker completed {"Process": "storagenode", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Lazy File Walker": false, "Total Pieces Size": 162425758456, "Total Pieces Content Size": 161772246776, "Total Pieces Count": 1276390, "Duration": "28.927455ms"}
2024-11-02T19:05:39Z    INFO    pieces  used-space-filewalker started   {"Process": "storagenode", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2024-11-02T19:05:39Z    INFO    pieces  used-space-filewalker completed {"Process": "storagenode", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Lazy File Walker": false, "Total Pieces Size": 7762985216, "Total Pieces Content Size": 7750394624, "Total Pieces Count": 24591, "Duration": "30.412837ms"}
2024-11-02T19:05:39Z    INFO    pieces  used-space-filewalker started   {"Process": "storagenode", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2024-11-02T19:05:39Z    INFO    pieces  used-space-filewalker completed {"Process": "storagenode", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Lazy File Walker": false, "Total Pieces Size": 63412933376, "Total Pieces Content Size": 63335810304, "Total Pieces Count": 150631, "Duration": "12.341508ms"}
2024-11-02T19:05:39Z    INFO    pieces  used-space-filewalker started   {"Process": "storagenode", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE"}
2024-11-02T19:05:39Z    INFO    pieces  used-space-filewalker completed {"Process": "storagenode", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Lazy File Walker": false, "Total Pieces Size": 667484672, "Total Pieces Content Size": 667060736, "Total Pieces Count": 828, "Duration": "27.938112ms"}

All my nodes have this in the config.yaml

pieces.file-stat-cache: badger
pieces.enable-lazy-filewalker: false

storage2.monitor.dedicated-disk: true
storage2.monitor.reserved-bytes: 100 GB
storage2.piece-scan-on-startup: false

Is this a bug?

2

Yes, and it’s on 1.116 as well

1 Like
3

Is it only when the lazy is off and with a badger cache?

I have only one node updated so far, and it doesn’t have this behavior, but it doesn’t use the badger cache and still has lazy enabled.

Is the node restarting?
Please search for “Node\s”:

cat /mnt/x/storagenode2/storagenode.log | grep "Node\s" | tail
4

Happens with lazy on as well, but in that case the error is that used space can’t update the prefix database. Node doesn’t restart on its own.

For clarity: badger off, lazy on, dedicated disk, used-space off.

5

I do no experience this with badger on and lazy off. Could this be caused by dedicated disk?

6

Do you mean that you enabled this experimental feature?
@donald.m.motsinger do you too?

7

What’s the reason? is it corrupted or locked?

8

No, I have not enabled this feature, but I have also not experienced this issue, I simply informed that my 1.115.5 nodes run okay.

It would seem that both Mitsos and donald have this configuration enabled, and are both experiencing this issue, hence why I suggested it could be cause by it.

9

context cancelled. Neither, the databases are completely fine and on SSD. Downgrading to 1.114 makes everything work just fine.

Note: Before you reply with the usual “it’s a slow disk”. context cancelled does NOT mean slow. It means that the request has been cancelled.

As far as I can tell, 1.115 + 1.116 just ignore the scan on startup option and decide to run used-space anyway. When it fails/completes, then it respawns it and the cycle repeats forever. This isn’t about why the used space is running or failing. It’s about why the node ignores the option to not run it in the first place.

1 Like
10

Due to a timeout or the process termination (because it’s hang for example), yes. And like you noted, it’s usually because of the disk too slow.
However, this

This raises the suspicion that there is a possible problem with this new version. Could you please disable the dedicated disk feature? Does it stop behave like this?

11

Updated two nodes one without dedicated and one with dedicated to 1.116.5. Neither spams the logs with used space anymore.

That leaves just the (cosmetic as far as I can see) breakage with the dashboard mentioned in the other thread.

Dedicated disk off:

Screenshot_20241103_182925
Screenshot_20241103_182925916Ă—253 24.8 KB

Dedicated disk on:

Screenshot_20241103_182948
Screenshot_20241103_182948960Ă—268 24 KB

Edit: on the node with broken dashboard, restarting it with dedicated disk off returns the dashboard to normal.

12

I restarted both nodes. On one node the used-space-filewalker ran once for each satellite even though I have storage2.piece-scan-on-startup: false.

The other node still ran it in an endless loop. After commenting out

#storage2.monitor.dedicated-disk: true
#storage2.monitor.reserved-bytes: 100 GB
#storage2.piece-scan-on-startup: false

this node ran the used-space-filwalker once.

13

And after enabling back is it fixed?

14

I was able to reproduce that the used-space-filewalker is started and completed independently of this setting, if the option

is enabled

But not the issue with the constantly restarting scan, unless also the node is restarting.