MaxMaximus
commented
4 weeks ago Update. Strangely, I tried to reproduce the problem according to my own sequence from the 1st post. And on the 2nd (as well as the 3rd) restart of the node, GC successfully continued working from the saved position!
I haven't changed anything in the config or setup between them. The only three things that come to mind so far of how the first restart differed from the subsequent ones: 1 - node worked for a long time without restarts at the time of the first restart (more than a week, if necessary, I can later find the exact time of operation before restarting by scanning the log), and the 2nd and 3rd restarts were only after a few dozen minutes of work 2 - GC progress, judging by the number of sub-directories already created in \trash\ukfu6bhbboxilvt7jrwlqk7y2tapb5d2r2tsmj2sjxv5qaaaaaa\2024-07-06\ was almost finished (there were 845 of 1024 prefixes done) while at the 2nd and 3rd restarts it managed to process only a few prefixes. 3- Also, the difference will be that due to the reset of progress on the 2nd and 3rd passes GC did NOT move any files from \blobs\ to \trash\ because all files matching Bloom Filter were already moved during the first pass.
P.S. This is not the first time I notice that GC loses progress when restarting a node. Just only the first time I decided to document it. And the first time I saw that saving progress worked after all.
storjrobot
Hello.
Very useful feature to save-state-resume feature for GC filewalker is marked as already done some time ago: https://github.com/storj/storj/issues/6708 https://review.dev.storj.io/plugins/gitiles/storj/storj/+/0f90f061b028a9c877dbed3c01d8c3d95e4bc518
And it listed as merged and in production since storagenode v1.102: https://github.com/storj/storj/commit/0f90f06
But tests on my nodes (v 1.104.5 and 1.105.4 running as windows service) show what this feature is not working properly. GC (running in "lazy mode" as separate process) DO save current progress to db (
garbage_collection_filewalker_progress.db). But it does not use this information after node restart and begins GC process from scratch instead.Steps to reproduce the issue:
I taken node currently in the process of GC for satelliteID 12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S
I checked which prefix it was checking at the moment (by monitoring the disk I/O of GC process). It was
\blobs\ukfu6bhbboxilvt7jrwlqk7y2tapb5d2r2tsmj2sjxvw5qaaaaaa\2m\I also openedgarbage_collection_filewalker_progress.db(I use sqlite3 tool to view it):Looks like progress is saved. But here's an important note: I noticed that lazy GC writes the prefixs to this database immediately when it STARTS working on it. Whereas the name of the field in db table
last_checked_prefix(as well as the description of the changes on the github) assume that the last prefix already processed should be stored in the database. Either this is an incorrect name and description of the field. Or could be another bug in the code that records the current (just started) prefix instead of the previous (last completed) one.I stopped the node correctly:
sc stop storagenodeand waited while all storj processes finished and exitedI started node again:
sc start storagenodeChecked which prefix GC is processing now. It was
\blobs\ukfu6bhbboxilvt7jrwlqk7y2tapb5d2r2tsmj2sjxvw5qaaaaaa\aa\That is, it started its work from the beginning, the prefix stored in the database (\2m), which was last processing during the previous launch, was ignored.After some time progress in
garbage_collection_filewalker_progress.dbwas also reset.Logs: storagenode.log around restart
I also recoeded full trace of disk IO of GC processed (two PIDs - before and after restart) by using Process Monitor. Attach it as zipped .csv as it large (log of ~5k IOP)
Garbage_Collector_IO.zip