#770905 assistant keeps CPU 100% busy

Package:
git-annex
Source:
git-annex
Description:
manage files with git, without checking their contents into git
Submitter:
Date:
2014-11-25 23:21:33 UTC
Severity:
normal
#770905#5
Date:
2014-11-25 02:48:18 UTC
From:
To:
I know that the version I have is outdated but it is not a regularly occuring
issue, so decided to investigate/report instead of just
kill/upgrade/restart.  I have noted busy fan of the laptop, and saw that

31825 yoh       20   0  678276  53756  37872 S 103.7  0.3  57:26.39 git-annex

which monitors few (two) annex repositories is way too busy.

log file $HOME/annex/.git/annex/daemon.log is not growing with last entry about
inability to connect to remote box:

ssh: connect to host xxx.yyy.dartmouth.edu port 22: Connection timed out
fatal: Could not read from remote repository.

Please make sure you have the correct access rights
and the repository exists.

following files are open:

hopa:/proc/31825/fd
$> ls -l
total 0
lr-x------ 1 yoh yoh 64 Nov 24 08:58 0 -> /dev/null
l-wx------ 1 yoh yoh 64 Nov 24 08:58 1 -> /home/yoh/annex/.git/annex/daemon.log
lr-x------ 1 yoh yoh 64 Nov 24 08:58 10 -> anon_inode:inotify
lr-x------ 1 yoh yoh 64 Nov 24 08:58 11 -> /dev/null
lrwx------ 1 yoh yoh 64 Nov 24 21:31 12 -> socket:[1407919]
l-wx------ 1 yoh yoh 64 Nov 24 08:58 13 -> pipe:[981286]
lrwx------ 1 yoh yoh 64 Nov 24 08:58 14 -> socket:[979402]
lrwx------ 1 yoh yoh 64 Nov 24 08:58 15 -> /home/yoh/annex/.git/annex/daemon.pid
l-wx------ 1 yoh yoh 64 Nov 24 08:58 16 -> pipe:[981054]
lr-x------ 1 yoh yoh 64 Nov 24 08:58 17 -> pipe:[981055]
lrwx------ 1 yoh yoh 64 Nov 24 21:31 18 -> socket:[1411137]
lr-x------ 1 yoh yoh 64 Nov 24 08:58 19 -> anon_inode:inotify
l-wx------ 1 yoh yoh 64 Nov 24 08:58 2 -> /home/yoh/annex/.git/annex/daemon.log
lr-x------ 1 yoh yoh 64 Nov 24 08:58 20 -> anon_inode:inotify
lrwx------ 1 yoh yoh 64 Nov 24 08:58 21 -> socket:[981220]
l-wx------ 1 yoh yoh 64 Nov 24 08:58 22 -> pipe:[981218]
lr-x------ 1 yoh yoh 64 Nov 24 08:58 23 -> pipe:[981219]
lrwx------ 1 yoh yoh 64 Nov 24 08:58 24 -> socket:[981221]
lr-x------ 1 yoh yoh 64 Nov 24 08:58 25 -> anon_inode:inotify
lr-x------ 1 yoh yoh 64 Nov 24 08:58 26 -> pipe:[981287]
l-wx------ 1 yoh yoh 64 Nov 24 08:58 27 -> pipe:[980836]
lr-x------ 1 yoh yoh 64 Nov 24 08:58 28 -> pipe:[980837]
lr-x------ 1 yoh yoh 64 Nov 24 08:58 3 -> /dev/urandom
lrwx------ 1 yoh yoh 64 Nov 24 08:58 4 -> anon_inode:[eventpoll]
lr-x------ 1 yoh yoh 64 Nov 24 08:58 5 -> pipe:[978406]
l-wx------ 1 yoh yoh 64 Nov 24 08:58 6 -> pipe:[978406]
lrwx------ 1 yoh yoh 64 Nov 24 08:58 7 -> anon_inode:[eventfd]
lr-x------ 1 yoh yoh 64 Nov 24 08:58 8 -> /home/yoh/.config/git-annex/autostart
lrwx------ 1 yoh yoh 64 Nov 24 08:58 9 -> socket:[979773]


and according to strace

Process 31825 attached with 7 threads
[pid 10521] futex(0x7fa65000091c, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...>
[pid 32172] futex(0x7fa65c00698c, FUTEX_WAIT_PRIVATE, 11, NULL <unfinished ...>
[pid 31848] futex(0x7fa65800091c, FUTEX_WAIT_PRIVATE, 3023, NULL <unfinished ...>
[pid 31829] futex(0x445e59c, FUTEX_WAIT_PRIVATE, 262485, NULL <unfinished ...>
[pid 31828] futex(0x445e38c, FUTEX_WAIT_PRIVATE, 304773, NULL <unfinished ...>
[pid 31825] futex(0x445e26c, FUTEX_WAIT_PRIVATE, 45, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 31825] --- SIGVTALRM {si_signo=SIGVTALRM, si_code=SI_TIMER, si_timerid=0, si_overrun=0, si_value={int=0, ptr=0}} ---
[pid 31825] rt_sigreturn( <unfinished ...>
[pid 31838] futex(0x445e59c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x445e598, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...>
[pid 31825] <... rt_sigreturn resumed> ) = 202
[pid 31838] <... futex resumed> )       = 1
[pid 31829] <... futex resumed> )       = 0
[pid 31838] futex(0x7fa6600009dc, FUTEX_WAIT_PRIVATE, 181307, NULL <unfinished ...>
[pid 31829] futex(0x445e5c8, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 31825] futex(0x445e26c, FUTEX_WAIT_PRIVATE, 45, NULL <unfinished ...>
[pid 31829] <... futex resumed> )       = 0
[pid 31825] <... futex resumed> )       = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 31825] --- SIGVTALRM {si_signo=SIGVTALRM, si_code=SI_TIMER, si_timerid=0, si_overrun=0, si_value={int=0, ptr=0}} ---
[pid 31825] rt_sigreturn()              = 202
[pid 31825] futex(0x445e26c, FUTEX_WAIT_PRIVATE, 45, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 31825] --- SIGVTALRM {si_signo=SIGVTALRM, si_code=SI_TIMER, si_timerid=0, si_overrun=0, si_value={int=0, ptr=0}} ---
[pid 31825] rt_sigreturn( <unfinished ...>
[pid 31829] futex(0x7fa6600009dc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7fa6600009d8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...>
[pid 31825] <... rt_sigreturn resumed> ) = 202
[pid 31829] <... futex resumed> )       = 1
[pid 31825] futex(0x445e26c, FUTEX_WAIT_PRIVATE, 45, NULL <unfinished ...>
[pid 31829] futex(0x445e59c, FUTEX_WAIT_PRIVATE, 262487, NULL <unfinished ...>
[pid 31838] <... futex resumed> )       = 0
[pid 31838] futex(0x7fa660000a08, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 31825] <... futex resumed> )       = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 31825] --- SIGVTALRM {si_signo=SIGVTALRM, si_code=SI_TIMER, si_timerid=0, si_overrun=0, si_value={int=0, ptr=0}} ---
[pid 31825] rt_sigreturn()              = 202
[pid 31825] futex(0x445e26c, FUTEX_WAIT_PRIVATE, 45, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 31825] --- SIGVTALRM {si_signo=SIGVTALRM, si_code=SI_TIMER, si_timerid=0, si_overrun=0, si_value={int=0, ptr=0}} ---
[pid 31838] futex(0x445e59c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x445e598, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...>
[pid 31825] rt_sigreturn( <unfinished ...>
[pid 31838] <... futex resumed> )       = 1
[pid 31829] <... futex resumed> )       = 0
[pid 31838] futex(0x7fa6600009dc, FUTEX_WAIT_PRIVATE, 181309, NULL <unfinished ...>
[pid 31829] futex(0x445e5c8, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 31825] <... rt_sigreturn resumed> ) = 202
[pid 31829] <... futex resumed> )       = 0
[pid 31825] futex(0x445e26c, FUTEX_WAIT_PRIVATE, 45, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 31825] --- SIGVTALRM {si_signo=SIGVTALRM, si_code=SI_TIMER, si_timerid=0, si_overrun=0, si_value={int=0, ptr=0}} ---
[pid 31825] rt_sigreturn()              = 202
[pid 31825] futex(0x445e26c, FUTEX_WAIT_PRIVATE, 45, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 31825] --- SIGVTALRM {si_signo=SIGVTALRM, si_code=SI_TIMER, si_timerid=0, si_overrun=0, si_value={int=0, ptr=0}} ---
[pid 31829] futex(0x7fa6600009dc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7fa6600009d8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...>
[pid 31825] rt_sigreturn( <unfinished ...>
[pid 31829] <... futex resumed> )       = 1
[pid 31838] <... futex resumed> )       = 0
[pid 31829] futex(0x445e59c, FUTEX_WAIT_PRIVATE, 262489, NULL <unfinished ...>
[pid 31838] futex(0x7fa660000a08, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 31825] <... rt_sigreturn resumed> ) = 202
[pid 31838] <... futex resumed> )       = 0
[pid 31825] futex(0x445e26c, FUTEX_WAIT_PRIVATE, 45, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 31825] --- SIGVTALRM {si_signo=SIGVTALRM, si_code=SI_TIMER, si_timerid=0, si_overrun=0, si_value={int=0, ptr=0}} ---
[pid 31825] rt_sigreturn()              = 202
[pid 31825] futex(0x445e26c, FUTEX_WAIT_PRIVATE, 45, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 31825] --- SIGVTALRM {si_signo=SIGVTALRM, si_code=SI_TIMER, si_timerid=0, si_overrun=0, si_value={int=0, ptr=0}} ---
[pid 31838] futex(0x445e59c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x445e598, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...>
[pid 31825] rt_sigreturn( <unfinished ...>
[pid 31838] <... futex resumed> )       = 1
[pid 31829] <... futex resumed> )       = 0
[pid 31838] futex(0x7fa6600009dc, FUTEX_WAIT_PRIVATE, 181311, NULL <unfinished ...>
[pid 31829] futex(0x445e5c8, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 31825] <... rt_sigreturn resumed> ) = 202
[pid 31829] <... futex resumed> )       = 0
[pid 31825] futex(0x445e26c, FUTEX_WAIT_PRIVATE, 45, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 31825] --- SIGVTALRM {si_signo=SIGVTALRM, si_code=SI_TIMER, si_timerid=0, si_overrun=0, si_value={int=0, ptr=0}} ---
[pid 31825] rt_sigreturn()              = 202
[pid 31825] futex(0x445e26c, FUTEX_WAIT_PRIVATE, 45, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 31825] --- SIGVTALRM {si_signo=SIGVTALRM, si_code=SI_TIMER, si_timerid=0, si_overrun=0, si_value={int=0, ptr=0}} ---
[pid 31829] futex(0x7fa6600009dc, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7fa6600009d8, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...>
[pid 31825] rt_sigreturn( <unfinished ...>
[pid 31838] <... futex resumed> )       = 0
[pid 31829] <... futex resumed> )       = 1
[pid 31838] futex(0x7fa660000a08, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 31829] futex(0x7fa660000a08, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 31838] <... futex resumed> )       = -1 EAGAIN (Resource temporarily unavailable)
[pid 31829] <... futex resumed> )       = 0
[pid 31838] futex(0x7fa660000a08, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 31829] futex(0x445e59c, FUTEX_WAIT_PRIVATE, 262491, NULL <unfinished ...>
[pid 31838] <... futex resumed> )       = 0
[pid 31825] <... rt_sigreturn resumed> ) = 202
[pid 31825] futex(0x445e26c, FUTEX_WAIT_PRIVATE, 45, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 31825] --- SIGVTALRM {si_signo=SIGVTALRM, si_code=SI_TIMER, si_timerid=0, si_overrun=0, si_value={int=0, ptr=0}} ---
[pid 31825] rt_sigreturn()              = 202
[pid 31825] futex(0x445e26c, FUTEX_WAIT_PRIVATE, 45, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 31825] --- SIGVTALRM {si_signo=SIGVTALRM, si_code=SI_TIMER, si_timerid=0, si_overrun=0, si_value={int=0, ptr=0}} ---
[pid 31838] futex(0x445e59c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x445e598, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...>
[pid 31825] rt_sigreturn( <unfinished ...>
[pid 31838] <... futex resumed> )       = 1
[pid 31829] <... futex resumed> )       = 0
[pid 31838] futex(0x7fa6600009dc, FUTEX_WAIT_PRIVATE, 181313, NULL <unfinished ...>
[pid 31829] futex(0x445e5c8, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 31825] <... rt_sigreturn resumed> ) = 202
[pid 31829] <... futex resumed> )       = 0
[pid 31825] futex(0x445e26c, FUTEX_WAIT_PRIVATE, 45, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)



git annex webapp   causes browser to start but there it is stuck at "Starting webapp..."

here are annexes running (besides reportbug git-annex ;) )

$> ps auxw -H | grep -1 '[ ]git-annex'
yoh       1566  0.0  0.0  21132  3684 ?        S    Nov11   0:00   git --git-dir=/home/yoh/annex/.git --work-tree=/home/yoh/annex cat-file --batch
yoh       1578  0.0  0.0 292812  6412 ?        S    Nov11   0:00   git-annex assistant --startdelay=5s
yoh       1608  0.1  0.2 519176 43204 ?        Sl   Nov11  33:01   git-annex assistant --startdelay=5s
yoh       1619  0.0  0.0  22172  4060 ?        S    Nov11   0:00     git --git-dir=/home/yoh/deb/tarballs/.git --work-tree=/home/yoh/deb/tarballs cat-file --batch
yoh       1696  0.0  0.1 444396 18328 ?        SNl  Nov11   0:00     git-annex remotedaemon
yoh       1727  0.0  0.0  21128  3536 ?        S    Nov11   0:00     git --git-dir=/home/yoh/deb/tarballs/.git --work-tree=/home/yoh/deb/tarballs check-ignore -z --stdin --verbose --non-matching
--
yoh      31823  0.0  0.5 2074452 91832 ?       Ssl  Nov18   0:28   /home/yoh/.dropbox-dist/dropbox-lnx.x86_64-2.10.52/dropbox
yoh      31825  0.7  0.3 678276 53756 ?        Sl   Nov18  65:38   git-annex assistant --startdelay=5s
yoh      31865  0.0  0.0  21188  3700 ?        S    Nov18   0:00     git --git-dir=/home/yoh/annex/.git --work-tree=/home/yoh/annex cat-file --batch
yoh      32022  0.0  0.1 519152 20720 ?        SNl  Nov18   0:00     git-annex remotedaemon
yoh      32171  0.0  0.0  27248  5348 ?        SN   Nov18   0:00       git --git-dir=/home/yoh/annex/.git --work-tree=/home/yoh/annex cat-file --batch


I have killed 31825  and then started webapp succesfully which insists that the
beast is " Syncing with xxx.yyy.dartmouth.edu_annex, onerussian.com_annex"
(even if I "Shutdown daemon").  anyway -- CPU is now not 100% loaded so it must
be "ok".

FWIW that xxx.yyy.dartmouth.edu_annex  is not reachable atm at all (need
to bring that poor sparc up again manually tomorrow).
#770905#10
Date:
2014-11-25 21:47:10 UTC
From:
To:
You were asking about the assistant's monitoring of /usr/bin/git-annex
and auto-restarting on change at around this time. Do you think that
could be related? How is annex.autoupgrade configured?

This would kind of suggest the whole process is in a bad state, if its
web serving thread isn't replying.

This is unusual, because the assistant only has 2 functions that open this
file; one writes a new repository to it, and one reads it at program
start time and should not keep it open for long, and doesn't seem to in
my tests.
#770905#15
Date:
2014-11-25 23:20:17 UTC
From:
To:
I have upgraded only after I have detected this high cpu load,
troubleshooted, and restarted... so -- unlikely

nohow specifically, "git config annex.autoupgrade" returns nothing

at least here it seems to be consistent for me:

$> ps auxw | grep 'git[-]annex'
yoh       1977  0.1  0.3 604328 51720 ?        Sl   11:13   0:33 git-annex assistant --startdelay=5s
yoh       2016  0.1  0.2 446436 45568 ?        Sl   11:13   0:30 git-annex assistant --startdelay=5s
yoh       2099  0.0  0.1 444364 19072 ?        SNl  11:13   0:00 git-annex remotedaemon
yoh       2100  0.0  0.1 519120 20088 ?        SNl  11:13   0:00 git-annex remotedaemon

$> lsof | grep autostart
git-annex 1977             yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 1977 1979        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 1977 1980        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 1977 1981        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 1977 1983        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 1977 2209        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 1977 3655        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git       1993             yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 2016             yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 2016 2017        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 2016 2018        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 2016 2019        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 2016 2021        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git       2025             yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 2099             yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 2099 2101        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 2099 2102        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 2099 2110        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 2099 3002        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 2100             yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 2100 2105        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 2100 2106        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 2100 2112        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 2100 2390        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git-annex 2100 3795        yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git       2175             yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git       2192             yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git       2368             yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git       2616             yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart
git       2622             yoh    8r      REG              254,1        39    3546553 /home/yoh/.config/git-annex/autostart

if anyhow matters, no heavy cpu atm, and the last message webapp reports
for one of the repos is "Failed to sync with ..."