NetBSD Problem Report #55271
From www@netbsd.org Sun May 17 20:33:36 2020
Return-Path: <www@netbsd.org>
Received: from mail.netbsd.org (mail.netbsd.org [199.233.217.200])
(using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits))
(Client CN "mail.NetBSD.org", Issuer "mail.NetBSD.org CA" (not verified))
by mollari.NetBSD.org (Postfix) with ESMTPS id 7F70B1A921E
for <gnats-bugs@gnats.NetBSD.org>; Sun, 17 May 2020 20:33:36 +0000 (UTC)
Message-Id: <20200517203335.4A7531A9227@mollari.NetBSD.org>
Date: Sun, 17 May 2020 20:33:35 +0000 (UTC)
From: roland.illig@gmx.de
Reply-To: roland.illig@gmx.de
To: gnats-bugs@NetBSD.org
Subject: kgmon sometimes creates unreasonably large output file
X-Send-Pr-Version: www-1.0
>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
>Last-Modified: Sun May 17 20:55: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:/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:
>Audit-Trail:
From: Roland Illig <roland.illig@gmx.de>
To: gnats-bugs@netbsd.org
Cc:
Subject: Re: bin/55271: kgmon sometimes creates unreasonably large output file
Date: Sun, 17 May 2020 22:47:30 +0200
Indeed, running "kgmon -d", it looks like an endless loop:
kgmon: [mcleanup] frompc 0xffffffff809e6504 selfpc 0x0 count 0
kgmon: [mcleanup] frompc 0xffffffff809e650c selfpc 0xffffffff8021f54a
count 174504
kgmon: [mcleanup] frompc 0xffffffff809e650c selfpc 0xffffffff8098ff84
count 174135
kgmon: [mcleanup] frompc 0xffffffff809e650c selfpc 0xffffffff809daad3
count 546607
kgmon: [mcleanup] frompc 0xffffffff809e650c selfpc 0xffffffff8021f54a
count 174504
kgmon: [mcleanup] frompc 0xffffffff809e650c selfpc 0xffffffff8098ff84
count 174135
kgmon: [mcleanup] frompc 0xffffffff809e650c selfpc 0xffffffff809daad3
count 546607
kgmon: [mcleanup] frompc 0xffffffff809e650c selfpc 0xffffffff8021f54a
count 174504
kgmon: [mcleanup] frompc 0xffffffff809e650c selfpc 0xffffffff8098ff84
count 174135
kgmon: [mcleanup] frompc 0xffffffff809e650c selfpc 0xffffffff809daad3
count 546607
kgmon: [mcleanup] frompc 0xffffffff809e650c selfpc 0xffffffff8021f54a
count 174504
kgmon: [mcleanup] frompc 0xffffffff809e650c selfpc 0xffffffff8098ff84
count 174135
kgmon: [mcleanup] frompc 0xffffffff809e650c selfpc 0xffffffff809daad3
count 546607
(Contact us)
$NetBSD: query-full-pr,v 1.46 2020/01/03 16:35:01 leot Exp $
$NetBSD: gnats_config.sh,v 1.9 2014/08/02 14:16:04 spz Exp $
Copyright © 1994-2020
The NetBSD Foundation, Inc. ALL RIGHTS RESERVED.