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 totalPerhaps 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
Former user commented on 2016-05-03T13:50:28.000-0400:
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.