1.78.2 slamming my array (Windows)

[Stob]

Since upgrading to version 1.78.2 my storage has been very slow to respond. I had previously disabled the filewalker on start as it used to take over 7 days to run. Now with the latest version my drive is verging on non-responsive.

I checked monkit and haven’t seen such a backlog before…

[132176141495038753,6923289289273561108] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m29.599319041s)
 [2564435030571292207,6923289289273561108] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m29.599300541s)
  [4996693919647545660,6923289289273561108] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m29.599290241s)

[385875927250589988,7176989075029112343] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h2m2.966804441s)
 [2818134816326843442,7176989075029112343] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h2m2.966764141s)
  [5250393705403096895,7176989075029112343] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h2m2.966748441s)
   [4431184082852494036,7176989075029112343] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h2m2.680569441s)
    [6863442971928747490,7176989075029112343] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xa2, 0x8b, 0x4f, 0x4, 0xe1, 0xb, 0xae, 0x85, 0xd6, 0x7f, 0x4c, 0x6c, 0xb8, 0x2b, 0xf8, 0xd4, 0xc0, 0xf0, 0xf4, 0x7a, 0x8e, 0xa7, 0x26, 0x27, 0x52, 0x4d, 0xeb, 0x6e, 0xc0, 0x0, 0x0, 0x0}, 2, 2560, time.Time(2023-05-08T10:23:08.3004244Z)}) (elapsed: 1h2m2.680560541s)

[425773472147132400,7216886619925654755] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m40.736092041s)
 [2858032361223385854,7216886619925654755] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m40.737576141s)
  [5290291250299639307,7216886619925654755] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m40.737559541s)
   [8516389783350940496,7216886619925654755] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m39.426115641s)
    [1725276635572418142,7216886619925654755] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0x84, 0xa7, 0x4c, 0x2c, 0xd4, 0x3c, 0x5b, 0xa7, 0x65, 0x35, 0xe1, 0xf4, 0x2f, 0x5d, 0xf7, 0xc2, 0x87, 0xed, 0x68, 0xd3, 0x35, 0x22, 0x78, 0x2f, 0x4a, 0xfa, 0xbf, 0xdb, 0x40, 0x0, 0x0, 0x0}, 2, 181248, time.Time(2023-05-08T10:23:31.556282Z)}) (elapsed: 1h1m39.426106141s)

[840799489549717747,7631912637328240102] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m53.005293041s)
 [3273058378625971201,7631912637328240102] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m53.005265041s)
  [5705317267702224654,7631912637328240102] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m53.005252441s)
   [8233634864953414684,7631912637328240102] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m52.731559641s)
    [1442521717174892330,7631912637328240102] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xa2, 0x8b, 0x4f, 0x4, 0xe1, 0xb, 0xae, 0x85, 0xd6, 0x7f, 0x4c, 0x6c, 0xb8, 0x2b, 0xf8, 0xd4, 0xc0, 0xf0, 0xf4, 0x7a, 0x8e, 0xa7, 0x26, 0x27, 0x52, 0x4d, 0xeb, 0x6e, 0xc0, 0x0, 0x0, 0x0}, 2, 4608, time.Time(2023-05-08T10:23:18.2509023Z)}) (elapsed: 1h1m52.731549041s)

[2018873966224511789,8809987114003034143] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m52.036121441s)
 [4451132855300765242,8809987114003034143] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m52.036104241s)
  [6883391744377018696,8809987114003034143] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m52.036097841s)
   [188337304773432918,8809987114003034143] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m50.856003041s)
    [2620596193849686371,8809987114003034143] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xa2, 0x8b, 0x4f, 0x4, 0xe1, 0xb, 0xae, 0x85, 0xd6, 0x7f, 0x4c, 0x6c, 0xb8, 0x2b, 0xf8, 0xd4, 0xc0, 0xf0, 0xf4, 0x7a, 0x8e, 0xa7, 0x26, 0x27, 0x52, 0x4d, 0xeb, 0x6e, 0xc0, 0x0, 0x0, 0x0}, 2, 2304, time.Time(2023-05-08T10:23:20.1265756Z)}) (elapsed: 1h1m50.855992341s)

[2160251425423274695,8951364573201797049] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m42.033148441s)
 [4592510314499528148,8951364573201797049] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m42.033124341s)
  [7024769203575781602,8951364573201797049] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m42.033114041s)
   [4855316460448782754,8951364573201797049] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m38.036187941s)
    [7287575349525036208,8951364573201797049] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0x84, 0xa7, 0x4c, 0x2c, 0xd4, 0x3c, 0x5b, 0xa7, 0x65, 0x35, 0xe1, 0xf4, 0x2f, 0x5d, 0xf7, 0xc2, 0x87, 0xed, 0x68, 0xd3, 0x35, 0x22, 0x78, 0x2f, 0x4a, 0xfa, 0xbf, 0xdb, 0x40, 0x0, 0x0, 0x0}, 4, 7936, time.Time(2023-05-08T10:23:32.9472789Z)}) (elapsed: 1h1m38.036176441s)

[2504588713226478589,72329824150225135] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h2m2.329256341s)
 [4936847602302732042,72329824150225135] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h2m2.329230341s)
  [7369106491378985496,72329824150225135] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h2m2.329220541s)
   [770110759950336294,72329824150225135] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h2m2.043841841s)
    [3202369649026589748,72329824150225135] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xa2, 0x8b, 0x4f, 0x4, 0xe1, 0xb, 0xae, 0x85, 0xd6, 0x7f, 0x4c, 0x6c, 0xb8, 0x2b, 0xf8, 0xd4, 0xc0, 0xf0, 0xf4, 0x7a, 0x8e, 0xa7, 0x26, 0x27, 0x52, 0x4d, 0xeb, 0x6e, 0xc0, 0x0, 0x0, 0x0}, 2, 2560, time.Time(2023-05-08T10:23:08.9396296Z)}) (elapsed: 1h2m2.043826241s)

[3222318421474860954,790059532398607500] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m50.023940241s)
 [5654577310551114407,790059532398607500] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m50.023912541s)
  [8086836199627367861,790059532398607500] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m50.023900141s)
   [8996683324225623379,790059532398607500] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m36.534414641s)
    [2205570176447101024,790059532398607500] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0x7b, 0x2d, 0xe9, 0xd7, 0x2c, 0x2e, 0x93, 0x5f, 0x19, 0x18, 0xc0, 0x58, 0xca, 0xaf, 0x8e, 0xd0, 0xf, 0x5, 0x81, 0x63, 0x90, 0x8, 0x70, 0x73, 0x17, 0xff, 0x1b, 0xd0, 0x0, 0x0, 0x0, 0x0}, 4, 2319360, time.Time(2023-05-08T10:23:34.4487294Z)}) (elapsed: 1h1m36.534397741s)

[3267637172498687283,835378283422433830] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m41.474608341s)
 [5699896061574940737,835378283422433830] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m41.474584441s)
  [8132154950651194190,835378283422433830] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m41.474574041s)
   [8708507199700813649,835378283422433830] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m38.443670041s)
    [1917394051922291295,835378283422433830] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xa2, 0x8b, 0x4f, 0x4, 0xe1, 0xb, 0xae, 0x85, 0xd6, 0x7f, 0x4c, 0x6c, 0xb8, 0x2b, 0xf8, 0xd4, 0xc0, 0xf0, 0xf4, 0x7a, 0x8e, 0xa7, 0x26, 0x27, 0x52, 0x4d, 0xeb, 0x6e, 0xc0, 0x0, 0x0, 0x0}, 2, 2560, time.Time(2023-05-08T10:23:32.5399107Z)}) (elapsed: 1h1m38.443662441s)

[3354589520479920489,922330631403667035] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h2m11.806662141s)
 [5786848409556173942,922330631403667035] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h2m11.806591641s)
  [8219107298632427396,922330631403667035] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h2m11.806574741s)
   [4552612769602985736,922330631403667035] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h2m4.746409941s)
    [6984871658679239190,922330631403667035] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xaf, 0x2c, 0x42, 0x0, 0x3e, 0xfc, 0x82, 0x6a, 0xb4, 0x36, 0x1f, 0x73, 0xf9, 0xd8, 0x90, 0x94, 0x21, 0x46, 0xfe, 0xe, 0xbe, 0x80, 0x67, 0x86, 0xf8, 0xe7, 0x19, 0x8, 0x0, 0x0, 0x0, 0x0}, 4, 2319360, time.Time(2023-05-08T10:23:06.2369048Z)}) (elapsed: 1h2m4.746392241s)

[3490545773551399477,1058286884475146024] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m56.340932341s)
 [5922804662627652931,1058286884475146024] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m56.340903941s)
  [8355063551703906384,1058286884475146024] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m56.340892341s)
   [3945469335850527236,1058286884475146024] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m52.037285141s)
    [6377728224926780690,1058286884475146024] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xaf, 0x2c, 0x42, 0x0, 0x3e, 0xfc, 0x82, 0x6a, 0xb4, 0x36, 0x1f, 0x73, 0xf9, 0xd8, 0x90, 0x94, 0x21, 0x46, 0xfe, 0xe, 0xbe, 0x80, 0x67, 0x86, 0xf8, 0xe7, 0x19, 0x8, 0x0, 0x0, 0x0, 0x0}, 4, 15360, time.Time(2023-05-08T10:23:18.9462676Z)}) (elapsed: 1h1m52.038279041s)

[3606553254174607260,1174294365098353806] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m44.194526341s)
 [6038812143250860713,1174294365098353806] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m44.194503941s)
  [8471071032327114167,1174294365098353806] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m44.194496041s)
   [3702611962349543836,1174294365098353806] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m43.969359241s)
    [6134870851425797290,1174294365098353806] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xaf, 0x2c, 0x42, 0x0, 0x3e, 0xfc, 0x82, 0x6a, 0xb4, 0x36, 0x1f, 0x73, 0xf9, 0xd8, 0x90, 0x94, 0x21, 0x46, 0xfe, 0xe, 0xbe, 0x80, 0x67, 0x86, 0xf8, 0xe7, 0x19, 0x8, 0x0, 0x0, 0x0, 0x0}, 2, 768, time.Time(2023-05-08T10:23:27.0151434Z)}) (elapsed: 1h1m43.969349441s)

[3682663189901272630,1250404300825019177] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m53.215108641s)
 [6114922078977526084,1250404300825019177] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m53.215080741s)
  [8547180968053779537,1250404300825019177] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m53.215069941s)
   [8784617135427479020,1250404300825019177] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m46.247642641s)
    [1993503987648956665,1250404300825019177] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0x7b, 0x2d, 0xe9, 0xd7, 0x2c, 0x2e, 0x93, 0x5f, 0x19, 0x18, 0xc0, 0x58, 0xca, 0xaf, 0x8e, 0xd0, 0xf, 0x5, 0x81, 0x63, 0x90, 0x8, 0x70, 0x73, 0x17, 0xff, 0x1b, 0xd0, 0x0, 0x0, 0x0, 0x0}, 4, 2319360, time.Time(2023-05-08T10:23:24.7366654Z)}) (elapsed: 1h1m46.247633941s)

[4036106837898179895,1603847948821926442] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m37.010937541s)
 [6468365726974433349,1603847948821926442] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m37.010913041s)
  [8900624616050686802,1603847948821926442] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m37.010903941s)
   [9163430761999941408,1603847948821926442] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m32.734755541s)
    [2372317614221419054,1603847948821926442] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xaf, 0x2c, 0x42, 0x0, 0x3e, 0xfc, 0x82, 0x6a, 0xb4, 0x36, 0x1f, 0x73, 0xf9, 0xd8, 0x90, 0x94, 0x21, 0x46, 0xfe, 0xe, 0xbe, 0x80, 0x67, 0x86, 0xf8, 0xe7, 0x19, 0x8, 0x0, 0x0, 0x0, 0x0}, 4, 2319360, time.Time(2023-05-08T10:23:38.2495098Z)}) (elapsed: 1h1m32.734742641s)

[4309755396102002336,1877496507025748883] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m58.593875741s)
 [6742014285178255790,1877496507025748883] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m58.593849441s)
  [9174273174254509243,1877496507025748883] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m58.593837941s)
   [5417141143177414925,1877496507025748883] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m58.336013241s)
    [7849400032253668378,1877496507025748883] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xaf, 0x2c, 0x42, 0x0, 0x3e, 0xfc, 0x82, 0x6a, 0xb4, 0x36, 0x1f, 0x73, 0xf9, 0xd8, 0x90, 0x94, 0x21, 0x46, 0xfe, 0xe, 0xbe, 0x80, 0x67, 0x86, 0xf8, 0xe7, 0x19, 0x8, 0x0, 0x0, 0x0, 0x0}, 2, 2560, time.Time(2023-05-08T10:23:12.6485852Z)}) (elapsed: 1h1m58.335996841s)

[4329704168550273542,1897445279474020089] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m46.868859741s)
 [6761963057626526996,1897445279474020089] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m46.868821041s)
  [9194221946702780449,1897445279474020089] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m46.868805641s)
   [8612448491525877073,1897445279474020089] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m38.497284841s)
    [1821335343747354718,1897445279474020089] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xaf, 0x2c, 0x42, 0x0, 0x3e, 0xfc, 0x82, 0x6a, 0xb4, 0x36, 0x1f, 0x73, 0xf9, 0xd8, 0x90, 0x94, 0x21, 0x46, 0xfe, 0xe, 0xbe, 0x80, 0x67, 0x86, 0xf8, 0xe7, 0x19, 0x8, 0x0, 0x0, 0x0, 0x0}, 4, 399104, time.Time(2023-05-08T10:23:32.4868689Z)}) (elapsed: 1h1m38.497274141s)

[4713939001250019848,2281680112173766395] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m42.910817941s)
 [7146197890326273302,2281680112173766395] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m42.910740741s)
  [355084742547750947,2281680112173766395] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m42.910722941s)
   [5194232542124702731,2281680112173766395] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m41.534314341s)
    [7626491431200956184,2281680112173766395] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xa2, 0x8b, 0x4f, 0x4, 0xe1, 0xb, 0xae, 0x85, 0xd6, 0x7f, 0x4c, 0x6c, 0xb8, 0x2b, 0xf8, 0xd4, 0xc0, 0xf0, 0xf4, 0x7a, 0x8e, 0xa7, 0x26, 0x27, 0x52, 0x4d, 0xeb, 0x6e, 0xc0, 0x0, 0x0, 0x0}, 2, 1218560, time.Time(2023-05-08T10:23:29.4502436Z)}) (elapsed: 1h1m41.534300341s)

[4976745147199274454,2544486258123021001] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m40.646682441s)
 [7409004036275527908,2544486258123021001] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m40.646658141s)
  [617890888497005553,2544486258123021001] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m40.646649841s)
   [6877970538249734778,2544486258123021001] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m37.349687841s)
    [86857390471212424,2544486258123021001] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xa2, 0x8b, 0x4f, 0x4, 0xe1, 0xb, 0xae, 0x85, 0xd6, 0x7f, 0x4c, 0x6c, 0xb8, 0x2b, 0xf8, 0xd4, 0xc0, 0xf0, 0xf4, 0x7a, 0x8e, 0xa7, 0x26, 0x27, 0x52, 0x4d, 0xeb, 0x6e, 0xc0, 0x0, 0x0, 0x0}, 3, 256, time.Time(2023-05-08T10:23:33.6346991Z)}) (elapsed: 1h1m37.349675241s)

[5032906310477668619,2600647421401415165] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h2m2.157931741s)
 [7465165199553922072,2600647421401415165] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h2m2.157903441s)
  [674052051775399718,2600647421401415165] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h2m2.157889141s)
   [5225023726827541772,2600647421401415165] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h2m1.352794241s)
    [7657282615903795225,2600647421401415165] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xaf, 0x2c, 0x42, 0x0, 0x3e, 0xfc, 0x82, 0x6a, 0xb4, 0x36, 0x1f, 0x73, 0xf9, 0xd8, 0x90, 0x94, 0x21, 0x46, 0xfe, 0xe, 0xbe, 0x80, 0x67, 0x86, 0xf8, 0xe7, 0x19, 0x8, 0x0, 0x0, 0x0, 0x0}, 3, 256, time.Time(2023-05-08T10:23:09.6315377Z)}) (elapsed: 1h2m1.352764841s)

[5386349958474575884,2954091069398322430] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m40.694248041s)
 [7818608847550829337,2954091069398322430] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m40.694219841s)
  [1027495699772306983,2954091069398322430] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m40.694208041s)
   [2013452760097227871,2954091069398322430] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m37.433392341s)
    [4445711649173481325,2954091069398322430] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xf4, 0x74, 0x53, 0x5a, 0x19, 0xdb, 0x0, 0xdb, 0x4f, 0x80, 0x71, 0xa1, 0xbe, 0x6c, 0x25, 0x51, 0xf4, 0xde, 0xd6, 0xa6, 0xe3, 0x8f, 0x8, 0x18, 0xc6, 0x8c, 0x68, 0xd0, 0x0, 0x0, 0x0, 0x0}, 3, 256, time.Time(2023-05-08T10:23:33.5508633Z)}) (elapsed: 1h1m37.433369741s)

[5437089915625686131,3004831026549432677] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m44.634334341s)
 [7869348804701939584,3004831026549432677] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m44.634312141s)
  [1078235656923417230,3004831026549432677] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m44.634301241s)
   [5533148623800622707,3004831026549432677] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m44.400801141s)
    [7965407512876876161,3004831026549432677] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xa2, 0x8b, 0x4f, 0x4, 0xe1, 0xb, 0xae, 0x85, 0xd6, 0x7f, 0x4c, 0x6c, 0xb8, 0x2b, 0xf8, 0xd4, 0xc0, 0xf0, 0xf4, 0x7a, 0x8e, 0xa7, 0x26, 0x27, 0x52, 0x4d, 0xeb, 0x6e, 0xc0, 0x0, 0x0, 0x0}, 2, 1024, time.Time(2023-05-08T10:23:26.583542Z)}) (elapsed: 1h1m44.400788441s)

[6524526890252827513,4092268001176574060] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m54.815266541s)
 [8956785779329080967,4092268001176574060] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m54.815242041s)
  [2165672631550558612,4092268001176574060] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m54.815231341s)
   [7798660075102558131,4092268001176574060] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m52.516184341s)
    [1007546927324035777,4092268001176574060] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xa2, 0x8b, 0x4f, 0x4, 0xe1, 0xb, 0xae, 0x85, 0xd6, 0x7f, 0x4c, 0x6c, 0xb8, 0x2b, 0xf8, 0xd4, 0xc0, 0xf0, 0xf4, 0x7a, 0x8e, 0xa7, 0x26, 0x27, 0x52, 0x4d, 0xeb, 0x6e, 0xc0, 0x0, 0x0, 0x0}, 3, 256, time.Time(2023-05-08T10:23:18.4681198Z)}) (elapsed: 1h1m52.516174641s)

[6589794413724925049,4157535524648671595] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m39.262916041s)
 [9022053302801178502,4157535524648671595] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m39.262882641s)
  [2230940155022656148,4157535524648671595] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m39.262870241s)
   [4132165546073116472,4157535524648671595] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m36.846737141s)
    [6564424435149369925,4157535524648671595] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0x84, 0xa7, 0x4c, 0x2c, 0xd4, 0x3c, 0x5b, 0xa7, 0x65, 0x35, 0xe1, 0xf4, 0x2f, 0x5d, 0xf7, 0xc2, 0x87, 0xed, 0x68, 0xd3, 0x35, 0x22, 0x78, 0x2f, 0x4a, 0xfa, 0xbf, 0xdb, 0x40, 0x0, 0x0, 0x0}, 4, 3840, time.Time(2023-05-08T10:23:34.1377457Z)}) (elapsed: 1h1m36.846727341s)

[7485113972002193278,5052855082925939825] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m50.668050941s)
 [694000824223670924,5052855082925939825] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m50.668004841s)
  [3126259713299924377,5052855082925939825] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m50.667986841s)
   [7171567868901828425,5052855082925939825] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m48.499704741s)
    [380454721123306071,5052855082925939825] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xaf, 0x2c, 0x42, 0x0, 0x3e, 0xfc, 0x82, 0x6a, 0xb4, 0x36, 0x1f, 0x73, 0xf9, 0xd8, 0x90, 0x94, 0x21, 0x46, 0xfe, 0xe, 0xbe, 0x80, 0x67, 0x86, 0xf8, 0xe7, 0x19, 0x8, 0x0, 0x0, 0x0, 0x0}, 2, 181248, time.Time(2023-05-08T10:23:22.4847121Z)}) (elapsed: 1h1m48.499629941s)

[8056045014924528820,5623786125848275366] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m33.165752341s)
 [1264931867146006465,5623786125848275366] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m33.165711341s)
  [3697190756222259919,5623786125848275366] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m33.165692141s)
   [8753825950724639979,5623786125848275366] storj.io/storj/storagenode/storagenodedb.(*bandwidthDB).Add() (elapsed: 1h1m32.370660741s)
    [1962712802946117624,5623786125848275366] storj.io/private/tagsql.(*sqlDB).ExecContext("\n\t\tINSERT INTO\n\t\t\tbandwidth_usage(satellite_id, action, amount, created_at)\n\t\tVALUES(?, ?, ?, datetime(?))", {storj.NodeID{0xf4, 0x74, 0x53, 0x5a, 0x19, 0xdb, 0x0, 0xdb, 0x4f, 0x80, 0x71, 0xa1, 0xbe, 0x6c, 0x25, 0x51, 0xf4, 0xde, 0xd6, 0xa6, 0xe3, 0x8f, 0x8, 0x18, 0xc6, 0x8c, 0x68, 0xd0, 0x0, 0x0, 0x0, 0x0}, 3, 256, time.Time(2023-05-08T10:23:38.6135166Z)}) (elapsed: 1h1m32.370645241s)

[8849884658899576555,6417625769823323102] storj.io/common/rpc/rpctracing./piecestore.Piecestore/Download() (elapsed: 1h1m29.791513441s)
 [2058771511121054201,6417625769823323102] storj.io/storj/storagenode/piecestore.live-request() (elapsed: 1h1m29.791476041s)
  [4491030400197307654,6417625769823323102] storj.io/storj/storagenode/piecestore.(*Endpoint).Download() (elapsed: 1h1m29.791460541s)
   [6008020958548021672,6417625769823323102] storj.io/storj/storagenode/pieces.(*Store).Reader() (elapsed: 1h1m29.353937741s)
    [8440279847624275126,6417625769823323102] storj.io/storj/storagenode/blobstore/filestore.(*blobStore).Open() (elapsed: 1h1m29.353928541s)
     [1649166699845752771,6417625769823323102] storj.io/storj/storagenode/blobstore/filestore.(*Dir).Open() (elapsed: 1h1m29.353917341s)

[2937922408526491458,505663519450238004] storj.io/private/process.root() (elapsed: 1h0m53.4774881s)
 [7842337731575540777,505663519450238004] storj.io/storj/storagenode.(*Peer).Run() (elapsed: 1h0m49.1946249s)

[2734962579922050470,505663519450238004] storj.io/storj/private/server.(*Server).Run() (elapsed: 1h0m48.258414s, orphaned)

[6997758130449382794,505663519450238004] storj.io/storj/storagenode/bandwidth.(*Service).Run() (elapsed: 1h0m48.2594809s, orphaned)

[7356622984573573977,505663519450238004] storj.io/storj/storagenode/collector.(*Service).Run() (elapsed: 1h0m48.2526954s, orphaned)

[590879815370606746,505663519450238004] storj.io/storj/storagenode/console/consoleserver.(*Server).Run() (elapsed: 1h0m48.2566221s, orphaned)

[1217972021571336452,505663519450238004] storj.io/storj/storagenode/contact.(*Chore).Run() (elapsed: 1h0m48.2589528s, orphaned)

[7478051671324065677,505663519450238004] storj.io/storj/storagenode/gracefulexit.(*Chore).Run() (elapsed: 1h0m48.2559065s, orphaned)

[2229299060471812464,505663519450238004] storj.io/storj/storagenode/monitor.(*Service).Run() (elapsed: 1h0m48.2588389s, orphaned)

[3240626099372288476,505663519450238004] storj.io/storj/storagenode/orders.(*Service).Run() (elapsed: 1h0m48.2581461s, orphaned)

[2421416476821685617,505663519450238004] storj.io/storj/storagenode/pieces.(*CacheService).Run() (elapsed: 1h0m48.2576368s, orphaned)

[8344221139449338549,505663519450238004] storj.io/storj/storagenode/pieces.(*Store).Trash() (elapsed: 1h1m31.294667141s, orphaned)
 [1553107991670816195,505663519450238004] storj.io/storj/storagenode/blobstore/filestore.(*blobStore).StatWithStorageFormat() (elapsed: 1h1m31.294655241s)
  [3985366880747069648,505663519450238004] storj.io/storj/storagenode/blobstore/filestore.(*Dir).StatWithStorageFormat() (elapsed: 1h1m31.294649841s)

[9116470916425271395,505663519450238004] storj.io/storj/storagenode/pieces.(*TrashChore).Run() (elapsed: 1h0m48.2580567s, orphaned)
 [6340056136987164313,505663519450238004] storj.io/storj/storagenode/pieces.(*Store).EmptyTrash() (elapsed: 1h12m58.51331387s)
  [8772315026063417766,505663519450238004] storj.io/storj/storagenode/blobstore/filestore.(*blobStore).EmptyTrash() (elapsed: 1h12m58.51330627s)
   [1981201878284895412,505663519450238004] storj.io/storj/storagenode/blobstore/filestore.(*Dir).EmptyTrash() (elapsed: 1h12m58.51330147s)
    [4413460767361148865,505663519450238004] storj.io/storj/storagenode/blobstore/filestore.(*Dir).walkNamespaceInPath() (elapsed: 1h12m58.51329487s)

[7599480358074557377,505663519450238004] storj.io/storj/storagenode/retain.(*Service).Run() (elapsed: 1h0m48.2581846s, orphaned)

[6082489799723843359,505663519450238004] storj.io/storj/storagenode/version.(*Chore).Run() (elapsed: 1h0m48.2589166s, orphaned)

Is the new lazy filewalker thing affecting my node?

[artur]

Do you mind getting a CPU profile when this happens and pasting it here or sending it to me directly? It’s curl localhost:5999/debug/pprof/profile (more info: Guide to debug my storage node, uplink, s3 gateway, satellite).

[clement]

@Stob

Is the new lazy filewalker thing affecting my node?

The lazy file walker is disabled by default. Did you enable it?

Also, I don’t see the work of the lazy filewalker in the logs. Currently the only part of the lazyfilewalker that is released is the used-space-filewalker (for the piece scan on startup) and it will not work since you pointed out that you have disabled the piece scan on startup . The lazy filewalker for the retain service is not yet released. From the logs, the filewalker that was running was called by the retain service (garbage collection).

[Stob]

@clement

The lazy file walker is disabled by default. Did you enable it?

I didn’t enable it. I made an uneducated guess as the symptoms experienced were very similar to when the filewalker was previously enabled on startup.

[Stob]

The issue seemed to have resolved itself for now. So I closed the process, started the service and then ran the profile command. The system didn’t seem to have the slowdown quite to the same extent but was still busy on the storage:

FYI - nothing else is on the drive.

I will send the profile file in a DM as it’s not readable in notepad++.

[Alexey]

It could be a Garbage Collector, but since the read is not equal to writes, it also could be just uploads to your node.

[Stob]

My node is full and I’ve reduced the allocated space so currently my ingress is 0. Possibly the garbage collector contributing…

storj.io/storj/storagenode/pieces.(*Store).EmptyTrash()
storj.io/storj/storagenode/blobstore/filestore.(*blobStore).EmptyTrash()
storj.io/storj/storagenode/blobstore/filestore.(*Dir).EmptyTrash()

[AnoStor]

This is similar to what I’m seeing after the update - I’ve had no luck tracking it down other than it seems to be writing to lots of blob files. I also set my node to effectively full, temporarily, and confirmed no ingress. My array is handling it but only just. I handicapped it by coincidentally starting an online RAID expansion right before it started…

What file types do you see open? Same blob files as I do?

Edit: could this be STORJ purging the fake data from the network as part of the move to change incentives and payouts and all that?

[Alexey]

Then it would be reads from blobs and writes to trash. However, I’m not sure how the monitoring interpret moves from the one folder to another. Perhaps it writes to the source to relink to a new location?

[jammerdan]

@clement

Currently the only part of the lazyfilewalker that is released is the used-space-filewalker (for the piece scan on startup)

What else is planned?
There seem to be several filewalkers in place:

@Toyoo

Even four of them, if you count exhaustively.

• Estimation of disk space used (at the node’s startup, can be disabled).
• Garbage collection through bloom filters (each time a satellite sends a bloom filter and optimized few releases ago to avoid most of random I/O).
• Trash collection (this one is usually small, only goes through the trash/ directory).
• Graceful exit (only when invoked, obviously).

I am running into massive reads on startup which seems to be caused by the TrashChore:

Massive reads on startup

Is it this one? [7530092614813486020,3333302239938971669] storj.io/storj/storagenode/pieces.(*TrashChore).Run() (elapsed: 6m54.901722685s, orphaned) [1942410985489664106,3333302239938971669] storj.io/storj/storagenode/pieces.(*Store).EmptyTrash() (elapsed: 41.157451163s) [5081579554688100975,3333302239938971669] storj.io/storj/storagenode/blobstore/filestore.(*blobStore).EmptyTrash() (elapsed: 41.157451433s) [8220748123886537845,3333302239938971669] storj.io/storj/storagenode/blobstore/fi…

And I don’t really see a reason why this is handled the way it is. As already said, with nodes getting bigger traversing files is getting more and more expensive and I don’t see a reason why we need to run through the trash files on every node startup.
What is even worse is that there is no config setting to control the trash traversing task, so it runs whenever it wants to run at whatever priority it chooses. That’s also not a good implementation.
To me it seems that for the trash it would be sufficient to collect the modification times once. This should be done when the piece is moved into the trash. This can be stored in a database. From that modification date then we can calculate when to finally delete the piece. Also it is sufficient to run this only once a day to find out which pieces to delete on the current day and then delete the pieces over the day as background task with low priority.
This is my idea of a better implementation.
And it should also include the temp folder, as it seems that massive amounts of data can get pile up there from the partial files there without ever deleted automatically:

Large temporary folder

I have just checked on one of those temp folders and it is telling me it is holding 179878 pieces and has a size of 446 GB. # find temp -type f | wc -l 179878 # du -sh --apparent-size temp 447G temp The oldes file is from August 03 2022: # ls -lt | tail -1 -rw------- 1 root root 182016 Aug 3 2022 blob-1692607602.partial This certainly does not sound right.