Client: daily kbfs load spikes, on macOS

[lucymhdavies]

my log id: 1aa4f213045d69a0f13bda1c

About once daily I get massive load and memory spikes from kbfs. Upwards of a load of 20, which renders my computer unreponsive for about a minute.

[strib]

Thanks for the report. Was this log sent right after such a spike? We only send a small portion of the logs, and yours only contains about 18 minutes worth of data, so I'm not sure if I should be looking for the spike there, or asking for more logs. Thanks!

[lucymhdavies]

It wasn't, no. I'll do another keybase log send next time it happens.

Thanks for the super fast response!

[strib]

Cool thanks. Or if you're willing to share more logs, you can do something like this:

tar -czf /keybase/private/strib,lmhd/kbfs_logs.tgz $HOME/Library/Logs/*kbfs*

and let me know about what time it happened.

[lucymhdavies]

Tried running that command, but got the following:

$ tar -czf /keybase/private/strib,lmhd/kbfs_logs.tgz $HOME/Library/Logs/*kbfs*
tar: Removing leading '/' from member names
tar: Users/lda32/Library/Logs/keybase.kbfs.log: Truncated write; file may have grown while being archived.

Most recent spikes: 09:36 and 20:02 UTC, though looks like my logs only go back as far as 21:06 UTC anyway. Ah well.

I'll send some more logs if (hopefully if, not when) I get another load spike.

[strib]

Thanks! The logs you shared do go back far enough (there are rotated logs that were included in that command). It looks like both of those times correspond to KBFS getting restarted.

High CPU on process restart is somewhat expected. I think we may have fixed a few things recently that might improve things in the next release coming out next week, but I'm not 100% sure.

It seems that, during both times, kbfs wasn't running for several hours, so maybe that indicates when you turned your computer off? Not sure why else it would have restarted -- I don't see any crashes or anything. Does that sound possible?

[lucymhdavies]

Just had a fairly small load spike. Load went up to about 11 at 10:43 UTC. Keybase is currently using 17G of memory.

Log: 26086109ffb9dac60b6a1a1c

And yeah, when kbfs wasn't running, that would be because my computer was off.

Looking at when the load spikes happened in the past day, they were not long after the machine was booted up.

[strib]

Ok thanks. I see a little more about what's causing the non-restart spikes. Periodically your client is looking through the history of your public folder, looking for data that has been deleted in order to tell our servers that it should be cleaned up and no longer counted against your quota. (This has to be done on your client, rather than our servers, due to the encrypted nature of the data -- we can't tell what's been deleted until you tell us.)

It looks like your client is quite a bit behind, and is still processing updates to that folder from back in October. This is expensive because the device used to write those updates has now been revoked, which forces your client to do extra work to verify that they were valid clients at the time the write happened.

It's the kind of work that will get done eventually, but I understand it's pretty annoying. I can think of a few short term options:

1. You decide you don't care about cleaning up your quota usage. In this case, you can run a special tool to fast-forward this cleanup process. If you're comfortable with compiling Go code, you can compile the tool yourself, or I can compile it for you and share it with you. And if at some point in the future you need more quota, we can help you our manually with that.
2. I build a special release for you that skips all the expensive checks on revoked keys, where you're placing all your trust in our servers not to serve you bad data. Keybase is usually based on a principle of not trusting our servers for anything, just in case, but if you want to temporarily trust us, I could ship you something that turns off those checks.
3. Accept these kinds of spikes while the client works through this process. (We recently fixed a bug that was causing some folders _not_ to run this periodically, and I think your folder must have been stuck not cleaning things up for quite a while until that recent release. That's why you're so behind.) If you want to check the process, you can look at the output of cat /keybase/public/lmhd/.kbfs_status, and look at the LastGCRevision field. Right now it's at 533 -- it needs to get to 15,100 or so before the extra checks go away, so it's going to be quite a while I think.

Let me know what you prefer. Sorry for the rough experience.

[strib]

One other option:

1. Like option 1, if you decide you don't care about your quota for now, we can completely reset the folder, and start it over completely fresh. The used quota will leak, but we can fix that manually in the future if needed. Then you'd have to re-populate it again, but looks like you only have one file in there anyway.

[lucymhdavies]

Ah. That makes a lot of sense.

I did at one point try out kbfs as a place for hosting _lots_ of really small files (decided against that pretty quickly too), so that's probably what caused it to get into this state in the first place.

Probably explains why I'm seeing this too:

$ keybase fs quota
Usage:      -6652181068 bytes
Quota:      250.00 GB

I'm comfortable compiling go code, so option 1 sounds good. But yes, there's only the one file in there, so option 4 is probably the easiest.

[strib]

Sigh. Welp, I guess you don't actually have any quota issues then, hehe. Obviously there's something we need to fix there, I've been putting it off for a while but should probably get to it soon.

Anyway, if you want to try the tool yourself, do this:

go get github.com/keybase/client/go/kbfs/kbfstool
KEYBASE_RUN_MODE=prod kbfstool md force-qr /keybase/public/lmhd

I think that should fix everything for you. Happy to reset it as well if that turns out not to work.

[lucymhdavies]

~/go/src/github.com/keybase/client/go/kbfs/kbfstool [master|✔]
18:23 $ KEYBASE_RUN_MODE=prod kbfstool md force-qr /keybase/public/lmhd
▶ WARNING adding NotifyService protocol
▶ WARNING Failed to read cached favorites from disk: leveldb: not found
▶ INFO OnConnect called with a new connection
▶ INFO authentication successful; ping interval: 30s
Looking for unmerged branch...
Getting latest metadata...
Will put a forced QR op up to revision 18284:
md forceQR: Tried to do invalid operation GetUserDevicePublicKeys on non-private TLF 8c75bb5ee51a3826cbeb7ef4b3371217 (ver=MDVer(SegregatedKeyBundles))
Root metadata
-------------
MD revision: 18285
MD size: 388 bytes
Private MD size: 0 bytes
MD version: MDVer(SegregatedKeyBundles)

(*kbfsmd.RootMetadataV3)({
  WriterMetadata: (kbfsmd.WriterMetadataV3) {
    SerializedPrivateMetadata: ([]uint8) <nil>,
    LastModifyingWriter: (keybase1.UID) (len=32) 52f9121d5541251a4898f7f331c3a519,
    Writers: ([]keybase1.UserOrTeamID) (len=1) {
      (keybase1.UserOrTeamID) (len=32) 52f9121d5541251a4898f7f331c3a519
    },
    UnresolvedWriters: ([]keybase1.SocialAssertion) <nil>,
    WKeyBundleID: (kbfsmd.TLFWriterKeyBundleID) ,
    LatestKeyGen: (kbfsmd.KeyGen) -1,
    ID: (tlf.ID) 8c75bb5ee51a3826cbeb7ef4b3371217,
    BID: (kbfsmd.BranchID) 00000000000000000000000000000000,
    WFlags: (kbfsmd.WriterFlags) WriterFlags(),
    DiskUsage: (uint64) 104196,
    MDDiskUsage: (uint64) 613585107,
    RefBytes: (uint64) 0,
    UnrefBytes: (uint64) 0,
    MDRefBytes: (uint64) 0,
    UnknownFieldSetHandler: (codec.UnknownFieldSetHandler) {
      ufs: (codec.UnknownFieldSet) {
        fields: (map[string][]uint8) <nil>
      }
    }
  },
  LastModifyingUser: (keybase1.UID) (len=32) 52f9121d5541251a4898f7f331c3a519,
  Flags: (kbfsmd.MetadataFlags) MetadataFlags(),
  Revision: (kbfsmd.Revision) 18285,
  PrevRoot: (kbfsmd.ID) 01f3673e3f7319129a102964f20a84f0312e224553af46e214fbea59cf7d40e63c,
  UnresolvedReaders: ([]keybase1.SocialAssertion) <nil>,
  RKeyBundleID: (kbfsmd.TLFReaderKeyBundleID) ,
  ConflictInfo: (*tlf.HandleExtension)(<nil>),
  FinalizedInfo: (*tlf.HandleExtension)(<nil>),
  KBMerkleRoot: (*keybase1.MerkleRootV2)({
    Seqno: (keybase1.Seqno) 4833931,
    HashMeta: (keybase1.HashMeta) (len=32) df15d6dbb2d177657c25b28fa792c240d33bcd434239a5caf01472b1f9a4a792
  }),
  UnknownFieldSetHandler: (codec.UnknownFieldSetHandler) {
    ufs: (codec.UnknownFieldSet) {
      fields: (map[string][]uint8) <nil>
    }
  }
})

Extra metadata
--------------
(interface {}) <nil>

Private metadata
----------------
Size: 0 bytes
(libkbfs.PrivateMetadata) {
  Dir: (libkbfs.DirEntry) BlockInfo{BlockPointer: BlockPointer{ID: 018556e3c0d99b2bd31a4eac697fb740a13c8585ef550694c93de7e143b64f6ab6, KeyGen: -1, DataVer: 1, Context: Context{Creator: 52f9121d5541251a4898f7f331c3a519}, DirectType: direct}, EncodedSize: 1081},
  TLFPrivateKey: (kbfscrypto.TLFPrivateKey) {private 32 bytes},
  Changes: (libkbfs.BlockChanges) {
    Info: (libkbfs.BlockInfo) BlockInfo{},
    Ops: (libkbfs.opsList) (len=1) {
      (libkbfs.verboseOp) gc 18284

    },
    sizeEstimate: (uint64) 0
  },
  LastGCRevision: (kbfsmd.Revision) 18284,
  UnknownFieldSetHandler: (codec.UnknownFieldSetHandler) {
    ufs: (codec.UnknownFieldSet) {
      fields: (map[string][]uint8) <nil>
    }
  },
  cachedChanges: (libkbfs.BlockChanges) {
    Info: (libkbfs.BlockInfo) BlockInfo{},
    Ops: (libkbfs.opsList) <nil>,
    sizeEstimate: (uint64) 0
  }
}
Putting revision 18285...
New MD has revision 18285

[strib]

Well the output is a bit messy, but it looks like it worked on my end. Let me know if you're still seeing these spikes outside of restarts. Thanks for sticking with us!

[lucymhdavies]

Thanks :)

[lucymhdavies]

Seems to be a lot better now 😄