OS-5374: lxbrand zsh REPORTTIME behavior incorrect

Details

Issue Type:Bug
Priority:4 - Normal
Status:Open
Created at:2016-05-02T15:27:37.000Z
Updated at:2019-08-28T17:19:25.791Z

People

Created by:Former user
Reported by:Former user

Labels

lxbrand

Description

Reported by Rich Lowe via github:

I use the zsh option REPORTTIME which causes commands that run for greater than a certain amount of time to report time(1)-like statistics when they complete. (I use REPORTTIME=3, for 3 seconds).

This seems awfully confused in LX. A simple ls of my home directory reports:

dwyn:~> ls
bin  share
ls --color=auto  26.70s user 97.16s system 468191% cpu 0.026 total

Perhaps this is similar to other reported confusion regarding hires_tick?

This is joyent_20160414T011743Z, a debian-8 image based on c0b7ca82-d69f-11e5-a303-4f0b12cb14d6, reporting as Linux dwyn 3.16.0 BrandZ virtual linux x86_64 GNU/Linux using zsh 5.0.7-5

Initially filed as illumos-joyent#107

Comments

Comment by Former user
Created at 2016-05-03T17:50:28.000Z

It appears that zsh uses the rusage information communicated by wait4(2) to decide when and what to report about process time consumption.

Here's a trace from an Ubuntu VM:

1545  10:15:22.664864 execve("/usr/bin/zsh", ["zsh"], ["XDG_VTNR=1", "XDG_SESSION_ID=c1", "SHELL=/bin/bash", "TERM=linux", "HUSHLOGIN=FALSE", "USER=root", "LS_COLORS=rs=0:di=01;34:ln=01;36"..., "MAIL=/var/mail/root", "PATH=/usr/local/sbin:/usr/local/"..., "PWD=/root", "LANG=en_US.UTF-8", "SHLVL=1", "XDG_SEAT=seat0", "HOME=/root", "LOGNAME=root", "LESSOPEN=| /usr/bin/lesspipe %s", "XDG_RUNTIME_DIR=/run/user/0", "LESSCLOSE=/usr/bin/lesspipe %s %"..., "_=/usr/bin/strace"]) = 0
1545  10:15:22.694500 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb75009a8) = 1546
1546  10:15:22.694955 execve("/usr/bin/getent", ["getent", "group", "root"], ["XDG_VTNR=1", "XDG_SESSION_ID=c1", "SHELL=/bin/bash", "TERM=linux", "HUSHLOGIN=FALSE", "USER=root", "LS_COLORS=rs=0:di=01;34:ln=01;36"..., "MAIL=/var/mail/root", "PATH=/usr/local/sbin:/usr/local/"..., "PWD=/root", "LANG=en_US.UTF-8", "SHLVL=2", "XDG_SEAT=seat0", "HOME=/root", "LOGNAME=root", "LESSOPEN=| /usr/bin/lesspipe %s", "XDG_RUNTIME_DIR=/run/user/0", "LESSCLOSE=/usr/bin/lesspipe %s %"..., "_=/usr/bin/getent", "OLDPWD=/root"]) = 0
1546  10:15:22.696275 +++ exited with 0 +++
1545  10:15:22.696291 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=1546, si_status=0, si_utime=0, si_stime=0} ---
1545  10:15:22.696315 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG|WSTOPPED|WCONTINUED, {ru_utime={0, 0}, ru_stime={0, 0}, ru_maxrss=2308, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=127, ru_majflt=0, ru_nswap=0, ru_inblock=0, ru_oublock=0, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=236, ru_nivcsw=1}) = 1546
1545  10:15:22.696389 wait4(-1, 0xbff70f04, WNOHANG|WSTOPPED|WCONTINUED, 0xbff70f18) = -1 ECHILD (No child processes)
1545  10:15:22.712975 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb75009a8) = 1547
1547  10:15:22.713749 +++ exited with 0 +++
1545  10:15:22.713764 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=1547, si_status=0, si_utime=0, si_stime=0} ---
1545  10:15:22.713785 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG|WSTOPPED|WCONTINUED, {ru_utime={0, 0}, ru_stime={0, 0}, ru_maxrss=2844, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=54, ru_majflt=0, ru_nswap=0, ru_inblock=0, ru_oublock=0, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=47, ru_nivcsw=1}) = 1547
1545  10:15:22.713840 wait4(-1, 0xbff73b04, WNOHANG|WSTOPPED|WCONTINUED, 0xbff73b18) = -1 ECHILD (No child processes)
1545  10:15:24.072652 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb75009a8) = 1548
1548  10:15:24.073252 execve("/bin/ls", ["ls"], ["XDG_VTNR=1", "XDG_SESSION_ID=c1", "SHELL=/bin/bash", "TERM=linux", "HUSHLOGIN=FALSE", "USER=root", "LS_COLORS=rs=0:di=01;34:ln=01;36"..., "MAIL=/var/mail/root", "PATH=/usr/local/sbin:/usr/local/"..., "PWD=/root", "LANG=en_US.UTF-8", "SHLVL=2", "XDG_SEAT=seat0", "HOME=/root", "LOGNAME=root", "LESSOPEN=| /usr/bin/lesspipe %s", "XDG_RUNTIME_DIR=/run/user/0", "LESSCLOSE=/usr/bin/lesspipe %s %"..., "_=/bin/ls", "OLDPWD=/root"]) = 0
1548  10:15:24.085844 +++ exited with 0 +++
1545  10:15:24.085868 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=1548, si_status=0, si_utime=0, si_stime=0} ---
1545  10:15:24.085895 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG|WSTOPPED|WCONTINUED, {ru_utime={0, 0}, ru_stime={0, 0}, ru_maxrss=2628, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=129, ru_majflt=0, ru_nswap=0, ru_inblock=0, ru_oublock=0, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=226, ru_nivcsw=1}) = 1548
1545  10:15:24.085958 wait4(-1, 0xbff74c44, WNOHANG|WSTOPPED|WCONTINUED, 0xbff74c58) = -1 ECHILD (No child processes)
1545  10:15:27.487725 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb75009a8) = 1549
1549  10:15:27.488430 execve("/usr/bin/find", ["find", "/"], ["XDG_VTNR=1", "XDG_SESSION_ID=c1", "SHELL=/bin/bash", "TERM=linux", "HUSHLOGIN=FALSE", "USER=root", "LS_COLORS=rs=0:di=01;34:ln=01;36"..., "MAIL=/var/mail/root", "PATH=/usr/local/sbin:/usr/local/"..., "PWD=/root", "LANG=en_US.UTF-8", "SHLVL=2", "XDG_SEAT=seat0", "HOME=/root", "LOGNAME=root", "LESSOPEN=| /usr/bin/lesspipe %s", "XDG_RUNTIME_DIR=/run/user/0", "LESSCLOSE=/usr/bin/lesspipe %s %"..., "_=/usr/bin/find", "OLDPWD=/root"]) = 0
1549  10:15:28.666408 +++ exited with 0 +++
1545  10:15:28.666436 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=1549, si_status=0, si_utime=12, si_stime=49} ---
1545  10:15:28.666465 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG|WSTOPPED|WCONTINUED, {ru_utime={0, 120000}, ru_stime={0, 460000}, ru_maxrss=2628, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=327, ru_majflt=0, ru_nswap=0, ru_inblock=0, ru_oublock=0, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=375882, ru_nivcsw=98}) = 1549
1545  10:15:28.666613 wait4(-1, 0xbff74c44, WNOHANG|WSTOPPED|WCONTINUED, 0xbff74c58) = -1 ECHILD (No child processes)
1545  10:15:30.127264 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb75009a8) = 1550
1550  10:15:30.127964 execve("/bin/ls", ["ls"], ["XDG_VTNR=1", "XDG_SESSION_ID=c1", "SHELL=/bin/bash", "TERM=linux", "HUSHLOGIN=FALSE", "USER=root", "LS_COLORS=rs=0:di=01;34:ln=01;36"..., "MAIL=/var/mail/root", "PATH=/usr/local/sbin:/usr/local/"..., "PWD=/root", "LANG=en_US.UTF-8", "SHLVL=2", "XDG_SEAT=seat0", "HOME=/root", "LOGNAME=root", "LESSOPEN=| /usr/bin/lesspipe %s", "XDG_RUNTIME_DIR=/run/user/0", "LESSCLOSE=/usr/bin/lesspipe %s %"..., "_=/bin/ls", "OLDPWD=/root"]) = 0
1550  10:15:30.131173 +++ exited with 0 +++
1545  10:15:30.131195 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=1550, si_status=0, si_utime=0, si_stime=0} ---
1545  10:15:30.131225 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG|WSTOPPED|WCONTINUED, {ru_utime={0, 0}, ru_stime={0, 0}, ru_maxrss=2628, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=129, ru_majflt=0, ru_nswap=0, ru_inblock=0, ru_oublock=0, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=226, ru_nivcsw=2}) = 1550
1545  10:15:30.131296 wait4(-1, 0xbff74c44, WNOHANG|WSTOPPED|WCONTINUED, 0xbff74c58) = -1 ECHILD (No child processes)
1545  10:15:32.471742 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb75009a8) = 1551
1551  10:15:32.472482 execve("/bin/sleep", ["sleep", "1"], ["XDG_VTNR=1", "XDG_SESSION_ID=c1", "SHELL=/bin/bash", "TERM=linux", "HUSHLOGIN=FALSE", "USER=root", "LS_COLORS=rs=0:di=01;34:ln=01;36"..., "MAIL=/var/mail/root", "PATH=/usr/local/sbin:/usr/local/"..., "PWD=/root", "LANG=en_US.UTF-8", "SHLVL=2", "XDG_SEAT=seat0", "HOME=/root", "LOGNAME=root", "LESSOPEN=| /usr/bin/lesspipe %s", "XDG_RUNTIME_DIR=/run/user/0", "LESSCLOSE=/usr/bin/lesspipe %s %"..., "_=/bin/sleep", "OLDPWD=/root"]) = 0
1551  10:15:33.473793 +++ exited with 0 +++
1545  10:15:33.473851 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=1551, si_status=0, si_utime=0, si_stime=0} ---
1545  10:15:33.473906 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG|WSTOPPED|WCONTINUED, {ru_utime={0, 0}, ru_stime={0, 0}, ru_maxrss=2628, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=97, ru_majflt=0, ru_nswap=0, ru_inblock=0, ru_oublock=0, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=103, ru_nivcsw=1}) = 1551
1545  10:15:33.474036 wait4(-1, 0xbff74c44, WNOHANG|WSTOPPED|WCONTINUED, 0xbff74c58) = -1 ECHILD (No child processes)
1545  10:15:33.983666 +++ exited with 0 +++

Compared to a similar trace from LX:

16:09:07.838643 execve("/usr/bin/zsh", ["zsh"], ["REMOTEHOST=zone:global", "MANPATH=:/native/usr/share/man", "SHELL=/bin/bash", "TERM=screen-256color", "HUSHLOGIN=FALSE", "USER=root", "MAIL=/var/mail/root", "PATH=/usr/local/sbin:/usr/local/"..., "PWD=/root", "LANG=en_US.UTF-8", "SHLVL=1", "HOME=/root", "LOGNAME=root", "_=/usr/bin/strace"]) = 0
16:09:07.877975 getrusage(RUSAGE_CHILDREN, {ru_utime={0, 0}, ru_stime={0, 0}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=0, ru_majflt=0, ru_nswap=0, ru_inblock=0, ru_oublock=0, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=0, ru_nivcsw=0}) = 0
16:09:09.260466 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7ffffede09d0) = 137066
16:09:09.268103 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=137066, si_uid=0, si_status=0, si_utime=1, si_stime=4} ---
16:09:09.268347 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=137066, si_uid=0, si_status=0, si_utime=1, si_stime=4} ---
16:09:09.269048 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG|WSTOPPED|WCONTINUED, {ru_utime={0, 1376}, ru_stime={0, 4300}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=0, ru_majflt=0, ru_nswap=0, ru_inblock=0, ru_oublock=0, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=0, ru_nivcsw=0}) = 137066
16:09:09.270533 wait4(-1, 0x7fffffefee5c, WNOHANG|WSTOPPED|WCONTINUED, 0x7fffffefee80) = -1 ECHILD (No child processes)
16:09:10.387843 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7ffffede09d0) = 137067
16:09:10.395714 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=137067, si_uid=0, si_status=0, si_utime=1, si_stime=4} ---
16:09:10.395816 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=137067, si_uid=0, si_status=0, si_utime=1, si_stime=4} ---
16:09:10.395967 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG|WSTOPPED|WCONTINUED, {ru_utime={0, 2915}, ru_stime={0, 8991}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=0, ru_majflt=0, ru_nswap=0, ru_inblock=0, ru_oublock=0, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=0, ru_nivcsw=1}) = 137067
16:09:10.396612 wait4(-1, 0x7fffffefe97c, WNOHANG|WSTOPPED|WCONTINUED, 0x7fffffefe9a0) = -1 ECHILD (No child processes)
16:09:15.973990 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7ffffede09d0) = 137068
16:09:17.411262 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=137068, si_uid=0, si_status=0, si_utime=110, si_stime=1317} ---
16:09:17.411445 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=137068, si_uid=0, si_status=0, si_utime=110, si_stime=1317} ---
16:09:17.411784 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG|WSTOPPED|WCONTINUED, {ru_utime={0, 113258}, ru_stime={1, 326506}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=0, ru_majflt=0, ru_nswap=0, ru_inblock=0, ru_oublock=0, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=19, ru_nivcsw=325}) = 137068
16:09:17.412801 wait4(-1, 0x7fffffefe97c, WNOHANG|WSTOPPED|WCONTINUED, 0x7fffffefe9a0) = -1 ECHILD (No child processes)
16:09:21.166242 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7ffffede09d0) = 137069
16:09:21.174515 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=137069, si_uid=0, si_status=0, si_utime=1, si_stime=5} ---
16:09:21.174760 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=137069, si_uid=0, si_status=0, si_utime=1, si_stime=5} ---
16:09:21.175574 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG|WSTOPPED|WCONTINUED, {ru_utime={0, 114642}, ru_stime={1, 331507}, ru_maxrss=0, ru_ixrss=0, ru_idrss=0, ru_isrss=0, ru_minflt=0, ru_majflt=0, ru_nswap=0, ru_inblock=0, ru_oublock=0, ru_msgsnd=0, ru_msgrcv=0, ru_nsignals=0, ru_nvcsw=19, ru_nivcsw=325}) = 137069
16:09:21.177129 wait4(-1, 0x7fffffefee5c, WNOHANG|WSTOPPED|WCONTINUED, 0x7fffffefee80) = -1 ECHILD (No child processes)
16:09:22.038859 +++ exited with 0 +++

Note how the time is cumulative on LX. Looking at how rusage is populated in our wait emulation, it appears we're emitting the rusage states for the source (wait4(2)ing) process instead of the reaped child.