search

keybase / client

Keybase Go Library, Client, Service, OS X, iOS, Android, Electron
BSD 3-Clause "New" or "Revised" License
8.91k stars 1.23k forks source link

High CPU and RAM usage when tracking with CLI & GUI #3050

Open morganestes opened 8 years ago

morganestes commented 8 years ago

Possibly related to #2896, when tracking another user from the CLI, the GUI opens a window just after the CLI prompts me with "Is this the you wanted? [Y/n]". I clicked the button in the GUI to track, and thought I was done.

I came back to my computer this morning to find kernal_task running at 150% CPU and > 1GB RAM, and the CLI repeating these lines (13 times in all):

▶ INFO Checking for update, current version is 1.0.16-20160606110015+a548d0e
▶ INFO Using updater source: Remote (https://s3.amazonaws.com/prerelease.keybase.io)
▶ INFO Request "https://s3.amazonaws.com/prerelease.keybase.io/update-darwin-prod.json"
▶ INFO Checking update with version: 1.0.16-20160606110015+a548d0e
▶ INFO Update matches current version: 1.0.16-20160606110015+a548d0e = 1.0.16-20160606110015+a548d0e

I discovered an additional tracking window open behind another window confirming that the tracking was successful, and after clicking the confirmation button, the CLI gave me this:

▶ ERROR Failed to get track token%!(EXTRA libkb.IdentifyTimeoutError=Identification expired.)

Since then, another group of the updater lines have appeared in the terminal. Canceling the CLI ops dropped CPU usage but the memory is still high. I grabbed a spindump, but forgot to grab a sample of the Keybase process before I quit the GUI.

Keybase GUI Version: 1.0.16-20160606110015+a548d0e OS X 10.11.5

image

chrisnojima commented 8 years ago

can you run keybase log send if you see this in the future

strib commented 8 years ago

A keybase log send now would still be very useful, assuming the logs didn't roll over yet.

morganestes commented 8 years ago

Just ran it, but now sure how successful it was...

WARNING error opening log "/Users/morganestes/Library/Logs/keybase.updater.log": open /Users/morganestes/Library/Logs/keybase.updater.log: no such file or directory

Just after that it said it was complete, and gave me a log ID of 5ee8dbe7bfc965f6c984511c.

strib commented 8 years ago

Thanks @morganestes, it worked! I don't see anything weird in the logs though that would explain high CPU usage. The kernel_task thing is pretty weird, hrm.

@patrickxb @maxtaco: can you think of anything weird that would happen if you click "Track" on the GUI popup, but leave the "[Y/n]" command line question unanswered? Are there any locks held there, or constant polling back to the GUI?

maxtaco commented 8 years ago

There aren't any locks held. There is a token that captures the art aye displayed to the user and on track, they token is cashed in. But definitely no busy waiting. Does the electron log show anything weird?

The track situation might also be unrelated.

On Friday, June 10, 2016, Jeremy Stribling notifications@github.com wrote:

Thanks @morganestes https://github.com/morganestes, it worked! I don't see anything weird in the logs though that would explain high CPU usage. The kernel_task thing is pretty weird, hrm.

@patrickxb https://github.com/patrickxb @maxtaco https://github.com/maxtaco: can you think of anything weird that would happen if you click "Track" on the GUI popup, but leave the "[Y/n]" command line question unanswered? Are there any locks held there, or constant polling back to the GUI?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/keybase/client/issues/3050#issuecomment-225261969, or mute the thread https://github.com/notifications/unsubscribe/AA05_wtqP0dAPdusVZole_yN7klgw5fOks5qKa7CgaJpZM4IzAMx .

cjb commented 8 years ago

Can't see how that would result in CPU use inside kernelspace, though.

morganestes commented 8 years ago

I haven't been able to reproduce this after restarting the GUI app. I've tried id-ing and tracking users, starting in the CLI and switching to GUI in the middle, but the only problem I had this time around was a single ▶ ERROR Tracking statement was stale when I clicked the track button in the GUI and finished answering the y/n questions in the CLI.

morganestes commented 8 years ago

I was able to trigger it again, and have it running in a terminal now.

Also in the other terminal window, a warning is thrown when manually checking to see if the updater is running:

$ keybase update check-in-use
▶ WARNING Continuing despite error in lsof: Error running /usr/sbin/lsof [-w -F pcuftn /keybase]: exit status 1 ()
{
  "in_use": false
}

Sent a new log 480e434541ee5489e910731c with more info.

gabriel commented 8 years ago

The error about missing keybase.updater.log can be ignored (it's used by the new updater which isn't live yet).

The keybase update check-in-use is a command run by the updater to see if /keybase is in use (calls lsof)... erroring isn't necessarily bad here, and can just mean that /keybase is not in use. lsof returning 0 means it is in use.

Lsof returns a one (1) if any error was detected, including the failure to locate command names, file names, Internet addresses or files, login names, NFS files, PIDs, PGIDs, or UIDs it was asked to list.

So I don't think it is updater related.

I also tried reproing this (leaving track UI up and running lsof), and wasn't able to (on a bleeding edge version).

gabriel commented 8 years ago

Unless calling lsof -w -F pcuftn /keybase while Fuse or KBFS is in a particular state is causing the issue.

gabriel commented 8 years ago

I tried to repro this using the new updater and wasn't able to. FWIW, my kernel_task is currently at 1.41GB and my other computer is 1.1GB so the mem usage doesn't seem that out of the ordinary.

The update check output being repeated does seem weird but not sure how that happening 13 times would cause 150% usage in kernel_task. The update check causes the v1 updater to trigger a check and there is log forwarding from the service, but it should exit after. Maybe it has something to do with log forwarding from the service to the client and something spinning in there?

I looked in the logs and I don't see anything strange (or something that seemed uncontrollably looping).

morganestes commented 8 years ago

The kernel_task may be an unrelated red herring; it just jumped out as unexpectedly high (it's at 911MB right now). I haven't seen the updating loop issue again, but if I do I'll try to get a process dump before I close it all down. Hopefully it was just a one-off problem with my local environment and not Keybase itself.