Date: Fri, 22 Mar 2024 10:51:29 -0700 From: Mark Millard <marklmi@yahoo.com> To: freebsd-hackers <freebsd-hackers@freebsd.org>, FreeBSD ARM List <freebsd-arm@freebsd.org> Subject: Re: main aarch64: poudriere-devel [UFS context] cpdup stuck in pgnslp state [any more useful information to extract via kgdb?] Message-ID: <A39DEDD7-543B-4C27-8E97-4FB8722F8092@yahoo.com> In-Reply-To: <C272360B-AAD2-4188-B3B6-22DB60AE0BB3@yahoo.com> References: <C272360B-AAD2-4188-B3B6-22DB60AE0BB3@yahoo.com>
next in thread | previous in thread | raw e-mail | index | archive | help
[Adding some information from kgdb. Switch to freebsd-hackers and
(still) freebsd-arm. I also ask if there is more useful information
to extract via kgdb.]
On Mar 21, 2024, at 17:34, Mark Millard <marklmi@yahoo.com> wrote:
> Note, more recent process creations towards top, older ones towards =
bottom:
>=20
> PID JID USERNAME PRI NICE SIZE RES STATE C TIME =
CPU COMMAND
> . . .
> 33693 19 root 68 0 6524Ki 3252Ki wait 3 0:00 =
0.00% /usr/bin/make -C /usr/ports/lang/gcc13 build
> 33692 0 root 68 0 15728Ki 3552Ki wait 0 0:00 =
0.00% sh: poudriere[main-CA7-default][02]: build_pkg (gcc13-13.2.0_4) =
(sh)
> 30174 0 root 68 0 15728Ki 3564Ki select 3 0:00 =
0.00% sh: poudriere[main-CA7-default][02]: build_pkg (gcc13-13.2.0_4) =
(sh)
> 26338 0 root 66 0 17740Ki 5044Ki pgnslp 0 0:01 =
0.00% cpdup -i0 -s0 -f -x ref 01
> 26308 0 root 68 0 15728Ki 3556Ki wait 0 0:00 =
0.00% sh: poudriere[main-CA7-default][01]: build_pkg =
(boost-libs-1.84.0) (sh)
> 33592 0 root 26 0 15728Ki 3388Ki piperd 2 0:01 =
0.00% sh: poudriere[main-CA7-default]: pkg_cacher_main (sh)
> 29205 0 root 68 0 15728Ki 3392Ki nanslp 2 1:52 =
0.14% sh: poudriere[main-CA7-default]: html_json_main (sh)
> 28834 0 root 20 0 15728Ki 3548Ki select 3 0:01 =
0.00% /usr/local/libexec/poudriere/sh -e =
/usr/local/share/poudriere/bulk.sh -jmain-CA7 -c -f =
/root/origins/CA7-origins.txt
> 28833 0 root 20 0 13560Ki 1924Ki wait 3 0:00 =
0.00% /bin/sh /root/build-ports-main-CA7.sh -c
> . . .
>=20
> pgnslp seems to be from: vm_page_acquire_unlocked in sys/vm/vm_page.c =
.
> That in turn looks to be using vm_page_grab_sleep :
>=20
> if (!vm_page_grab_sleep(object, m, pindex, "pgnslp",
> allocflags, false))
> return (false);
>=20
> and:
>=20
> /*
> * vm_page_grab_sleep
> *
> * Sleep for busy according to VM_ALLOC_ parameters. Returns true
> * if the caller should retry and false otherwise.
> *
> * If the object is locked on entry the object will be unlocked =
with
> * false returns and still locked but possibly having been dropped
> * with true returns.
> */
> static bool
> vm_page_grab_sleep(vm_object_t object, vm_page_t m, vm_pindex_t =
pindex,
> const char *wmesg, int allocflags, bool locked)
> {
>=20
> if ((allocflags & VM_ALLOC_NOWAIT) !=3D 0)
> return (false);
>=20
> /*
> * Reference the page before unlocking and sleeping so that
> * the page daemon is less likely to reclaim it.
> */
> if (locked && (allocflags & VM_ALLOC_NOCREAT) =3D=3D 0)
> vm_page_reference(m);
>=20
> if (_vm_page_busy_sleep(object, m, pindex, wmesg, allocflags, =
locked) &&
> locked)
> VM_OBJECT_WLOCK(object);
> if ((allocflags & VM_ALLOC_WAITFAIL) !=3D 0)
> return (false);
>=20
> return (true);
> }
>=20
> . . .
> [10:08:06] [01] [00:00:00] Building devel/boost-libs | =
boost-libs-1.84.0
> . . .
>=20
> # poudriere status -b
> [main-CA7-default] [2024-03-21_06h23m31s] [parallel_build] Queued: 265 =
Built: 213 Failed: 0 Skipped: 0 Ignored: 0 Fetched: 0 Tobuild: =
52 Time: 10:50:40
> ID TOTAL ORIGIN PKGNAME =
PHASE TIME TMPFS CPU% MEM%
> [01] 00:42:40 devel/boost-libs | boost-libs-1.84.0 =
starting 00:42:40 951.54 MiB =20
> . . .
>=20
> Unfortunately:
>=20
> A) The booted kernel is my personal build based on -mcpu=3Dcortex-a76
> and LSE_ATOMICS . (It is in use on a RPi5 booted via EDK2.)
>=20
> B) The booted world is a PkgBase world.
>=20
> C) The poudriere jail's world directory tree is my personal armv7
> world build based on -mcpu=3Dcortex-a7 .
>=20
> All are based on: main-n268827-75464941dc17 . (Well, PkgBase
> commit identification/verification for world does not exist.
> I happened to update PkgBase during a long lull for commits
> to main. In the context, the boot-world seems unlikely to be
> involved here.)
>=20
> The boot media is a U2 Optane 960 GB used via a USB3 adaptor.
>=20
> I've done bunches of builds in the (A)-(C) context on the RPi5
> and have not seen this before, so: does not look to be readily
> repeatable.
>=20
> (Unfortunately, the purpose of the build was to find out how long
> the particular build configuration took to finish building the
> 265 packages from scratch, for comparison to other builds.)
>=20
> I may wait for the system to become fairly idle and then see about
> forcing a crash dump. It may be a while before the poudriere bulk
> runs out of packages it can build, absent building boost-libs .
>=20
>=20
> Side note:
> As far as I can tell, how to identify a context that allows
> identification of what commit vintage a PkgBase world is based on
> is unspecified so far. For a PkgBase kernel uname -apKU may well
> report the kernel-commit identification well. (Hard to verify.)
The cpdup kernel thread backtrace follows. The kernel build was
NODEBUG and optimatized, but with debug information still produced.
This can lead to somewhat messy information but is better than
not having the information.
(kgdb) thread 145
[Switching to thread 145 (Thread 361925)]
#0 sched_switch (td=3Dtd@entry=3D0xffff0000dfaf8c80, =
flags=3Dflags@entry=3D259) at /usr/main-src/sys/kern/sched_ule.c:2290
2290 cpuid =3D td->td_oncpu =3D PCPU_GET(cpuid);
(kgdb) bt
#0 sched_switch (td=3Dtd@entry=3D0xffff0000dfaf8c80, =
flags=3Dflags@entry=3D259) at /usr/main-src/sys/kern/sched_ule.c:2290
#1 0xffff0000004f5f2c in mi_switch (flags=3Dflags@entry=3D259) at =
/usr/main-src/sys/kern/kern_synch.c:546
#2 0xffff00000054ea28 in sleepq_switch (wchan=3D<optimized out>, =
pri=3D<optimized out>) at /usr/main-src/sys/kern/subr_sleepqueue.c:607
#3 0xffff00000054e8f8 in sleepq_wait (wchan=3D<unavailable>, =
wchan@entry=3D0xffffa001fae26630, pri=3D<unavailable>, pri@entry=3D52) =
at /usr/main-src/sys/kern/subr_sleepqueue.c:658
#4 0xffff00000084e768 in _vm_page_busy_sleep (obj=3D<optimized out>, =
obj@entry=3D0xffffa0012aab9528, m=3Dm@entry=3D0xffffa001fae26630, =
pindex=3Dpindex@entry=3D0, wmesg=3D0xffff0000009c6297 "pgnslp", =
allocflags=3Dallocflags@entry=3D21504, locked=3D<optimized out>) at =
/usr/main-src/sys/vm/vm_page.c:1100
#5 0xffff0000008548e4 in vm_page_grab_sleep (object=3D0xffffa0012aab9528,=
m=3D0xffffa001fae26630, pindex=3D0, allocflags=3D21504, locked=3Dfalse, =
wmesg=3D<optimized out>) at /usr/main-src/sys/vm/vm_page.c:4547
#6 vm_page_acquire_unlocked (object=3Dobject@entry=3D0xffffa0012aab9528, =
pindex=3Dpindex@entry=3D0, prev=3D<optimized out>, =
prev@entry=3D0xffff0000e04c5570, mp=3Dmp@entry=3D0xffff0000e04c55b8, =
allocflags=3D21504)
at /usr/main-src/sys/vm/vm_page.c:4690
#7 0xffff0000008552c4 in vm_page_grab_valid_unlocked =
(mp=3Dmp@entry=3D0xffff0000e04c55b8, =
object=3Dobject@entry=3D0xffffa0012aab9528, pindex=3Dpindex@entry=3D0, =
allocflags=3Dallocflags@entry=3D21504)
at /usr/main-src/sys/vm/vm_page.c:4871
#8 0xffff0000005949e8 in uiomove_object_page (obj=3D0xffffa0012aab9528, =
len=3D<unavailable>, uio=3D0xffff0000e04c57d8) at =
/usr/main-src/sys/kern/uipc_shm.c:207
#9 uiomove_object (obj=3D0xffffa0012aab9528, obj@entry=3D<error reading =
variable: value is not available>, obj_size=3D29352, =
obj_size@entry=3D<error reading variable: value is not available>, =
uio=3D0xffff0000e04c57d8, uio@entry=3D<error reading variable: value is =
not available>) at /usr/main-src/sys/kern/uipc_shm.c:268
#10 0xffff0000009b8a54 in VOP_READ_APV (vop=3D0xffff000000c8c038 =
<tmpfs_vnodeop_entries>, a=3Da@entry=3D0xffff0000e04c5658) at =
vnode_if.c:1048
#11 0xffff0000005fd630 in VOP_READ (vp=3D0xffffa00129280540, =
uio=3D0xffff0000e04c57d8, ioflag=3D327680, cred=3D<unavailable>) at =
./vnode_if.h:537
#12 vn_read (fp=3Dfp@entry=3D0xffffa0007492bdc0, =
uio=3Duio@entry=3D0xffff0000e04c57d8, =
active_cred=3Dactive_cred@entry=3D0xffffa0010ab5f400, flags=3D<optimized =
out>, td=3D<optimized out>)
at /usr/main-src/sys/kern/vfs_vnops.c:1123
#13 0xffff0000005f5598 in vn_io_fault (fp=3D0xffffa0007492bdc0, =
fp@entry=3D<error reading variable: value is not available>, =
uio=3D0xffff0000e04c57d8, uio@entry=3D<error reading variable: =
value is not available>, active_cred=3D0xffffa0010ab5f400, =
active_cred@entry=3D<error reading variable: value is not available>, =
flags=3D0, flags@entry=3D<error reading variable: value is not =
available>, td=3D0xffff0000dfaf8c80, td@entry=3D<error reading variable: =
value is not available>) at /usr/main-src/sys/kern/vfs_vnops.c:1504
#14 0xffff000000562ed4 in fo_read (fp=3D0xffffa0007492bdc0, =
uio=3D0xffff0000e04c57d8, active_cred=3D<unavailable>, flags=3D0, =
td=3D0xffff0000dfaf8c80) at /usr/main-src/sys/sys/file.h:344
#15 dofileread (td=3Dtd@entry=3D0xffff0000dfaf8c80, fd=3Dfd@entry=3D3, =
fp=3D0xffffa0007492bdc0, auio=3Dauio@entry=3D0xffff0000e04c57d8, =
offset=3D<optimized out>, flags=3D0, flags@entry=3D-531867712)
at /usr/main-src/sys/kern/sys_generic.c:366
#16 0xffff000000562a00 in kern_readv (td=3D0xffff0000dfaf8c80, fd=3D3, =
auio=3D0xffff0000e04c57d8) at /usr/main-src/sys/kern/sys_generic.c:287
#17 sys_read (td=3D0xffff0000dfaf8c80, td@entry=3D<error reading =
variable: value is not available>, uap=3D<unavailable>, uap@entry=3D<error=
reading variable: value is not available>)
at /usr/main-src/sys/kern/sys_generic.c:203
#18 0xffff00000089f9b4 in syscallenter (td=3D0xffff0000dfaf8c80) at =
/usr/main-src/sys/arm64/arm64/../../kern/subr_syscall.c:186
#19 svc_handler (td=3D0xffff0000dfaf8c80, frame=3D<optimized out>) at =
/usr/main-src/sys/arm64/arm64/trap.c:198
#20 do_el0_sync (td=3D0xffff0000dfaf8c80, frame=3D<optimized out>) at =
/usr/main-src/sys/arm64/arm64/trap.c:640
#21 <signal handler called>
#22 0x00000000271dd394 in ?? ()
#23 0x0000000026e3071c in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt =
stack?)
(kgdb) frame 4
#4 0xffff00000084e768 in _vm_page_busy_sleep (obj=3D<optimized out>, =
obj@entry=3D0xffffa0012aab9528, m=3Dm@entry=3D0xffffa001fae26630, =
pindex=3Dpindex@entry=3D0, wmesg=3D0xffff0000009c6297 "pgnslp", =
allocflags=3Dallocflags@entry=3D21504, locked=3D<optimized out>) at =
/usr/main-src/sys/vm/vm_page.c:1100
1100 sleepq_wait(m, PVM);
FYI:
. . .
} while (!atomic_fcmpset_int(&m->busy_lock, &x, x | =
VPB_BIT_WAITERS));
if (locked)
VM_OBJECT_DROP(obj);
DROP_GIANT();
sleepq_add(m, NULL, wmesg, 0, 0);
sleepq_wait(m, PVM);
PICKUP_GIANT();
return (true);
}
. . .
(kgdb) print /x *m
$2 =3D {plinks =3D {q =3D {tqe_next =3D 0xffffa001fc7c31c0, tqe_prev =3D =
0xffffa001ff85d2d0}, s =3D {ss =3D {sle_next =3D 0xffffa001fc7c31c0}}, =
memguard =3D {p =3D 0xffffa001fc7c31c0, v =3D 0xffffa001ff85d2d0}, uma =3D=
{
slab =3D 0xffffa001fc7c31c0, zone =3D 0xffffa001ff85d2d0}}, listq =
=3D {tqe_next =3D 0xffffa001ff85d2d0, tqe_prev =3D 0xffffa0012aab9570}, =
object =3D 0xffffa0012aab9528, pindex =3D 0x0, phys_addr =3D =
0x12a816000, md =3D {pv_list =3D {tqh_first =3D 0x0, tqh_last =3D =
0xffffa001fae26668}, pv_gen =3D 0x15fd, pv_memattr =3D 0x2}, ref_count =3D=
0x80000000, busy_lock =3D 0x1, a =3D {{flags =3D 0x208, queue =3D =
0x1, act_count =3D 0x1}, _bits =3D 0x1010208}, order =3D 0xd, pool =3D =
0x0, flags =3D 0x1, oflags =3D 0x0, psind =3D 0x0, segind =3D 0x8, valid =
=3D 0xff, dirty =3D 0x0}
Any more potentially useful information to extract via kgdb?
=3D=3D=3D
Mark Millard
marklmi at yahoo.com
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?A39DEDD7-543B-4C27-8E97-4FB8722F8092>