"Once-a-day" long delay before startup

"Once-a-day" long delay before startup

[gi1242+zsh]

Hi All,

I notice that about every so often (at least once a day) when I open a
new shell, my hard disk spins for 15 secs or so before zsh starts. Of
course, most of the time it starts instantly.

Would anyone know what the problem is? I'm guessing it's from
reading/recreating the completion cache. However given that I've not
made changes to the completion system in a few months, I'm not sure why
I have the once-a-day performance penalty. One thing that might
contribute is that I usually run a nightly system update
(Debian/testing). However my performance penalty appears at random
times, seeming uncorrelated to when I run a system update.

Thanks,

GI

PS: Posted to zsh-users. Don't know if workers is more appropriate.

-- 
What's the difference between Michael Jackson and Casper?
One is pale and scares kids and the other is a friendly ghost.

Re: "Once-a-day" long delay before startup

[Vincent Lefevre]

On 2011-08-14 10:57:49 -0400, gi1242+zsh@gmail.com wrote:
> I notice that about every so often (at least once a day) when I open a
> new shell, my hard disk spins for 15 secs or so before zsh starts. Of
> course, most of the time it starts instantly.
> 
> Would anyone know what the problem is?
[...]

You can add

  [[ -o interactive ]] && echo 'zshenv...'

to your .zshenv file, and see if the hard disk spins before or after.
If after, you can add other similar messages to find what triggers the
problem.

I have a similar problem on my Mac OS X machine after doing a disk or
memory intensive operation (AFAIK), but I haven't had the time to look
at it yet. I wonder whether this comes from the code that builds the
command hash.

-- 
Vincent Lefèvre <vincent@vinc17.net> - Web: <http://www.vinc17.net/>
100% accessible validated (X)HTML - Blog: <http://www.vinc17.net/blog/>
Work: CR INRIA - computer arithmetic / Arénaire project (LIP, ENS-Lyon)

Re: "Once-a-day" long delay before startup

[Vincent Lefevre]

On 2011-08-14 17:36:05 +0200, Vincent Lefevre wrote:
> I have a similar problem on my Mac OS X machine after doing a disk or
> memory intensive operation (AFAIK), but I haven't had the time to look
> at it yet. I wonder whether this comes from the code that builds the
> command hash.

I had a "locale -a" for automatic locale detection and settings,
which could be very slow. I now avoid it, but zsh startup is still
a bit slow at the first command that is in a directory with more
than 2000 commands[*] (unless the data are in the disk cache).

So, I suggest anyone who sees intensive dist access to look at
such problems.

[*] Test done after a "svn st" in a large working copy.

-- 
Vincent Lefèvre <vincent@vinc17.net> - Web: <http://www.vinc17.net/>
100% accessible validated (X)HTML - Blog: <http://www.vinc17.net/blog/>
Work: CR INRIA - computer arithmetic / Arénaire project (LIP, ENS-Lyon)

Re: "Once-a-day" long delay before startup

[Bart Schaefer]

On Aug 14, 10:57am, gi1242+zsh@gmail.com wrote:
}
} I notice that about every so often (at least once a day) when I open a
} new shell, my hard disk spins for 15 secs or so before zsh starts.

Per Vincent's remarks, you should determine whether the delay comes
before zsh even begins reading its startup files, or sometime during.

} Would anyone know what the problem is? I'm guessing it's from
} reading/recreating the completion cache.

If by "the completion cache" you mean the ~/.zcompdump file, I'd say
that's unlikely to be related.  However, it could have to do with
building the command hash table (scanning the directories in $path),
particularly if you have run some sort of memory-intensive operation
that may have caused the kernel to flush out part of its filesystem
cache.  There are various setopts to encourage that scan to be done
incrementally, but if your startup files include external commands
that are found in directories toward the end of the search path, all
the preceding directories are likely to get scanned anyway.

You might try placing

    unsetopt hashcmds hashdirs hashlistall

at the beginning of ~/.zshenv and make sure you don't set any of those
nor correct and correctall until as late as possible in ~/.zshrc.  This
will help assure that the hash table is not rebuilt during startup file
processing (unless of course you're explicitly "rehash"ing somewhere)
and is never built during non-interactive scripts.

Of course if /etc/zshenv is doing something intensive that's not going
to help.

The hashlistall option mostly applies to compctl, not compsys, so you
can probably leave it unset.

Re: "Once-a-day" long delay before startup

[Piotr Karbowski]

Hi, I have pretty much the same issue, the first login after boot, to 
each user take about 8-9s.

In order to check whats going on I changed my login shell to bash and did:

zsh -x 2>&1 | tee zsh-startup.log

In order to save logs and I careful watch what pop up onto screen. I 
have reproduced it few times, what you need to reproduce is reboot 
system or drop_cache (echo 3 > /proc/sys/vm/drop_caches) and then again 
run zsh as user.

What I see in the log is lot of things, then last few lines *before* 
this big lag is:

+compaudit:59> [[ -n /usr/share/zsh/4.3.12/functions/Calendar ]]
+compaudit:60> [[ 668 -lt 20 || /usr/share/zsh/4.3.12/functions/Calendar 
== */Base || -d /usr/share/zsh/4.3.12/functions/Calendar/Base ]]
+compaudit:81> [[ ask == use ]]
+compaudit:89> local GROUP GROUPMEM _i_pw _i_gid _i_ulwdirs
+compaudit:90> (( UID == EUID  ))

after that it take about 7-8s of nothing and then:

+compaudit:91> getent group slashbeast
+compaudit:91> IFS=: +compaudit:91> read GROUP _i_pw _i_gid GROUPMEM
+compaudit:106> [[ '' == slashbeast ]]
+compaudit:110> _i_wdirs=( )
+compaudit:114> [[ -f /etc/debian_version ]]
+compaudit:120> _i_wdirs=( )
+compaudit:121> _i_wfiles=( )
+compaudit:123> case 0:0 (0:0)
+compaudit:124> _i_q=''
+compaudit:130> [[ -n '' ]]
+compaudit:137> return 0
+compinit:463> autoload -Uz compdump compinstall

Now I can re-start zsh and it will start in less than 1s. Until I drop 
cache, reboot or log as new user with zsh.

Also I have another system with exact the same zsh config, but there zsh 
start much quicker, 3-4s, which is really odd because the box with 
'slowest' zsh is many times better.

Anyone have idea whats going on?

-- Piotr

Re: "Once-a-day" long delay before startup

[gi1242+zsh]

[-- Attachment #1: Type: text/plain, Size: 2055 bytes --]

On Fri, Aug 19, 2011 at 12:08:16AM +0200, Piotr Karbowski wrote:

> Hi, I have pretty much the same issue, the first login after boot, to  
> each user take about 8-9s.
>
> In order to check whats going on I changed my login shell to bash and did:
>
> zsh -x 2>&1 | tee zsh-startup.log
>
> In order to save logs and I careful watch what pop up onto screen. I
> have reproduced it few times, what you need to reproduce is reboot
> system or drop_cache (echo 3 > /proc/sys/vm/drop_caches) and then
> again  run zsh as user.

That's a neat trick. It reproduces the behaviour for me every time.

It appears that building the command hash is the time consuming step.

Here's what I did:

    1. I created /tmp/.zshrc containing only

	    print -P "${ZSH_NAME}-${ZSH_VERSION} ($ZSH_PATCHLEVEL)"
	    which dircolors

    2. I executed the commands
    
	sudo echo 3 > /proc/sys/vm/drop_caches
	ZDOTDIR=/tmp zsh -xd 2>&1 | tee /tmp/zsh.log

I saw the output

	+/etc/zsh/zshenv:15> [[ -z .:/home/gautam/bin:/usr/lib/ccache:/usr/local/bin:/usr/bin:/bin:/usr/games || .:/home/gautam/bin:/usr/lib/ccache:/usr/local/bin:/usr/bin:/bin:/usr/games == /bin:/usr/bin ]]
	+/tmp/.zshrc:1> print -P 'zsh-4.3.12 (Debian)'
	zsh-4.3.12 (Debian)
	+/tmp/.zshrc:3> which dircolors
	/usr/bin/dircolors

Once "which dircolors" appears on screen, I see a long long long pause
(with the hard disk constantly spinning). After a long long long time, I
finally see the output (/usr/bin/dircolors) appear.

For comparison, I also executed the following

    sudo echo 3 > /proc/sys/vm/drop_caches
    sh
    which dircolors

"sh" started instantly, and which dircolors executed instantly. I also
checked that under the above conditions, the PATH in both sh and zsh
were identical.

I've no idea why "which dircolors" takes such a long time on zsh (when
the cache is cleared), and runs instantly on sh. I'd appreciate any
help.

Thanks,

GI

-- 
Freedom of speech is wonderful - right up there with the freedom not to
listen.

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

Re: "Once-a-day" long delay before startup

[Bart Schaefer]

On Aug 18, 10:03pm, gi1242+zsh@gmail.com wrote:
}
} I've no idea why "which dircolors" takes such a long time on zsh (when
} the cache is cleared), and runs instantly on sh. I'd appreciate any
} help.

sh doesn't do command hashing, it re-searches the path every time.

Refer to my earlier reply -- do as soon as possible during startup:

    unsetopt hashcmds hashdirs hashlistall

On my system "zsh -fc 'which ...'" takes about 40% as long with those
options unset as it does with them set.

Zsh is making the assumption that you'd prefer one big delay of a few
seconds at startup, to many tiny delays all the while the shell is
running.  However, zsh's default options were determined in a time
when path searching was slow and those "tiny" delays were a lot less
tiny.  Of course the tradeoff for getting your prompt sooner is that
you're going to have a delay the first time you attempt command
completion, because completion needs a filled hash table.

Re: "Once-a-day" long delay before startup

[Vincent Lefevre]

On 2011-08-18 21:05:58 -0700, Bart Schaefer wrote:
> Refer to my earlier reply -- do as soon as possible during startup:
> 
>     unsetopt hashcmds hashdirs hashlistall
> 
> On my system "zsh -fc 'which ...'" takes about 40% as long with those
> options unset as it does with them set.
> 
> Zsh is making the assumption that you'd prefer one big delay of a few
> seconds at startup, to many tiny delays all the while the shell is
> running.  However, zsh's default options were determined in a time
> when path searching was slow and those "tiny" delays were a lot less
> tiny.  Of course the tradeoff for getting your prompt sooner is that
> you're going to have a delay the first time you attempt command
> completion, because completion needs a filled hash table.

With HASH_DIRS, couldn't zsh fill the hash table only when the
directory is accessed? For instance, one may have remote directories,
for which the NFS server is sometimes down, near the end of the path.
So, when executing usual commands, the shell would not be affected by
problems with the NFS server.

Now, if zsh could fill the hash tables in background, this would be
even better.

-- 
Vincent Lefèvre <vincent@vinc17.net> - Web: <http://www.vinc17.net/>
100% accessible validated (X)HTML - Blog: <http://www.vinc17.net/blog/>
Work: CR INRIA - computer arithmetic / Arénaire project (LIP, ENS-Lyon)

Re: "Once-a-day" long delay before startup

[Bart Schaefer]

On Aug 19, 10:36am, Vincent Lefevre wrote:
} Subject: Re: "Once-a-day" long delay before startup
}
} That can be annoying. But I don't really understand. What if none
} of the concerned directories are group-writable? I suppose that
} getent should be useless. Why not calling it only when needed?

The test is written to find the directories that are both writable
and owned by the user/group in a single glob pass.  It comes down
to predicting whether two globs are slower than one getent, which
isn't practical.  But the test could be rewritten.

On Aug 19, 11:08am, Vincent Lefevre wrote:
}
} With HASH_DIRS, couldn't zsh fill the hash table only when the
} directory is accessed?

Yes, that is what it does, except during completion when it fills
the whole thing so as not to miss some possible completions.  But
whether incremental filling is any faster depends on the order of
the path and where the command is found in it.

Again the optimization chosen years ago was for commands you have
yet to use; a better one nowadays might be to assume command use is
mostly repetitive and only store individual commands as they are
found.  Except, again, for the completion issue, which usually makes
all of this discussion moot.

} Now, if zsh could fill the hash tables in background, this would be
} even better.

That could require completely rewriting the way the shell interacts
with the user for I/O -- I'm not even sure it's possible to maintain
POSIX compliance and do that.  Shells generally don't support shared
memory multithreading, and you'd still have to wait for the table to
be completely filled when completion begins, so you need a sempahore
as well.

However, it might be possible to *cache* the hash table in a manner
similar to the way completion caches work.

Re: "Once-a-day" long delay before startup

[gi1242+zsh]

On Thu, Aug 18, 2011 at 09:05:58PM -0700, Bart Schaefer wrote:

> }
> } I've no idea why "which dircolors" takes such a long time on zsh (when
> } the cache is cleared), and runs instantly on sh. I'd appreciate any
> } help.
> 
> sh doesn't do command hashing, it re-searches the path every time.
> 
> Refer to my earlier reply -- do as soon as possible during startup:
> 
>     unsetopt hashcmds hashdirs hashlistall
> 
> On my system "zsh -fc 'which ...'" takes about 40% as long with those
> options unset as it does with them set.

Indeed. Even with

    unsetopt hashcmds hashdirs

zsh starts quickly. I'm not sure how this problem can be solved (if at
all).

GI

-- 
Freedom of speech is wonderful - right up there with the freedom not to
listen.

Re: "Once-a-day" long delay before startup

[Bart Schaefer]

On Aug 19,  8:47pm, gi1242+zsh@gmail.com wrote:
} Subject: Re: "Once-a-day" long delay before startup
}
} On Thu, Aug 18, 2011 at 09:05:58PM -0700, Bart Schaefer wrote:
} 
} > Refer to my earlier reply -- do as soon as possible during startup:
} > 
} >     unsetopt hashcmds hashdirs hashlistall
} 
} Indeed. Even with
} 
}     unsetopt hashcmds hashdirs
} 
} zsh starts quickly.

Yes, as I mentioned, hashlistall really only applies later, but there
is no point in leaving it set if the other two are unset.

} I'm not sure how this problem can be solved (if at all).

Why is the above not a solution?

I suppose you mean a solution that doesn't require you to change your
zshenv configuration.  One possibility is that we could declare the
hashcmds and hashdirs options to be obsolete, and no longer have them
on by default.  (I doubt they're necessary for non-interactive shells
in any event.)  Meanwhile ...

Here's a crude pass at a function set for caching the hash table.  It
writes the current value of $PATH as the first line of the file and
reads back that line to determine whether the file matches the path
in the current shell.  The store function fills the cache and writes
the file all in the background.  Improvements are possible.

emulate -R zsh -c '#
cachehash_valid() {
  local _typeset cachepath
  [[ -n $cachefile && -O $cachefile &&
     -r $cachefile && ! -w $cachefile ]] &&
  IFS="=" read _typeset cachepath < $cachefile &&
  [[ $cachepath == $PATH ]]
}
cachehash_store() {
  local cachefile=${ZDOTDIR:-$HOME}/.zcachehash
  { hash -f && umask 0277 &&
    { typeset -p PATH
      print "hash -r"
      hash -L } >| $cachefile-$$ &&
    command mv -f $cachefile-$$ $cachefile } &!
}
cachehash_load() {
  local cachefile=${ZDOTDIR:-$HOME}/.zcachehash
  cachehash_valid && source $cachefile
}
#'

Also, I just invented that idiom of '# ... #' for wrapping the argument
of "emulate zsh -c ..." but it seems like a good way to make obvious
the presence of the quotes.

-- 
Barton E. Schaefer

Re: "Once-a-day" long delay before startup

[Bart Schaefer]

On Aug 19, 12:08am, Piotr Karbowski wrote:
}
} +compaudit:90> (( UID == EUID  ))
} 
} after that it take about 7-8s of nothing and then:
} 
} +compaudit:91> getent group slashbeast

The compaudit script wants to check that you haven't allowed someone
else to feed autoloadable functions to your shell, which would be a
large security risk.

The getent call is used to read the system's groups database for the
groups of your login user, so that the shell can then check whether
other persons in that group might have write access to your fpath.
(There is an assumption that getent is in /usr/bin, so if it's not
there the check relies on the local /etc/group file.)

If you're in an environment (such as, say, a university or a large
corporation) where the groups database is networked and may contain
hundreds or even thousands of entries, that "getent" call can take a
very long time.

After one reading, though, your system has cached the database and
until the cache expires or is flushed subsequent calls to "getent"
return almost instantly.

You can skip this security check by using "compinit -u" when you
load the completion system.

Re: "Once-a-day" long delay before startup

[Vincent Lefevre]

On 2011-08-18 20:52:36 -0700, Bart Schaefer wrote:
> The getent call is used to read the system's groups database for the
> groups of your login user, so that the shell can then check whether
> other persons in that group might have write access to your fpath.
> (There is an assumption that getent is in /usr/bin, so if it's not
> there the check relies on the local /etc/group file.)
> 
> If you're in an environment (such as, say, a university or a large
> corporation) where the groups database is networked and may contain
> hundreds or even thousands of entries, that "getent" call can take a
> very long time.

That can be annoying. But I don't really understand. What if none
of the concerned directories are group-writable? I suppose that
getent should be useless. Why not calling it only when needed?

-- 
Vincent Lefèvre <vincent@vinc17.net> - Web: <http://www.vinc17.net/>
100% accessible validated (X)HTML - Blog: <http://www.vinc17.net/blog/>
Work: CR INRIA - computer arithmetic / Arénaire project (LIP, ENS-Lyon)

Re: "Once-a-day" long delay before startup

[Piotr Karbowski]

On 19.08.2011 05:52, Bart Schaefer wrote:
 > On Aug 19, 12:08am, Piotr Karbowski wrote:
 > }
 > } +compaudit:90>  (( UID == EUID  ))
 > }
 > } after that it take about 7-8s of nothing and then:
 > }
 > } +compaudit:91>  getent group slashbeast
 >
 > The compaudit script wants to check that you haven't allowed someone
 > else to feed autoloadable functions to your shell, which would be a
 > large security risk.
 >
 > The getent call is used to read the system's groups database for the
 > groups of your login user, so that the shell can then check whether
 > other persons in that group might have write access to your fpath.
 > (There is an assumption that getent is in /usr/bin, so if it's not
 > there the check relies on the local /etc/group file.)
 >
 > If you're in an environment (such as, say, a university or a large
 > corporation) where the groups database is networked and may contain
 > hundreds or even thousands of entries, that "getent" call can take a
 > very long time.
 >
 > After one reading, though, your system has cached the database and
 > until the cache expires or is flushed subsequent calls to "getent"
 > return almost instantly.
 >
 > You can skip this security check by using "compinit -u" when you
 > load the completion system.
 >

Thats is not the case I think. I have had did what gi1241 did to test it 
and even without this 'gentent' I am getting this lag just before 
dircolors is executed.

% ZDOTDIR=/tmp zsh -xd 2>&1 | tee /tmp/zsh.log
+/tmp/.zshrc:1> print -P 'zsh-4.3.12 (1.5346)'
zsh-4.3.12 (1.5346)
+/tmp/.zshrc:2> which dircolors
### lag starts here.
/usr/bin/dircolors

-- Piotr.