Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

quiescent zsh using pure occasionally jumps to 99% cpu usage #502

Open
2 tasks
skierpage opened this issue Oct 15, 2019 · 12 comments
Open
2 tasks

quiescent zsh using pure occasionally jumps to 99% cpu usage #502

skierpage opened this issue Oct 15, 2019 · 12 comments

Comments

@skierpage
Copy link

General information

  • Pure version: v1.8.0 ?
  • ZSH version: 5.7.1 (x86_64-redhat-linux-gnu)
  • Terminal program & version: Konsole 19.08.0
  • Operating system: Fedora 31 beta KDE spin
  • ZSH framework: uhh, none?

I have:

  • Tested with another terminal program and can reproduce the issue:
  • Followed the Integration instructions for my framework

Problem description

I run zsh as my default shell, and my terminal is Konsole with three tabs, one where I issue lots of commands and the other two mostly just showing output from programs I run (detached from the shell, they don't show up in jobs). I installed pure in September 2018, I think it was a bit after version 1.8.0. Several times in 2019 I notice in top and htop output that zsh is at 99% CPU. ps reveals the zsh at high usage is not in my active shell but one of these inactive ones. This high CPU is not turning the fan on so I'm usually not aware of it, and I'm not sure what triggers this high CPU mode. zsh is not in a git directory. I ran ltrace and noticed some

strlen("watcher")                                            = 7
strlen("watcher")                                            = 7
strcpy(0x7f2a04d7b690, "watcher")

output, and pure uses this string, hence this bug report.

I just updated pure to latest version and instructions (adding it to fpath). After source ~/.zshrc in the pty that was at high CPU, the issue persisted, I will see if this recurs in new shells.

Reproduction steps

Don't know yet. I've noticed the high CPU usage about 7 times.

I completely understand if you reject this bug report as unreproducible, Thanks for this nice software.

My .zshrc:

HISTFILE=~/.histfile
HISTSIZE=5000
SAVEHIST=5000
setopt appendhistory notify
bindkey -v

zstyle ':completion:*' completer _complete _ignored
zstyle :compinstall filename '/home/spage/.zshrc'

autoload -Uz compinit
compinit
zstyle ':completion:*' glob 1
zstyle ':completion:*' menu select=long-list select=0
zstyle ':completion:*' list-colors ${(s.:.)LS_COLORS}

limit coredumpsize 2048000

unsetopt hup # don't set HUP to jobs when exiting
bindkey -M viins '' history-incremental-search-backward
bindkey -M vicmd '' history-incremental-search-backward
bindkey -M viins '' beginning-of-line
bindkey -M vicmd '' beginning-of-line
bindkey -M viins '' end-of-line
bindkey -M vicmd '' end-of-line
bindkey '^W' vi-backward-kill-word

fpath+=("$HOME/dotfiles/pure")    ## I added this line just now
autoload -U promptinit; promptinit
prompt pure

export GPGKEY=blahblahblah
export VISUAL=/usr/bin/vim

alias grepr='grep --exclude-dir=.git --exclude-dir=.svn --exclude-dir=vendor --exclude-dir=node_modules'

settitle () {print -Pn "\e]2;${@}\a"}
alias st=settitle

longest () {
	MAX=0 IFS=
	while read -r line; do
		if [ ${#line} -gt $MAX ]; then MAX=${#line}; fi
	done
	echo $MAX
}

export PATH="$HOME/.cargo/bin:$PATH"
@skierpage
Copy link
Author

Several times in 2019 I notice in top and htop output that zsh is at 99% CPU. ps reveals the zsh at high usage is not in my active shell but one of these inactive ones.

It happened in my active shell today.

I will see if this recurs in new shells.

It does.

Here's are the most popular lines in ltrace:
3890 free(nil) =
1501 __errno_location() = 0x7f358ced1b00
1498 sigprocmask(0, <16>, <16,27>) = 0
1497 fflush(0x7f358d096420) = 0
1412 sigprocmask(SIG_BLOCK, <16>, <16,27>) = 0
1411 sigprocmask(0, <16>, <27>) = 0
1234 fflush(0x7f358d096500) = 0
1234 ferror(0x7f358d096500) = 0
1151 strlen("watcher") = 7
1144 strlen("prompt_pure") = 11
1144 strlen("local") = 5
968 strlen("prompt_pure_async_callback") = 26
533 strlen("_async_zle_watcher") = 18
528 strcpy(0x555e448a2e50, "local") = 0x555e448a2e50

zsh_at_99_cpu_ltrace.txt is a small chunk of ltrace output.

@mafredri
Copy link
Collaborator

Thanks for reporting and for the trace @skierpage, I've seen this myself a few times and have not had time to dig into the issue. I've chucked it up to the zpty implementation in zsh being a hack, but I'll try to see if the trace can provide any clues as to what's happening.

IIRC, it's the async worker (i.e. zpty clone from the current shell) that is causing 99% CPU, which could indicate for example that the fd has become corrupt and the read-loop in the worker just keeps on looping without reaching the exit state.

@ixil
Copy link

ixil commented Nov 20, 2019

I'm having a similar problem but with a git repo, using zsh -xv unfortunately. I couldn't copy output since the loop stops my tmux plugins' copying ability.

It does seem to be async launching a zpty and then it loops forever - although at one point it spat out a massive string of repeated unrelated git errors (git pack object is not a git object).
EDIT: I'll try out your indestructible branch, thanks for the beautiful prompt 👍
EDIT1: Sadly it still gets stuck spinning at 100%

@mafredri
Copy link
Collaborator

Thanks @ixil. If either of you are able to reproduce the issue semi-reliably, I'd be very interested to know if this: https://github.com/mafredri/zsh-async/blob/95c2b1577f455728ec01cec001a86c216d0af2bd/async.zsh#L155 is where we're failing. The thing I'm most curious about is if this loop keeps spinning without pause, causing the cpu usage. Perhaps the read is not returning an error, perhaps request is empty after read? Or perhaps it contains the value of the previous request.

@ixil
Copy link

ixil commented Nov 20, 2019

Attaching ltrace to an unresponsive zsh in a git repo I get the below:
Note this may be a different issue still to @skierpage.

sudo ltrace -p 18367
strlen("it/objects/pack/pack-182482f55bb"...)                    = 480575
strlen("t/objects/pack/pack-182482f55bba"...)                    = 480574
strlen("/objects/pack/pack-182482f55bbaf"...)                    = 480573
strlen("objects/pack/pack-182482f55bbafb"...)                    = 480572
...

Furthermore looking at a strace output which comes in longer (repeating blocks) that request keeps getting extended with values of the previous request

rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc06a8e5000
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc06a8e1000
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc06a8dd000
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
munmap(0x7fc06a8dd000, 16384)           = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
munmap(0x7fc06a8e1000, 16384)           = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
munmap(0x7fc06a8e5000, 16384)           = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
openat(AT_FDCWD, "/dev/null", O_WRONLY|O_CREAT|O_NOCTTY|O_TRUNC, 0666) = 3
fcntl(2, F_DUPFD, 10)                   = 12
close(2)                                = 0
dup2(3, 2)                              = 2
close(3)                                = 0
select(12, [11], NULL, NULL, {tv_sec=0, tv_usec=0}) = 0 (Timeout)
dup2(12, 2)                             = 2
close(12)                               = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
munmap(0x7fc06a8e9000, 16384)           = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
munmap(0x7fc06a8ed000, 16384)           = 0
rt_sigprocmask(SIG_UNBLOCK, [WINCH], [WINCH], 8) = 0
poll([{fd=10, events=POLLIN}, {fd=11, events=POLLIN}], 2, -1) = 1 ([{fd=11, revents=POLLIN}])
rt_sigprocmask(SIG_BLOCK, [WINCH], [], 8) = 0
mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc06a8ed000
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc06a8e9000
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [WINCH], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
openat(AT_FDCWD, "/dev/null", O_WRONLY|O_CREAT|O_NOCTTY|O_TRUNC, 0666) = 3
fcntl(2, F_DUPFD, 10)                   = 12
close(2)                                = 0
dup2(3, 2)                              = 2
close(3)                                = 0
select(12, [11], NULL, NULL, {tv_sec=0, tv_usec=0}) = 1 (in [11], left {tv_sec=0, tv_usec=0})
read(11, "\0", 1)                       = 1
select(12, [11], NULL, NULL, {tv_sec=0, tv_usec=0}) = 1 (in [11], left {tv_sec=0, tv_usec=0})
read(11, "p", 1)                        = 1
select(12, [11], NULL, NULL, {tv_sec=0, tv_usec=0}) = 1 (in [11], left {tv_sec=0, tv_usec=0})
read(11, "r", 1)                        = 1
select(12, [11], NULL, NULL, {tv_sec=0, tv_usec=0}) = 1 (in [11], left {tv_sec=0, tv_usec=0})
read(11, "o", 1)                        = 1
select(12, [11], NULL, NULL, {tv_sec=0, tv_usec=0}) = 1 (in [11], left {tv_sec=0, tv_usec=0})
read(11, "m", 1)                        = 1
select(12, [11], NULL, NULL, {tv_sec=0, tv_usec=0}) = 1 (in [11], left {tv_sec=0, tv_usec=0})
read(11, "p", 1)                        = 1
select(12, [11], NULL, NULL, {tv_sec=0, tv_usec=0}) = 1 (in [11], left {tv_sec=0, tv_usec=0})
read(11, "t", 1)                        = 1
select(12, [11], NULL, NULL, {tv_sec=0, tv_usec=0}) = 1 (in [11], left {tv_sec=0, tv_usec=0})
read(11, "_", 1)                        = 1
select(12, [11], NULL, NULL, {tv_sec=0, tv_usec=0}) = 1 (in [11], left {tv_sec=0, tv_usec=0})
read(11, "p", 1)                        = 1
select(12, [11], NULL, NULL, {tv_sec=0, tv_usec=0}) = 1 (in [11], left {tv_sec=0, tv_usec=0})
read(11, "u", 1)                        = 1
select(12, [11], NULL, NULL, {tv_sec=0, tv_usec=0}) = 1 (in [11], left {tv_sec=0, tv_usec=0})
read(11, "r", 1)                        = 1
select(12, [11], NULL, NULL, {tv_sec=0, tv_usec=0}) = 1 (in [11], left {tv_sec=0, tv_usec=0})
read(11, "e", 1)                        = 1
select(12, [11], NULL, NULL, {tv_sec=0, tv_usec=0}) = 1 (in [11], left {tv_sec=0, tv_usec=0})
read(11, "_", 1)                        = 1
select(12, [11], NULL, NULL, {tv_sec=0, tv_usec=0}) = 1 (in [11], left {tv_sec=0, tv_usec=0})
read(11, "a", 1)                        = 1
select(12, [11], NULL, NULL, {tv_sec=0, tv_usec=0}) = 1 (in [11], left {tv_sec=0, tv_usec=0})
read(11, "s", 1)                        = 1
select(12, [11], NULL, NULL, {tv_sec=0, tv_usec=0}) = 1 (in [11], left {tv_sec=0, tv_usec=0})
read(11, "y", 1)                        = 1
select(12, [11], NULL, NULL, {tv_sec=0, tv_usec=0}) = 1 (in [11], left {tv_sec=0, tv_usec=0})

@ixil
Copy link

ixil commented Nov 20, 2019

I suspect my problem is not related as manually git fetching my repo spewed several thousand lines and then tried to download the repo - I think the read loop to find the null byte may have just been slowing it down. As far as I could see the problem for me was in process_async_results Here I think... L274

pos=${ASYNC_PROCESS_BUFFER[$worker][(i)$null]}  # Get index of NULL-character (delimiter).

rather than in with your read statement (at least throwing echos everywhere made it look like that

@mafredri
Copy link
Collaborator

mafredri commented Nov 20, 2019

Oh, that’s different than what I had suspected at least. @ixil would changing >/dev/null to &>/dev/null on:

pure/pure.zsh

Line 320 in 2e354b8

command git -c gc.auto=0 fetch >/dev/null &

help your issue?

@skierpage
Copy link
Author

Attaching ltrace to an unresponsive zsh in a git repo I get the below:
Note this may be a different issue still to @skierpage.

sudo ltrace -p 18367
strlen("it/objects/pack/pack-182482f55bb"...)                    = 480575
strlen("t/objects/pack/pack-182482f55bba"...)                    = 480574
strlen("/objects/pack/pack-182482f55bbaf"...)                    = 480573
strlen("objects/pack/pack-182482f55bbafb"...)                    = 480572
...

The two ltrace()s I captured were nothing like that, no large repeating strlen() calls.

Furthermore looking at a strace output which comes in longer (repeating blocks) that request keeps getting extended with values of the previous request

lots of rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD WINCH], 8) = 0
followed by mmap mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc06a8e5000
followed by more rt_sigprocmask, then munmap, then an openat() ...

That is like an strace I captured, , except I didn't see your read()/select() part at the end.

@ixil
Copy link

ixil commented Nov 21, 2019

Oh, that’s different than what I had suspected at least. @ixil would changing >/dev/null to &>/dev/null on:

pure/pure.zsh

Line 320 in 2e354b8

command git -c gc.auto=0 fetch >/dev/null &

help your issue?

I suspect it would have, however I had already manually fixed the broken repo

mafredri added a commit that referenced this issue Dec 3, 2019
Only fetch information for the current branch to minimize the amount of
work Pure (well, git) needs to do.

This commit also starts redirecting git stderr to `/dev/null` because in
some cases git can start spewing errors like crazy (see #502). We also
never use the stderr so there's no point in keeping it around.

Fixes #473.
@romkatv
Copy link
Contributor

romkatv commented Dec 6, 2019

Perhaps it's this bug? Can anyone here check whether the issue reproduces after applying the linked patch? Here's how you can build zsh from HEAD on Debian-based Linux distro and install it as /usr/local/bin/zsh:

(
  emulate -L zsh
  setopt err_return
  sudo apt update
  sudo apt install -y git build-essential libncurses-dev gcc autoconf man yodl
  zsh_dir="$(mktemp -d)"
  {
    git clone https://github.com/zsh-users/zsh $zsh_dir
    cd $zsh_dir
    ./Util/preconfig
    ./configure
    sudo make -j 20 install
  } always {
    sudo rm -rf $zsh_dir
  }
)

(Your original zsh is still available as /bin/zsh.)

Add /usr/loca/bin/zsh to the list of login shells:

grep -qE '^/usr/local/bin/zsh$' /etc/shells || sudo tee -a /etc/shells <<</usr/local/bin/zsh >/dev/null

Make /usr/local/bin/zsh your login shell:

chsh -s /usr/local/bin/zsh

@lenormf
Copy link

lenormf commented Feb 16, 2024

I’m experiencing this issue, and the following did not mitigate it:

  • Running ZSH v5.9 (compiled locally), which includes this changeset

  • Apply the following patch locally, as recommended above:

    diff --git a/pure.zsh b/pure.zsh
    index 1e49d49..78cffd7 100644
    --- a/pure.zsh
    +++ b/pure.zsh
    @@ -408,7 +408,7 @@ prompt_pure_async_git_fetch() {
            log "prompt_pure_async_git_fetch: beginning fetch"
     
            # set GIT_TERMINAL_PROMPT=0 to disable auth prompting for git fetch (git 2.3+)
    -       GIT_TERMINAL_PROMPT=0 git -c gc.auto=0 fetch
    +       GIT_TERMINAL_PROMPT=0 git -c gc.auto=0 fetch &>/dev/null
     
            if (( !$? )); then
                    reply[fetch]=1
    

I suppose the root cause stems from an old version of a package, somewhere (I use Ubuntu Focal).

My system comes with Git v2.36.0, I will try upgrading that as well.

@lenormf
Copy link

lenormf commented Feb 19, 2024

Upgrading Git to version 2.43.2 did not address the issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants