ls and cd very slow in new terminal
On my Ubuntu 20.04 system I start a Gnome Terminal app. This starts bash. In that fresh instance of bash I run ls or cd ... And something blocks for multiple seconds before the program runs. I would like to know what and why, and how to debug this better.
It happens almost always the first time. After the first time in new Terminal/bash instance it works well for the same command. But another command in another directory can again be slow.
I have run perf trace on the bash process when this happens, just for running ls in my home directory. This is the output:
? ( ): ... [continued]: pselect6()) = 1 0.019 ( 0.007 ms): read(buf: 0x7ffdb676be1f, count: 1) = 1 0.034 ( 0.005 ms): select(n: 1, inp: 0x7ffdb676bd40, exp: 0x7ffdb676bdc0, tvp: 0x7ffdb676bd30) = 0 (Timeout) 0.053 ( 0.008 ms): write(fd: 2</dev/pts/1>, buf: 0x55ec925b5bd0, count: 1) = 1 0.065 (117.862 ms): pselect6(n: 1, inp: 0x7ffdb676be20, sig: 0x7ffdb676bde0) = 1 117.944 ( 0.007 ms): read(buf: 0x7ffdb676be1f, count: 1) = 1 117.959 ( 0.004 ms): select(n: 1, inp: 0x7ffdb676bd40, exp: 0x7ffdb676bdc0, tvp: 0x7ffdb676bd30) = 0 (Timeout) 117.978 ( 0.006 ms): write(fd: 2</dev/pts/1>, buf: 0x55ec925b5bd0, count: 1) = 1 117.987 (565.240 ms): pselect6(n: 1, inp: 0x7ffdb676be20, sig: 0x7ffdb676bde0) = 1 683.246 ( 0.007 ms): read(buf: 0x7ffdb676be1f, count: 1) = 1 683.260 ( 0.008 ms): write(fd: 2</dev/pts/1>, buf: 0x55ec925b5bd0, count: 1) = 1 686.274 ( 0.022 ms): ioctl(cmd: TCGETS, arg: 0x7ffdb676bea0) = 0 686.299 ( 0.005 ms): ioctl(cmd: TCSETSW, arg: 0x7ffdb676be70) = 0 686.306 ( 0.002 ms): ioctl(cmd: TCGETS, arg: 0x7ffdb676be70) = 0 686.312 ( 0.003 ms): rt_sigaction(sig: INT, act: 0x7ffdb676bc50, oact: 0x7ffdb676bcf0, sigsetsize: 8) = 0 686.317 ( 0.002 ms): rt_sigaction(sig: TERM, act: 0x7ffdb676bc50, oact: 0x7ffdb676bcf0, sigsetsize: 8) = 0 686.322 ( 0.002 ms): rt_sigaction(sig: HUP, act: 0x7ffdb676bc50, oact: 0x7ffdb676bcf0, sigsetsize: 8) = 0 686.327 ( 0.002 ms): rt_sigaction(sig: ALRM, act: 0x7ffdb676bc50, oact: 0x7ffdb676bcf0, sigsetsize: 8) = 0 686.332 ( 0.002 ms): rt_sigaction(sig: WINCH, act: 0x7ffdb676bd10, oact: 0x7ffdb676bdb0, sigsetsize: 8) = 0 686.337 ( 0.003 ms): rt_sigaction(sig: INT, act: 0x7ffdb676bc70, oact: 0x7ffdb676bd10, sigsetsize: 8) = 0 19783.751 ( 0.010 ms): stat(filename: 0x8e1ab3b3, statbuf: 0x7ffdb676cc60) = 0 19783.764 ( 0.004 ms): stat(filename: 0x925961a0, statbuf: 0x7ffdb676cb50) = -1 ENOENT (No such file or directory) 19783.769 ( 0.001 ms): stat(filename: 0x8fc536f0, statbuf: 0x7ffdb676cb50) = -1 ENOENT (No such file or directory) 19783.771 ( 0.001 ms): stat(filename: 0x925961d0, statbuf: 0x7ffdb676cb50) = -1 ENOENT (No such file or directory) 19783.774 ( 0.002 ms): stat(filename: 0x8fc536f0, statbuf: 0x7ffdb676cb50) = -1 ENOENT (No such file or directory) 19783.777 ( 0.002 ms): stat(filename: 0x8fc536f0, statbuf: 0x7ffdb676cb50) = -1 ENOENT (No such file or directory) 19783.780 ( 0.002 ms): stat(filename: 0x8fc536f0, statbuf: 0x7ffdb676cb50) = -1 ENOENT (No such file or directory) 19783.782 ( 0.002 ms): stat(filename: 0x8fc536f0, statbuf: 0x7ffdb676cb50) = -1 ENOENT (No such file or directory) 19783.785 ( 0.002 ms): stat(filename: 0x8fc536f0, statbuf: 0x7ffdb676cb50) = 0 19783.788 ( 0.001 ms): stat(filename: 0x8fc536f0, statbuf: 0x7ffdb676ca70) = 0 19783.791 ( 0.001 ms): geteuid() = 1000 19783.793 ( 0.001 ms): getegid() = 1000 19783.795 ( 0.001 ms): getuid() = 1000 19783.797 ( 0.001 ms): getgid() = 1000 19783.798 ( 0.005 ms): access(filename: 0x8fc536f0, mode: X) = 0 19783.804 ( 0.001 ms): stat(filename: 0x8fc536f0, statbuf: 0x7ffdb676ca70) = 0 19783.807 ( 0.001 ms): geteuid() = 1000 19783.809 ( 0.001 ms): getegid() = 1000 19783.810 ( 0.001 ms): getuid() = 1000 19783.812 ( 0.001 ms): getgid() = 1000 19783.814 ( 0.001 ms): access(filename: 0x8fc536f0, mode: R) = 0 19783.816 ( 0.001 ms): stat(filename: 0x8fc536f0, statbuf: 0x7ffdb676cb80) = 0 19783.818 ( 0.001 ms): stat(filename: 0x8fc536f0, statbuf: 0x7ffdb676caa0) = 0 19783.820 ( 0.001 ms): geteuid() = 1000 19783.822 ( 0.001 ms): getegid() = 1000 19783.823 ( 0.001 ms): getuid() = 1000 19783.825 ( 0.001 ms): getgid() = 1000 19783.827 ( 0.001 ms): access(filename: 0x8fc536f0, mode: X) = 0 19783.829 ( 0.001 ms): stat(filename: 0x8fc536f0, statbuf: 0x7ffdb676caa0) = 0 19783.831 ( 0.001 ms): geteuid() = 1000 19783.833 ( 0.001 ms): getegid() = 1000 19783.834 ( 0.001 ms): getuid() = 1000 19783.836 ( 0.001 ms): getgid() = 1000 19783.838 ( 0.001 ms): access(filename: 0x8fc536f0, mode: R) = 0 19788.081 ( 0.011 ms): rt_sigprocmask(how: BLOCK, nset: 0x7ffdb676cc40, oset: 0x7ffdb676ccc0, sigsetsize: 8) = 0 19788.093 ( 0.012 ms): pipe(fildes: 0x55ec8e1e3738) = 0 19788.107 ( 0.742 ms): clone(clone_flags: CHILD_CLEARTID|CHILD_SETTID|0x11, child_tidptr: 0x7fd71d022a10) = 5948 (bash) 19788.863 ( 0.002 ms): setpgid(pid: 5948 (bash), pgid: 5948 (bash)) = 0 19788.879 ( 0.002 ms): rt_sigprocmask(how: SETMASK, nset: 0x7ffdb676ccc0, sigsetsize: 8) = 0 19788.903 ( 0.001 ms): rt_sigprocmask(how: BLOCK, nset: 0x7ffdb676cba0, oset: 0x7ffdb676cc20, sigsetsize: 8) = 0 19788.906 ( 0.002 ms): close(fd: 3) = 0 19788.909 ( 0.001 ms): close(fd: 4) = 0 19788.937 ( 0.003 ms): ioctl(fd: 255</dev/pts/1>, cmd: TIOCGPGRP, arg: 0x7ffdb676cb64) = 0 19788.943 ( 0.002 ms): rt_sigprocmask(how: SETMASK, nset: 0x7ffdb676cc20, sigsetsize: 8) = 0 19788.947 ( 0.002 ms): rt_sigprocmask(how: BLOCK, nset: 0x7ffdb676cca0, oset: 0x7ffdb676cd20, sigsetsize: 8) = 0 19788.953 ( 1.664 ms): wait4(upid: -1, stat_addr: 0x7ffdb676cc40, options: UNTRACED|CONTINUED) = 5948 (bash) 19790.626 ( 0.002 ms): rt_sigprocmask(how: BLOCK, nset: 0x7ffdb676cb60, oset: 0x7ffdb676cbe0, sigsetsize: 8) = 0 19790.630 ( 0.002 ms): ioctl(fd: 255</dev/pts/1>, cmd: TIOCSPGRP, arg: 0x7ffdb676cb4c) = 0 19790.633 ( 0.001 ms): rt_sigprocmask(how: SETMASK, nset: 0x7ffdb676cbe0, sigsetsize: 8) = 0 19790.636 ( 0.002 ms): ioctl(fd: 255</dev/pts/1>, cmd: TCGETS, arg: 0x7ffdb676cc40) = 0 19790.640 ( 0.002 ms): ioctl(fd: 255</dev/pts/1>, cmd: TIOCGWINSZ, arg: 0x7ffdb676cc50) = 0 19790.657 ( 0.002 ms): rt_sigprocmask(how: SETMASK, nset: 0x7ffdb676cd20, sigsetsize: 8) = 0 19790.665 ( 0.001 ms): wait4(upid: -1, stat_addr: 0x7ffdb676be90, options: NOHANG|UNTRACED|CONTINUED) = -1 ECHILD (No child processes) 19790.670 ( ): rt_sigreturn() ... 19790.682 ( 0.001 ms): rt_sigaction(sig: INT, act: 0x7ffdb676cc70, oact: 0x7ffdb676cd10, sigsetsize: 8) = 0 19790.694 ( 0.002 ms): rt_sigprocmask(how: BLOCK, oset: 0x7ffdb676cce0, sigsetsize: 8) = 0 19790.728 ( 0.006 ms): stat(filename: 0x8fb64ea0, statbuf: 0x7ffdb676ca10) = 0 19790.736 ( 0.002 ms): stat(filename: 0x925b7c50, statbuf: 0x7ffdb676c930) = 0 19790.739 ( 0.005 ms): openat(dfd: CWD, filename: 0x925b7c50, flags: APPEND|WRONLY) = 3 19790.746 ( 0.045 ms): write(fd: 3, buf: 0x55ec925b7bd0, count: 3) = 3 19790.793 ( 0.002 ms): close(fd: 3) = 0 19790.800 ( 0.009 ms): chown(filename: 0x925b7c50, user: 1000, group: 1000) = 0 19790.847 ( 0.002 ms): rt_sigprocmask(how: BLOCK, nset: 0x7ffdb676bdf0, oset: 0x7ffdb676be70, sigsetsize: 8) = 0 19790.851 ( 0.002 ms): ioctl(fd: 255</dev/pts/1>, cmd: TIOCSPGRP, arg: 0x7ffdb676bddc) = 0 19790.855 ( 0.001 ms): rt_sigprocmask(how: SETMASK, nset: 0x7ffdb676be70, sigsetsize: 8) = 0 19790.858 ( 0.002 ms): rt_sigaction(sig: INT, act: 0x7ffdb676bc70, oact: 0x7ffdb676bd10, sigsetsize: 8) = 0 19790.862 ( 0.002 ms): fcntl(cmd: GETFL) = RDWR 19790.885 ( 0.002 ms): ioctl(cmd: TIOCGWINSZ, arg: 0x7ffdb676be60) = 0 19790.888 ( 0.002 ms): ioctl(cmd: TIOCSWINSZ, arg: 0x7ffdb676be60) = 0 19790.891 ( 0.009 ms): ioctl(cmd: TCGETS, arg: 0x7ffdb676be30) = 0 19790.903 ( 0.001 ms): ioctl(cmd: TCGETS, arg: 0x7ffdb676be30) = 0 19790.906 ( 0.002 ms): ioctl(cmd: TCSETSW, arg: 0x7ffdb676be00) = 0 19790.909 ( 0.002 ms): ioctl(cmd: TCGETS, arg: 0x7ffdb676be00) = 0 19790.913 ( 0.002 ms): rt_sigprocmask(how: BLOCK, nset: 0x55ec8e1ef420, oset: 0x55ec8e1f5140, sigsetsize: 8) = 0 19790.916 ( 0.002 ms): rt_sigaction(sig: INT, act: 0x7ffdb676bad0, oact: 0x7ffdb676bb70, sigsetsize: 8) = 0 19790.920 ( 0.002 ms): rt_sigaction(sig: TERM, act: 0x7ffdb676bad0, oact: 0x7ffdb676bb70, sigsetsize: 8) = 0 19790.924 ( 0.001 ms): rt_sigaction(sig: HUP, act: 0x7ffdb676bad0, oact: 0x7ffdb676bb70, sigsetsize: 8) = 0 19790.927 ( 0.001 ms): rt_sigaction(sig: QUIT, act: 0x7ffdb676bad0, oact: 0x7ffdb676bb70, sigsetsize: 8) = 0 19790.930 ( 0.002 ms): rt_sigaction(sig: QUIT, act: 0x7ffdb676bc40, oact: 0x7ffdb676bce0, sigsetsize: 8) = 0 19790.933 ( 0.001 ms): rt_sigaction(sig: ALRM, act: 0x7ffdb676bba0, oact: 0x7ffdb676bc40, sigsetsize: 8) = 0 19790.935 ( 0.001 ms): rt_sigaction(sig: TSTP, act: 0x7ffdb676bad0, oact: 0x7ffdb676bb70, sigsetsize: 8) = 0 19790.938 ( 0.001 ms): rt_sigaction(sig: TSTP, act: 0x7ffdb676bc40, oact: 0x7ffdb676bce0, sigsetsize: 8) = 0 19790.940 ( 0.001 ms): rt_sigaction(sig: TTOU, act: 0x7ffdb676bad0, oact: 0x7ffdb676bb70, sigsetsize: 8) = 0 19790.942 ( 0.001 ms): rt_sigaction(sig: TTOU, act: 0x7ffdb676bc40, oact: 0x7ffdb676bce0, sigsetsize: 8) = 0 19790.945 ( 0.001 ms): rt_sigaction(sig: TTIN, act: 0x7ffdb676bad0, oact: 0x7ffdb676bb70, sigsetsize: 8) = 0 19790.947 ( 0.001 ms): rt_sigaction(sig: TTIN, act: 0x7ffdb676bc40, oact: 0x7ffdb676bce0, sigsetsize: 8) = 0 19790.950 ( 0.001 ms): rt_sigprocmask(how: SETMASK, nset: 0x55ec8e1f5140, sigsetsize: 8) = 0 19790.952 ( 0.001 ms): rt_sigaction(sig: WINCH, act: 0x7ffdb676bad0, oact: 0x7ffdb676bb70, sigsetsize: 8) = 0 19790.960 ( 0.006 ms): write(fd: 2</dev/pts/1>, buf: 0x55ec925b5bd0, count: 60) = 60 19790.969 (2622.411 ms): pselect6(n: 1, inp: 0x7ffdb676be20, sig: 0x7ffdb676bde0) = 1 22413.398 ( 0.007 ms): read(buf: 0x7ffdb676be1f, count: 1) = 1 22413.412 ( 0.005 ms): ioctl(cmd: TCGETS, arg: 0x7ffdb676bea0) = 0 22413.419 ( 0.004 ms): ioctl(cmd: TCSETSW, arg: 0x7ffdb676be70) = 0 22413.426 ( 0.003 ms): ioctl(cmd: TCGETS, arg: 0x7ffdb676be70) = 0 22413.433 ( 0.003 ms): rt_sigaction(sig: INT, act: 0x7ffdb676bc50, oact: 0x7ffdb676bcf0, sigsetsize: 8) = 0 22413.439 ( 0.003 ms): rt_sigaction(sig: TERM, act: 0x7ffdb676bc50, oact: 0x7ffdb676bcf0, sigsetsize: 8) = 0 22413.444 ( 0.002 ms): rt_sigaction(sig: HUP, act: 0x7ffdb676bc50, oact: 0x7ffdb676bcf0, sigsetsize: 8) = 0 22413.448 ( 0.002 ms): rt_sigaction(sig: ALRM, act: 0x7ffdb676bc50, oact: 0x7ffdb676bcf0, sigsetsize: 8) = 0 22413.453 ( 0.002 ms): rt_sigaction(sig: WINCH, act: 0x7ffdb676bd10, oact: 0x7ffdb676bdb0, sigsetsize: 8) = 0 22413.458 ( 0.002 ms): rt_sigaction(sig: INT, act: 0x7ffdb676bc70, oact: 0x7ffdb676bd10, sigsetsize: 8) = 0 22413.478 ( 0.008 ms): write(fd: 2</dev/pts/1>, buf: 0x55ec925b5bd0, count: 5) = 5 22413.492 ( 0.002 ms): rt_sigaction(sig: INT, act: 0x7ffdb676cc70, oact: 0x7ffdb676cd10, sigsetsize: 8) = 0 22413.498 ( 0.003 ms): rt_sigprocmask(how: BLOCK, nset: 0x7ffdb676ce10, oset: 0x7ffdb676ce90, sigsetsize: 8) = 0 22413.503 ( 0.002 ms): rt_sigprocmask(how: SETMASK, nset: 0x7ffdb676ce90, sigsetsize: 8) = 0 22413.508 ( 0.003 ms): setpgid(pgid: 5907 (bash)) = -1 EPERM (Operation not permitted) 22413.545 ( ): exit_group() = ?Observe crazy delay between the last rt_sigaction and the first stat. stat is when bash starts searching for ls program in PATH. But why this delay before it starts doing so?
1 Answer
I think I figured it out. I had 300k lines in my .bash_history file, HISTCONTROL=ignoreboth:erasedups set, with the rest configured for history to be appended at every command to bash history. So I think that time bash spent deduplicating and appending. And cd .. and ls are very common lines in my history so it took some time? Not sure why old occurances were persisting so that it had to try to remove them again and again. In any case, clearing my history made things fast again. Or it took so long just to check for duplicates. I also removed erasedups just in case. I anyway do not want historical entries to be removed (so that a series of commands in history stays recorded).
