Bug 201685 - top(1) with -m io produces garbage output for first update
Summary: top(1) with -m io produces garbage output for first update
Status: Open
Alias: None
Product: Base System
Classification: Unclassified
Component: bin (show other bugs)
Version: 10.1-RELEASE
Hardware: Any Any
: --- Affects Only Me
Assignee: freebsd-bugs (Nobody)
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2015-07-19 03:38 UTC by cstdenis
Modified: 2018-06-24 22:40 UTC (History)
1 user (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description cstdenis 2015-07-19 03:38:03 UTC
When top is run -m io, the io stats in the first update are garbage data.

Here is output of top configured with 2 updates to show the problem. It is most noticeable when used in batch mode, but also affects interactive mode.

The unmapped user IDs are normal here, it's caused by this being a jail server.

======================================================

root@Rin:/usr/local/etc/ezjail # freebsd-version
10.1-RELEASE-p14

root@Rin:/usr/local/etc/ezjail # top -v
top: version 3.5beta12


root@Rin:/usr/local/etc/ezjail # /usr/bin/top -mio -ototal -n -d 2
last pid:   193;  load averages:  1.97,  2.27,  2.11  up 171+18:03:41    20:32:03
386 processes: 2 running, 384 sleeping

Mem: 779M Active, 3746M Inact, 3058M Wired, 11M Cache, 310M Free
ARC: 1583M Total, 48M MFU, 1126M MRU, 6861K Anon, 32M Header, 371M Other
Swap: 2048M Total, 202M Used, 1846M Free, 9% Inuse


  PID USERNAME     VCSW  IVCSW   READ  WRITE  FAULT  TOTAL PERCENT COMMAND
 1524 root       112440252 2645423  87941 119361424      0 119449365   3.15% syslogd
 1686     88     247804194 1369925 5510586 94629832   5372 100145790   2.64% mysqld
 1372    106     18593140 211500 339101 11605238    342 11944681   0.31% clamav-milter
 1949 root       7797680 472957  57488 11850655      0 11908143   0.31% syslogd
 1377    106     404512 159938 1307130 7620728     25 8927883   0.24% freshclam
 1369    106     2078158 997412 246356 6206470  18863 6471689   0.17% clamd
 1353    112     15867731  34136 114640 5581016     74 5695730   0.15% dccifd
31926    125     2631184 251393 108606 1665388      0 1773994   0.05% tlsmgr
 1268 root       2050530   5384  19637 1061213      2 1080852   0.03% syslogd
  795 root       1762819   9738  21263 823570      0 844833   0.02% syslogd
20952    125     877982  17509 218959      0     13 218972   0.01% gam_server
31922    125     1303632 200001 161101      0      0 161101   0.00% qmgr
22107     70      93677    874 104230  34571      0 138801   0.00% postgres
 2388 root       1488787   4106   9781  81676      2  91459   0.00% syslogd
 1088 root       661820   3474   9723  80783      2  90508   0.00% syslogd
95245 root        34598   3184      1  32019      0  32020   0.00% cronolog
 2502 root       335281   3487  11902      1      3  11906   0.00% cron
  946 root       15139723 210467   7126   3700     32  10858   0.00% ntpd

last pid:   194;  load averages:  1.97,  2.27,  2.11  up 171+18:03:44    20:32:06
369 processes: 1 running, 368 sleeping
CPU: 18.2% user,  0.0% nice,  3.4% system,  0.0% interrupt, 78.3% idle
Mem: 757M Active, 3747M Inact, 3054M Wired, 11M Cache, 335M Free
ARC: 1583M Total, 47M MFU, 1125M MRU, 8412K Anon, 32M Header, 371M Other
Swap: 2048M Total, 202M Used, 1846M Free, 9% Inuse

  PID USERNAME     VCSW  IVCSW   READ  WRITE  FAULT  TOTAL PERCENT COMMAND
 2138     88      30105     72     43   1062      0   1105  80.77% mysqld
99895 www          7664     30     63      0      0     63   4.61% httpd
  134 www          3399     15     38      0      0     38   2.78% httpd
  173 www          4081     17     31      0      0     31   2.27% httpd
  143 www          4100     12     30      0      0     30   2.19% httpd
95245 root           31      0      0     28      0     28   2.05% cronolog
99884 www          1158     16     17      0      0     17   1.24% httpd
99822 www          2031      6     15      0      0     15   1.10% httpd
99897 www          2017     19     15      0      0     15   1.10% httpd
99810 www          2065     10     15      0      0     15   1.10% httpd
99812 www          1167      4      9      0      0      9   0.66% httpd
  193 root            3      0      2      0      0      2   0.15% top
  175    125          0      0      0      0      0      0   0.00% imapd
  172 www             0      0      0      0      0      0   0.00% httpd
  168 www             0      0      0      0      0      0   0.00% httpd
  167 www            42      2      0      0      0      0   0.00% httpd
  166 www             0      0      0      0      0      0   0.00% httpd
  164 root            0      0      0      0      0      0   0.00% virtual
Comment 1 cstdenis 2015-07-26 02:24:48 UTC
The entire CPU line is also missing from the first output in batch mode (regardless of other parameters).
Comment 2 Eitan Adler freebsd_committer freebsd_triage 2018-06-23 03:18:11 UTC
> The entire CPU line is also missing from the first output in batch mode (regardless of other parameters).

This was fixed in bug #218889 / r335576.
Comment 3 Eitan Adler freebsd_committer freebsd_triage 2018-06-23 03:21:20 UTC
top computes the difference itself. When it only does one iteration, it has nothing to compare against. One way of fixing this would be to always do a "dummy" run and only ever output the *second* run. 
That said, this is currently working as intended. I'm open to changing the behavior if people find no value in the current status though.
Comment 4 cstdenis 2018-06-24 21:55:08 UTC
I encountered this error because I was trying to log periodic snapshots of top output as part of tracking down some system issues. 

i.e. (/root/datestamp.sh; /usr/bin/top -j -t -mio -ototal) >> /var/log/top_io.log


Having it do a "dummy" run before outputting would be a great fix and make that kind of logging possible. As it is, the above command is useless.
Comment 5 Eitan Adler freebsd_committer freebsd_triage 2018-06-24 22:40:05 UTC
reopen per comment