NetBSD-Bugs archive
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index][Old Index]
Re: kern/54818: 9.0_RC1 pagedaemon spins
The following reply was made to PR kern/54818; it has been noted by GNATS.
From: Havard Eidnes <he%NetBSD.org@localhost>
To: gnats-bugs%netbsd.org@localhost
Cc: ad%netbsd.org@localhost, netbsd-bugs%netbsd.org@localhost, tsutsui%ceres.dti.ne.jp@localhost
Subject: Re: kern/54818: 9.0_RC1 pagedaemon spins
Date: Wed, 20 May 2020 22:11:56 +0200 (CEST)
Hi,
as we've found, this isn't the exact same bug as I'm seeing on
8.1 related to audio, but since I started logging state here I
thought I'd continue...
I've added the below diff to sys/dev/audio.c, and done a couple
of "play video with firefox via youtube" cycles. One such cycle
might look like this:
audio_open: flags=0x2 sc=0xfffffe811e23d000 hdl=0xfffffe811e22d130
audio_initbufs: mode=0x5
audio_init_ringbuffer: MI blksize=8192
audio_init_ringbuffer: final blksize=8192
audio_init_ringbuffer: MI blksize=8192
audio_init_ringbuffer: final blksize=8192
audio_init_ringbuffer: MI blksize=8192
audio_init_ringbuffer: final blksize=8192
audio_init_ringbuffer: MI blksize=8192
audio_init_ringbuffer: final blksize=8192
audiosetinfo sc=0xfffffe811e23d000 ai=0xffff800141296af0
audiosetinfo() Setting record params: enc=1 1ch 8/8bit 8000Hz
audiosetinfo() Setting play params: enc=1 1ch 8/8bit 8000Hz
audio_setup_pfilters: new 2, old 0
audio_setup_pfilters: HW-buffer=0xfffffe83df618ac0 pustream=0xfffffe83df618838
[0] enc=1 1ch 8/8bit 8000Hz
[1] enc=6 1ch 16/16bit 8000Hz
[HW] enc=6 2ch 16/16bit 48000Hz
audio_setup_rfilters: HW-buffer=0xfffffe83df618b68 rustream=0xfffffe83df618c80
[HW] enc=6 2ch 16/16bit 48000Hz
[0] enc=6 1ch 16/16bit 8000Hz
[1] enc=1 1ch 8/8bit 8000Hz
audio_setup_rfilters: new 2, old 0
audiosetinfo: filter setup is completed.
audio_initbufs: mode=0x5
audio_init_ringbuffer: MI blksize=336
audio_init_ringbuffer: final blksize=512
audio_calcwater: plow=49152 phigh=65536 rlow=0 rhigh=65195
audio_calcwater: plow=49152 phigh=65536 rlow=0 rhigh=65195
audio_open: done sc_mode = 0x5
AUDIO_SETINFO mode=0x5
audiosetinfo sc=0xfffffe811e23d000 ai=0xfffffe83fb636008
audiosetinfo() Setting play params: enc=10 2ch 16/16bit 48000Hz
audio_setup_pfilters: new 0, old 2
audio_stream_dtor: non-null start, size 65536
audio_stream_dtor: non-null start, size 65536
audio_setup_pfilters: HW-buffer=0xfffffe83df618ac0 pustream=0xfffffe83df618ac0
[HW] enc=6 2ch 16/16bit 48000Hz
audiosetinfo: filter setup is completed.
audio_initbufs: mode=0x1
audio_init_ringbuffer: MI blksize=8192
audio_init_ringbuffer: final blksize=8192
audio_calcwater: plow=49152 phigh=65536 rlow=0 rhigh=65195
AUDIO_GETINFO
audio_pint: used < blksize vc=0xfffffe83df618800 used=0 blksize=8192
audio_pint: used < blksize vc=0xfffffe83df618800 used=0 blksize=8192
mix_write: call trigger_output
(audio playing here, until closing firefox window)
audio_pint: used < blksize vc=0xfffffe83df618800 used=128 blksize=8192
audio_pint: used < blksize vc=0xfffffe83df618800 used=0 blksize=8192
audio_pint: used < blksize vc=0xfffffe83df618800 used=0 blksize=8192
etc.
audio_close: sc=0xfffffe811e23d000
audio_destroy_pfilters: npfilters 0
audio_destroy_rfilters: nrfilters 2
Now...
What's "missing" here at the end is printf() from
audio_stream_dtor() indicating that stream->start was non-NULL,
so nothing gets actually released in this audio_stream_dtor()
invocation for the "rfilters". So the allocations made for
audio_setup_rfilters() by audio_stream_ctor(), ref. the
audio_setup_rfilters: new 2, old 0
logged line, appear to get lost, two for each cycle of
open/close.
The releases shown below correspond to
audio_setup_pfilters: new 0, old 2
audio_stream_dtor: non-null start, size 65536
audio_stream_dtor: non-null start, size 65536
The diff below also changes a few of the key functions from
statics to non-static -- this makes them visible in backtrace
from dtrace, and an open/close cycle looks like this in the
dtrace log:
CPU FUNCTION
0 -> uvm_km_kmem_alloc size: 65536
netbsd`kmem_intr_alloc+0x6d
netbsd`kmem_intr_zalloc+0xf
netbsd`audio_stream_ctor+0x5e
netbsd`audio_setup_pfilters+0xc4
netbsd`audiosetinfo+0x64e
netbsd`audio_set_defaults+0xeb
netbsd`audio_open.part.32+0x488
netbsd`audioopen+0x101
netbsd`spec_open+0x276
netbsd`VOP_OPEN+0x4c
netbsd`vn_open+0x1ed
netbsd`do_open+0x112
netbsd`do_sys_openat+0x68
netbsd`sys_open+0x24
netbsd`syscall+0x1ec
netbsd`handle_syscall+0x2d
0 -> uvm_km_kmem_alloc size: 65536
netbsd`kmem_intr_alloc+0x6d
netbsd`kmem_intr_zalloc+0xf
netbsd`audio_stream_ctor+0x5e
netbsd`audio_setup_pfilters+0xc4
netbsd`audiosetinfo+0x64e
netbsd`audio_set_defaults+0xeb
netbsd`audio_open.part.32+0x488
netbsd`audioopen+0x101
netbsd`spec_open+0x276
netbsd`VOP_OPEN+0x4c
netbsd`vn_open+0x1ed
netbsd`do_open+0x112
netbsd`do_sys_openat+0x68
netbsd`sys_open+0x24
netbsd`syscall+0x1ec
netbsd`handle_syscall+0x2d
0 -> uvm_km_kmem_alloc size: 65536
netbsd`kmem_intr_alloc+0x6d
netbsd`kmem_intr_zalloc+0xf
netbsd`audio_stream_ctor+0x5e
netbsd`audio_setup_rfilters+0x180
netbsd`audiosetinfo+0xea8
netbsd`audio_set_defaults+0xeb
netbsd`audio_open.part.32+0x488
netbsd`audioopen+0x101
netbsd`spec_open+0x276
netbsd`VOP_OPEN+0x4c
netbsd`vn_open+0x1ed
netbsd`do_open+0x112
netbsd`do_sys_openat+0x68
netbsd`sys_open+0x24
netbsd`syscall+0x1ec
netbsd`handle_syscall+0x2d
0 -> uvm_km_kmem_alloc size: 65536
netbsd`kmem_intr_alloc+0x6d
netbsd`kmem_intr_zalloc+0xf
netbsd`audio_stream_ctor+0x5e
netbsd`audio_setup_rfilters+0x180
netbsd`audiosetinfo+0xea8
netbsd`audio_set_defaults+0xeb
netbsd`audio_open.part.32+0x488
netbsd`audioopen+0x101
netbsd`spec_open+0x276
netbsd`VOP_OPEN+0x4c
netbsd`vn_open+0x1ed
netbsd`do_open+0x112
netbsd`do_sys_openat+0x68
netbsd`sys_open+0x24
netbsd`syscall+0x1ec
netbsd`handle_syscall+0x2d
0 -> uvm_km_kmem_free size: 65536
netbsd`audio_stream_dtor+0x37
netbsd`audio_setup_pfilters+0x47b
netbsd`audiosetinfo+0x64e
netbsd`audio_ioctl+0x2a6
netbsd`audioioctl+0xe6
netbsd`sys_ioctl+0x11a
netbsd`syscall+0x1ec
netbsd`handle_syscall+0x2d
0 -> uvm_km_kmem_free size: 65536
netbsd`audio_stream_dtor+0x37
netbsd`audio_setup_pfilters+0x47b
netbsd`audiosetinfo+0x64e
netbsd`audio_ioctl+0x2a6
netbsd`audioioctl+0xe6
netbsd`sys_ioctl+0x11a
netbsd`syscall+0x1ec
netbsd`handle_syscall+0x2d
So -- 4 allocations and 2 releases.
However, I'll have to admit that I'm still not able to connect
the dots and see what's actually causing this memory leak, so
I've here just summarized the debugging done so far.
For the record, the dtrace script is
------------------------------
#pragma D option flowindent
fbt::uvm_km_kmem_alloc:entry
/arg1 > 49152 && arg1 <= 65536 /
{
printf("size: %d", arg1);
stack();
}
fbt::uvm_km_kmem_free:entry
/arg2 > 49152 && arg2 <= 65536/
{
printf("size: %d", arg2);
stack();
}
------------------------------
and run via "dtrace -s kmem.d -x nolibs > logfile 2>&1".
And lastly, here's the diff to audio.c. I've made a few of the
ouputs which appear to come "as the audio plays" dependent on
AUDIO_DEBUG >= 2, so that the setup debug info isn't drowned out.
Index: sys/dev/audio.c
===================================================================
RCS file: /cvsroot/src/sys/dev/Attic/audio.c,v
retrieving revision 1.357.2.13
diff -u -p -U 5 -r1.357.2.13 audio.c
--- sys/dev/audio.c 7 Jun 2018 18:24:16 -0000 1.357.2.13
+++ sys/dev/audio.c 20 May 2020 19:54:26 -0000
@@ -195,11 +195,11 @@ __KERNEL_RCSID(0, "$NetBSD: audio.c,v 1.
#include <uvm/uvm.h>
#include "ioconf.h"
-/* #define AUDIO_DEBUG 1 */
+#define AUDIO_DEBUG 1
#ifdef AUDIO_DEBUG
#define DPRINTF(x) if (audiodebug) printf x
#define DPRINTFN(n,x) if (audiodebug>(n)) printf x
int audiodebug = AUDIO_DEBUG;
#else
@@ -297,18 +297,18 @@ void audio_clear(struct audio_softc *, s
void audio_clear_intr_unlocked(struct audio_softc *sc,
struct virtual_channel *);
int audio_alloc_ring(struct audio_softc *, struct audio_ringbuffer *, int,
size_t);
void audio_free_ring(struct audio_softc *, struct audio_ringbuffer *);
-static int audio_setup_pfilters(struct audio_softc *, const audio_params_t *,
+int audio_setup_pfilters(struct audio_softc *, const audio_params_t *,
stream_filter_list_t *, struct virtual_channel *);
-static int audio_setup_rfilters(struct audio_softc *, const audio_params_t *,
+int audio_setup_rfilters(struct audio_softc *, const audio_params_t *,
stream_filter_list_t *, struct virtual_channel *);
static void audio_destroy_pfilters(struct virtual_channel *);
static void audio_destroy_rfilters(struct virtual_channel *);
-static void audio_stream_dtor(audio_stream_t *);
-static int audio_stream_ctor(audio_stream_t *, const audio_params_t *, int);
+void audio_stream_dtor(audio_stream_t *);
+int audio_stream_ctor(audio_stream_t *, const audio_params_t *, int);
static void stream_filter_list_append(stream_filter_list_t *,
stream_filter_factory_t, const audio_params_t *);
static void stream_filter_list_prepend(stream_filter_list_t *,
stream_filter_factory_t, const audio_params_t *);
static void stream_filter_list_set(stream_filter_list_t *, int,
@@ -1279,11 +1279,11 @@ audio_free_ring(struct audio_softc *sc,
}
r->s.start = NULL;
}
-static int
+int
audio_setup_pfilters(struct audio_softc *sc, const audio_params_t *pp,
stream_filter_list_t *pfilters, struct virtual_channel *vc)
{
stream_filter_t *pf[AUDIO_MAX_FILTERS], *of[AUDIO_MAX_FILTERS];
audio_stream_t ps[AUDIO_MAX_FILTERS], os[AUDIO_MAX_FILTERS];
@@ -1339,10 +1339,12 @@ audio_setup_pfilters(struct audio_softc
vc->sc_mpr.s.param = pfilters->filters[0].param;
vc->sc_pustream = &vc->sc_pstreams[0];
}
HW_UNLOCK(vc);
+ printf("%s: new %d, old %d\n",
+ __func__, pfilters->req_size, onfilters);
/* Destroy old filters. */
for (i = 0; i < onfilters; i++) {
of[i]->dtor(of[i]);
audio_stream_dtor(&os[i]);
}
@@ -1361,11 +1363,11 @@ audio_setup_pfilters(struct audio_softc
#endif /* AUDIO_DEBUG */
return 0;
}
-static int
+int
audio_setup_rfilters(struct audio_softc *sc, const audio_params_t *rp,
stream_filter_list_t *rfilters, struct virtual_channel *vc)
{
stream_filter_t *rf[AUDIO_MAX_FILTERS], *of[AUDIO_MAX_FILTERS];
audio_stream_t rs[AUDIO_MAX_FILTERS], os[AUDIO_MAX_FILTERS];
@@ -1439,10 +1441,12 @@ audio_setup_rfilters(struct audio_softc
audio_print_params(num, &vc->sc_rstreams[i].param);
}
}
#endif /* AUDIO_DEBUG */
+ printf("%s: new %d, old %d\n",
+ __func__, rfilters->req_size, onfilters);
/* Destroy old filters. */
for (i = 0; i < onfilters; i++) {
of[i]->dtor(of[i]);
audio_stream_dtor(&os[i]);
}
@@ -1453,10 +1457,12 @@ audio_setup_rfilters(struct audio_softc
static void
audio_destroy_pfilters(struct virtual_channel *vc)
{
int i;
+ printf("%s: npfilters %d\n",
+ __func__, vc->sc_npfilters);
for (i = 0; i < vc->sc_npfilters; i++) {
vc->sc_pfilters[i]->dtor(vc->sc_pfilters[i]);
vc->sc_pfilters[i] = NULL;
audio_stream_dtor(&vc->sc_pstreams[i]);
}
@@ -1466,33 +1472,44 @@ audio_destroy_pfilters(struct virtual_ch
static void
audio_destroy_rfilters(struct virtual_channel *vc)
{
int i;
+ printf("%s: nrfilters %d\n",
+ __func__, vc->sc_nrfilters);
for (i = 0; i < vc->sc_nrfilters; i++) {
vc->sc_rfilters[i]->dtor(vc->sc_rfilters[i]);
vc->sc_rfilters[i] = NULL;
audio_stream_dtor(&vc->sc_pstreams[i]);
}
vc->sc_nrfilters = 0;
}
-static void
+void
audio_stream_dtor(audio_stream_t *stream)
{
- if (stream->start != NULL)
+ if (stream->start != NULL) {
+ printf("%s: non-null start, size %zd\n",
+ __func__, stream->bufsize);
kmem_free(stream->start, stream->bufsize);
+ }
memset(stream, 0, sizeof(audio_stream_t));
}
-static int
+int
audio_stream_ctor(audio_stream_t *stream, const audio_params_t *param, int size)
{
int frame_size;
size = min(size, AU_RING_SIZE);
+ /* Will overwrite, may need to release */
+ if (stream->start != NULL) {
+ printf("%s: non-null start, size %zd\n",
+ __func__, stream->bufsize);
+ kmem_free(stream->start, stream->bufsize);
+ }
stream->bufsize = size;
stream->start = kmem_zalloc(size, KM_SLEEP);
frame_size = (param->precision + 7) / 8 * param->channels;
size = (size / frame_size) * frame_size;
stream->end = stream->start + size;
@@ -2432,11 +2449,11 @@ audio_drain(struct audio_softc *sc, stru
KASSERT(mutex_owned(sc->sc_lock));
KASSERT(mutex_owned(sc->sc_intr_lock));
error = 0;
- DPRINTF(("audio_drain: enter busy=%d\n", vc->sc_pbus));
+ DPRINTFN(2, ("audio_drain: enter busy=%d\n", vc->sc_pbus));
cb = &vc->sc_mpr;
if (cb->mmapped)
return 0;
used = audio_stream_get_used(&cb->s);
@@ -2501,11 +2518,11 @@ audio_drain(struct audio_softc *sc, stru
else if (sc->sc_usemixer)
drops += sc->sc_mixring.sc_mpr.blksize * PREFILL_BLOCKS;
error = 0;
while (cb->drops <= drops && !error) {
- DPRINTF(("audio_drain: vc=%p used=%d, drops=%ld\n",
+ DPRINTFN(2, ("audio_drain: vc=%p used=%d, drops=%ld\n",
vc,
audio_stream_get_used(&vc->sc_mpr.s),
cb->drops));
mutex_exit(sc->sc_intr_lock);
error = audio_waitio(sc, &sc->sc_wchan, vc);
@@ -2998,11 +3015,11 @@ audio_write(struct audio_softc *sc, stru
return 0;
}
if (!(vc->sc_mode & AUMODE_PLAY_ALL) && vc->sc_playdrop > 0) {
m = min(vc->sc_playdrop, uio->uio_resid);
- DPRINTF(("audio_write: playdrop %d\n", m));
+ DPRINTFN(2, ("audio_write: playdrop %d\n", m));
uio->uio_offset += m;
uio->uio_resid -= m;
vc->sc_playdrop -= m;
if (uio->uio_resid == 0)
return 0;
@@ -3128,11 +3145,11 @@ audio_ioctl(dev_t dev, struct audio_soft
if (!sc->sc_usemixer || chan->deschan != 0)
vc = pchan->vc;
else
vc = &sc->sc_mixring;
- DPRINTF(("audio_ioctl(%lu,'%c',%lu)\n",
+ DPRINTFN(2, ("audio_ioctl(%lu,'%c',%lu)\n",
IOCPARM_LEN(cmd), (char)IOCGROUP(cmd), cmd&0xff));
hw = sc->hw_if;
if (hw == NULL)
return ENXIO;
error = 0;
@@ -3157,18 +3174,18 @@ audio_ioctl(dev_t dev, struct audio_soft
if (*(int *)addr) {
if (sc->sc_async_audio != 0)
error = EBUSY;
else
sc->sc_async_audio = pchan->chan;
- DPRINTF(("audio_ioctl: FIOASYNC chan %d\n",
+ DPRINTFN(2, ("audio_ioctl: FIOASYNC chan %d\n",
pchan->chan));
} else
sc->sc_async_audio = 0;
break;
case AUDIO_FLUSH:
- DPRINTF(("AUDIO_FLUSH\n"));
+ DPRINTFN(2, ("AUDIO_FLUSH\n"));
rbus = vc->sc_rbus;
pbus = vc->sc_pbus;
mutex_enter(sc->sc_intr_lock);
audio_clear(sc, vc);
error = audio_initbufs(sc, vc);
@@ -3316,11 +3333,11 @@ audio_ioctl(dev_t dev, struct audio_soft
DPRINTF(("audio_ioctl: unknown ioctl\n"));
error = EINVAL;
}
break;
}
- DPRINTF(("audio_ioctl(%lu,'%c',%lu) result %d\n",
+ DPRINTFN(2, ("audio_ioctl(%lu,'%c',%lu) result %d\n",
IOCPARM_LEN(cmd), (char)IOCGROUP(cmd), cmd&0xff, error));
return error;
}
int
@@ -3582,11 +3599,11 @@ audiostartr(struct audio_softc *sc, stru
{
int error;
KASSERT(mutex_owned(sc->sc_lock));
- DPRINTF(("audiostartr: start=%p used=%d(hi=%d) mmapped=%d\n",
+ DPRINTFN(2, ("audiostartr: start=%p used=%d(hi=%d) mmapped=%d\n",
vc->sc_mrr.s.start, audio_stream_get_used(&vc->sc_mrr.s),
vc->sc_mrr.usedhigh, vc->sc_mrr.mmapped));
if (!audio_can_capture(sc))
return EINVAL;
@@ -3613,11 +3630,11 @@ audiostartp(struct audio_softc *sc, stru
KASSERT(mutex_owned(sc->sc_lock));
error = 0;
used = audio_stream_get_used(&vc->sc_mpr.s);
- DPRINTF(("audiostartp: start=%p used=%d(hi=%d blk=%d) mmapped=%d\n",
+ DPRINTFN(2, ("audiostartp: start=%p used=%d(hi=%d blk=%d) mmapped=%d\n",
vc->sc_mpr.s.start, used, vc->sc_mpr.usedhigh,
vc->sc_mpr.blksize, vc->sc_mpr.mmapped));
if (!audio_can_playback(sc))
return EINVAL;
@@ -3630,11 +3647,11 @@ audiostartp(struct audio_softc *sc, stru
else
blksize = vc->sc_mpr.blksize;
if (!vc->sc_mpr.mmapped && used < blksize) {
cv_broadcast(&sc->sc_wchan);
- DPRINTF(("%s: wakeup and return\n", __func__));
+ DPRINTFN(2, ("%s: wakeup and return\n", __func__));
return 0;
}
vc->sc_pbus = true;
if (sc->sc_trigger_started == false) {
@@ -3773,11 +3790,11 @@ audio_mix(void *v)
uint8_t *inp;
int cc, cc1, used, blksize;
sc = v;
- DPRINTF(("PINT MIX\n"));
+ DPRINTFN(2, ("PINT MIX\n"));
sc->schedule_rih = false;
sc->schedule_wih = false;
sc->sc_writeme = false;
if (sc->sc_dying == true)
Home |
Main Index |
Thread Index |
Old Index