keybase chat commands get slower and slower

[mortenkjarulff]

Attached script do:

while true ; do

  sleep 15

  keybase chat send ...

  ls /keybase/team/...

  echo '{"method": "read", ... | keybase chat api ...

  if 6 hours has gone
    run_keybase
  fi

done

After a while, chat send and chat read gets slower and slower, going from less that 1 second to more than 60 seconds.
sleep and ls times seems constant.
When 6 hours has gone and the run_keybase is executed, times get low again (but build up over the next 6 hours).

If I outcomment the ls command, all times are constant low.

These logs are from the same run, WITH the ls command:
a4f72ae29df5ba7e9a4c2a1c
0e3959537531bc60a74ac21c

These logs are from the same run, WITHOUT the ls command:
41c5342a84ccee599571831c
b7cc0500989c6a67920c0a1c

/Morten

[mortenkjarulff]

test.sh.txt

[strib]

@mortenkjarulff did you mean to file this in keybase/client? Chat is pretty much completely separate from kbfs at this point.

[mortenkjarulff]

Hi,

Appears not to be so separate 😀

Shall I file it there instead?

/Morten

[strib]

Oh, I guess I glossed over or didn't understand the line about "outcomment the ls".

Ok, here's what appears to be the issue. The team folder you're lsing has been written to by a device that has since been revoked. When you ls it, that triggers kbfs to attempt to "garbage-collect" the old data in it, by iterating through the old revisions of the folder. When it looks at the revisions that were written by the now-revoked device, it triggers a bunch of extra checking to verify that the device was valid at the time of the revision.

It looks like, in the case of this folder, the revisions by that revoked device are so expensive that they are slowing down chat.

Can you just ls that folder once, and maybe let the garbage collection run overnight and see if it finishes? You can tell if it made progress overnight by looking at the LastGCRevision field in the team folder's .kbfs_status file.

If it doesn't make any progress, even after many hours of work, I'll try to figure out a custom solution for you.

And obviously we need to figure out a way to reduce these extra checks without affecting security...

[mortenkjarulff]

Not sure I understand. I can reproduce at any time, even long time after I revoked.

I will manually ls now, and start the script tomorrow.

[strib]

We only garbage-collect data when it is at least two weeks old, but it could be longer depending on when your devices were online and when they accessed this particular folder. In your case the device was revoked on October 3rd, but it's trying to garbage-collect data written on September 29th.

[mortenkjarulff]

Ok, will try

Log after manual ls
a0cb1d208188c2886665501c

[mortenkjarulff]

LastGCRevision": 0,

Is that good?

[strib]

That means it has never been successfully garbage collected. If the team/folder is very old, this is surprising and might indicate some other bug.

[mortenkjarulff]

Timestamp on folder is October 8, that could well be the date I created the subteam

[strib]

Looks like it was created on September 20, so that lines up with the garbage collection and revocation messages I mentioned above.

[mortenkjarulff]

LastGCRevision": 0,
d46b49510feabaac7be4161c

If it can help

[strib]

Please just let it run for a long time uninterrupted.

[mortenkjarulff]

Still 0