bin/55271: kgmon sometimes creates unreasonably large output file

[roland.illig%gmx.de@localhost]

>Number:         55271
>Category:       bin
>Synopsis:       kgmon sometimes creates unreasonably large output file
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    bin-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Sun May 17 20:35:01 +0000 2020
>Originator:     Roland Illig
>Release:        8.0
>Organization:
>Environment:
NetBSD nb8.roland-illig.de 8.0 NetBSD 8.0 (GENERIC.PROF) #0: Sun May 17 14:12:24 UTC 2020  rillig%nb8.roland-illig.de@localhost:/home/rillig/proj/src8/sys/arch/amd64/compile/GENERIC.PROF amd64
>Description:
Some read(2) and write(2) calls take unreasonably long, even on a tmpfs.

https://mail-index.netbsd.org/netbsd-users/2020/04/29/msg024716.html

To investigate, I followed https://www.netbsd.org/docs/guide/en/chap-tuning.html#tuning-kprof and wrote the following program:

|#! /bin/sh
|
|set -eu
|
|cd '/root'
|
|# kgmon erzeugt manchmal irrsinnig gro▒e Dateien, grö▒er als 1 GB.
|ulimit -f 1000000
|
|pidfile='messung.pid'
|
|[ -f "$pidfile" ] \
|&& kill -0 "$(cat "$pidfile")" \
|&& exit 0
|echo $$ > "$pidfile"
|
|exec 1> "$(date +%H_%M_%S)" 2>&1
|
|kgmon -b -r
|trap 'kgmon -h' EXIT
|
|for i in 1 2 3 4 5; do
|    time wc -l 80mb
|done
|
|kgmon -p -h
|gprof /netbsd | sed 20q
|ls -l 'gmon.out'
|rm -f 'gmon.out' "$pidfile"

A typical output is:

|kgmon: kernel profiling is running.
|  326742 80mb
|        2.71 real         0.03 user         2.67 sys
|  326742 80mb
|        2.88 real         0.03 user         2.85 sys
|  326742 80mb
|        1.94 real         0.00 user         1.94 sys
|  326742 80mb
|        2.45 real         0.02 user         2.43 sys
|  326742 80mb
|        1.44 real         0.02 user         1.42 sys
|kgmon: kernel profiling is off.
|Flat profile:
|
|Each sample counts as 0.01 seconds.
|  %   cumulative   self              self     total
| time   seconds   seconds    calls  us/call  us/call  name
| 68.25     43.03    43.03   246298   174.71   174.71  x86_stihlt
| 15.88     53.04    10.01                             x86_pause
|  9.56     59.07     6.03   523746    11.51    11.51  inl
|  1.92     60.28     1.21                             Xspllower
|  0.59     60.65     0.37   128940     2.87     2.87  ldr7
|  0.40     60.90     0.25   328193     0.76     0.79  pmap_tlb_shootnow
|  0.25     61.05     0.15  6111386     0.03     0.03  uvm_page_compare_key
|  0.22     61.20     0.14   390810     0.36     1.09  pmap_enter_ma
|  0.21     61.33     0.13  2081445     0.06     0.06  mutex_enter
|  0.21     61.45     0.13   136603     0.95     1.24  copyout
|  0.17     61.56     0.11  1219386     0.09     0.09  atomic_cas_ptr
|  0.14     61.66     0.09  1301541     0.07     0.19  rb_tree_find_node
|  0.13     61.73     0.08                             calltrap
|  0.08     61.78     0.05   376838     0.13     0.24  pmap_free_ptp
|  0.08     61.84     0.05   124313     0.40    11.68  trap
|-rw-r--r--  1 root  wheel  5884150 May 17 20:25 gmon.out
|kgmon: kernel profiling is off.

The next run of that program triggered the ulimit though:

|kgmon: kernel profiling is running.
|  326742 80mb
|        4.68 real         0.02 user         4.30 sys
|  326742 80mb
|        4.12 real         0.03 user         3.70 sys
|  326742 80mb
|        4.92 real         0.03 user         4.49 sys
|  326742 80mb
|        4.00 real         0.03 user         3.74 sys
|  326742 80mb
|        4.07 real         0.04 user         3.63 sys
|[1]   File size limit exceeded kgmon -p -h
|kgmon: kernel profiling is off.

-rw-r--r--  1 root  wheel   512000000 May 17 20:26 gmon.out

Starting around offset 005945c0, which is near the usual file size, the data repeats:

005945c0  22 80 ff ff ff ff bf 03  00 00 00 00 00 00 08 b1  |"...............|
005945d0  98 80 ff ff ff ff a3 60  95 80 ff ff ff ff 68 01  |.......`......h.|
005945e0  00 00 00 00 00 00 14 b1  98 80 ff ff ff ff 58 b3  |..............X.|
005945f0  98 80 ff ff ff ff 43 04  00 00 00 00 00 00 40 b1  |......C.......@.|
00594600  98 80 ff ff ff ff 6b 9d  98 80 ff ff ff ff 68 01  |......k.......h.|
00594610  00 00 00 00 00 00 f4 b1  98 80 ff ff ff ff 6b 9d  |..............k.|
00594620  98 80 ff ff ff ff a9 02  00 00 00 00 00 00 f8 b6  |................|
00594630  98 80 ff ff ff ff cb 61  95 80 ff ff ff ff 47 36  |.......a......G6|
00594640  00 00 00 00 00 00 f8 b6  98 80 ff ff ff ff 00 00  |................|
00594650  00 00 00 00 00 00 00 00  00 00 00 00 00 00 58 b7  |..............X.|
00594660  98 80 ff ff ff ff 3a 8a  22 80 ff ff ff ff a1 32  |......:."......2|
00594670  00 00 00 00 00 00 58 b7  98 80 ff ff ff ff 4a f5  |......X.......J.|
00594680  21 80 ff ff ff ff 9f 01  00 00 00 00 00 00 58 b7  |!.............X.|
00594690  98 80 ff ff ff ff a3 60  95 80 ff ff ff ff 9a 01  |.......`........|
005946a0  00 00 00 00 00 00 58 b7  98 80 ff ff ff ff 3a 8a  |......X.......:.|
005946b0  22 80 ff ff ff ff a1 32  00 00 00 00 00 00 58 b7  |"......2......X.|
005946c0  98 80 ff ff ff ff 4a f5  21 80 ff ff ff ff 9f 01  |......J.!.......|
005946d0  00 00 00 00 00 00 58 b7  98 80 ff ff ff ff a3 60  |......X........`|
005946e0  95 80 ff ff ff ff 9a 01  00 00 00 00 00 00 58 b7  |..............X.|
005946f0  98 80 ff ff ff ff 3a 8a  22 80 ff ff ff ff a1 32  |......:."......2|

>How-To-Repeat:

>Fix: