Date: Tue, 26 Feb 2019 04:29:44 -0800 From: Mark Millard <marklmi@yahoo.com> To: Justin Hibbits <chmeeedalf@gmail.com>, FreeBSD PowerPC ML <freebsd-ppc@freebsd.org>, freebsd-hackers Hackers <freebsd-hackers@freebsd.org> Subject: The FreeBSD code structure that sometimes break powerpc64's pmac_thermal, buf*daemon* threads, etc. (stuck sleeping) Message-ID: <1C8071BF-5B3B-416D-8CE4-437D4555EEB5@yahoo.com>
next in thread | raw e-mail | index | archive | help
[head -r334018 based. I temporarily changed what messaging
happens for KTR_PROC in order to gather information. As stands
it was reporting on pmac_thermal because I can listen for the
fans to know the stuck-sleeping has happened recently.]
A powerpc64 sleepq_timeout callout usage has the structure:
0xe00000009af7c730: at sleepq_timeout+0x148
0xe00000009af7c7d0: at softclock_call_cc+0x234
0xe00000009af7c910: at callout_process+0x2e0
0xe00000009af7c9f0: at handleevents+0x22c
0xe00000009af7caa0: at timercb+0x340
0xe00000009af7cba0: at decr_intr+0x140
0xe00000009af7cbd0: at powerpc_interrupt+0x268
timercb does:
now =3D sbinuptime();
. . .
handleevents(now, 0);
That in turn leads to:
if (now >=3D state->nextcallopt || now >=3D state->nextcall) {
state->nextcall =3D state->nextcallopt =3D SBT_MAX;
callout_process(now);
}
Which leads to:
if (tmp->c_time <=3D now) {
. . .
if (tmp->c_iflags & CALLOUT_DIRECT) {
. . .
softclock_call_cc(tmp, cc,
#ifdef CALLOUT_PROFILING
&mpcalls_dir, =
&lockcalls_dir, NULL,
#endif
1);
So softclock_call_cc and sleepq_timeout do not get a copy
of timercb 's now value. (I will refer to this now value
in contexts for which it is not accessible.)
sleepq_timeout uses:
td->td_sleeptimo > sbinuptime()
to indicate to not do something like:
sleepq_resume_thread(. . .)
but also does not use sleepq_set_timeout_sbt to
set up another sleepq_timeout callout or do some
other such under this condition. (So a what is
effectively a no-op ends up the last activity
before the thread is stuck asleep.)
(I will continue to write sbinuptime() to reference
the value used in that test.)
With multiple processors, it is observed that,
despite sbinuptime() being physically later:
sbinuptime() < now
does sometimes happen for the code involved,
for example:
sbinuptime(): 0x11abf13bd142
now : 0x11accb5df419
This is even though:
tmp->c_time =3D=3D td->td_sleeptimo
is observed. sbinuptime() < now sometimes leads
to:
sbinuptime() < tmp->c_time =3D=3D td->td_sleeptimo <=3D now
for example the following happened:
sbinuptime(): 0x11abf13bd142
tmp->c_time : 0x11ac2096af71 [=3D=3D td->td_sleeptimo]
now : 0x11accb5df419
As I understand, keeping the various
powerpc64 CPUs' sbinuptime() values fully
synchronized is unlikely so the problem would
still exist even if "closer but not identical"
across CPUs was achieved.
[The testing context here is an old PowerMac G5
4-core (system total), which actually involves
2 sockets, 2 cores per socket.]
Overall this structure does not seemed to be
designed to handle variations in sbinuptime()
values across CPUs.
The sleepq_timeout source code (before my
limited modifications for reporting more):
static void
sleepq_timeout(void *arg)
{
struct sleepqueue_chain *sc __unused;
struct sleepqueue *sq;
struct thread *td;
void *wchan;
int wakeup_swapper;
td =3D arg;
wakeup_swapper =3D 0;
CTR3(KTR_PROC, "sleepq_timeout: thread %p (pid %ld, %s)",
(void *)td, (long)td->td_proc->p_pid, (void *)td->td_name);
thread_lock(td);
=20
if (td->td_sleeptimo > sbinuptime() || td->td_sleeptimo =3D=3D =
0) {
/*
* The thread does not want a timeout (yet).
*/
} else if (TD_IS_SLEEPING(td) && TD_ON_SLEEPQ(td)) {
/*
* See if the thread is asleep and get the wait
* channel if it is.
*/
wchan =3D td->td_wchan;
sc =3D SC_LOOKUP(wchan);
THREAD_LOCKPTR_ASSERT(td, &sc->sc_lock);
sq =3D sleepq_lookup(wchan);
MPASS(sq !=3D NULL);
td->td_flags |=3D TDF_TIMEOUT;
wakeup_swapper =3D sleepq_resume_thread(sq, td, 0);
} else if (TD_ON_SLEEPQ(td)) {
/*
* If the thread is on the SLEEPQ but isn't sleeping
* yet, it can either be on another CPU in between
* sleepq_add() and one of the sleepq_*wait*()
* routines or it can be in sleepq_catch_signals().
*/
td->td_flags |=3D TDF_TIMEOUT;
}
thread_unlock(td);
if (wakeup_swapper)
kick_proc0();
}
I wonder if just not having:
td->td_sleeptimo > sbinuptime() ||
in the if (. . .) is appropriate for the powerpc64 context in
use: presume callout_process 's tmp->c_time <=3D now is
sufficient? (Vs: race issues?)
Adjusted KTR_PROC output example ("show ktr /v" in ddb
captured, so newest to oldest order, flags and such are
in hex despite my not providing 0x prefixes):
922 (0xc00000000d12f000:cpu3) 151713214399 =
/usr/src/sys/kern/subr_sleepqueue.c.1027: sleepq_timeout thread not want =
timeout yet: thread 0xc00000000a8315a0 (pid 26, pmac_thermal) =
td_sleeptimo=3D11ac2096af71 sbinuptime=3D11abf13bd142
921 (0xc00000000d12f000:cpu3) 151713214374 =
/usr/src/sys/kern/subr_sleepqueue.c.1016: sleepq_timeout: thread =
0xc00000000a8315a0 (pid 26, pmac_thermal)
920 (0xc00000000d12f000:cpu3) 151713214337 =
/usr/src/sys/kern/kern_timeout.c.503: callout_process to call =
softclock_clock_cc: thread 0xc00000000a8315a0 c_time=3D11ac2096af71 =
now=3D11accb5df419
919 (0xc00000000a8315a0:cpu3) 151686051357 =
/usr/src/sys/kern/kern_synch.c.435: mi_switch: old thread 100078 =
(td_sched 0xc00000000a831ad8, pid 26, pmac_thermal)
918 (0xc00000000a8315a0:cpu3) 151686051310 =
/usr/src/sys/kern/subr_sleepqueue.c.409: sleepq_set_timeout_sbt: =
sbt=3Dfffffed8 pr=3D0 flags=3D100 td_sleeptimo=3D11ac2096af71 =
prec=3Dfffffed flags=3D501
917 (0xc00000000a8315a0:cpu3) 151686051306 =
/usr/src/sys/kern/subr_sleepqueue.c.407: sleepq_set_timeout_sbt =
installing sleepq_timeout: thread 0xc00000000a8315a0 (pid 26, =
pmac_thermal)
916 (0xc00000000a8315a0:cpu3) 151686051267 =
/usr/src/sys/kern/kern_synch.c.180: sleep: thread 100078 (pid 26, =
pmac_thermal) on pmac_therm (0xc0000000015082c3)
915 (0xc00000000a8315a0:cpu3) 151686051162 =
/usr/src/sys/kern/subr_sleepqueue.c.631: sleepq resume: thread =
0xc00000000a8315a0 (pid 26, pmac_thermal)
914 (0xc00000000a8315a0:cpu3) 151686051144 =
/usr/src/sys/kern/kern_synch.c.445: mi_switch: new thread 100078 =
(td_sched 0xc00000000a831ad8, pid 26, pmac_thermal)
913 (0xc000000001f6e000:cpu0) 151686050654 =
/usr/src/sys/kern/subr_sleepqueue.c.837: sleepq_wakeup: thread =
0xc00000000a8315a0 (pid 26, pmac_thermal)
912 (0xc000000001f6e000:cpu0) 151686050634 =
/usr/src/sys/kern/subr_sleepqueue.c.989: sleepq_remove_matching calling =
sleepq_resume_thread: thread 0xc00000000a8315a0 (pid 26, pmac_thermal)
911 (0xc00000000a8315a0:cpu3) 151684339557 =
/usr/src/sys/kern/kern_synch.c.435: mi_switch: old thread 100078 =
(td_sched 0xc00000000a831ad8, pid 26, pmac_thermal)
910 (0xc00000000a8315a0:cpu3) 151684339525 =
/usr/src/sys/kern/subr_sleepqueue.c.409: sleepq_set_timeout_sbt: =
sbt=3Dcccccbe0 pr=3D0 flags=3D100 td_sleeptimo=3D11abe0139d4d =
prec=3Dcccccbe flags=3D501
909 (0xc00000000a8315a0:cpu3) 151684339517 =
/usr/src/sys/kern/subr_sleepqueue.c.407: sleepq_set_timeout_sbt =
installing sleepq_timeout: thread 0xc00000000a8315a0 (pid 26, =
pmac_thermal)
908 (0xc00000000a8315a0:cpu3) 151684339498 =
/usr/src/sys/kern/kern_synch.c.180: sleep: thread 100078 (pid 26, =
pmac_thermal) on smu (0xe000000087fd1670)
907 (0xc00000000a8315a0:cpu3) 151684339326 =
/usr/src/sys/kern/subr_sleepqueue.c.631: sleepq resume: thread =
0xc00000000a8315a0 (pid 26, pmac_thermal)
906 (0xc00000000a8315a0:cpu3) 151684339313 =
/usr/src/sys/kern/kern_synch.c.445: mi_switch: new thread 100078 =
(td_sched 0xc00000000a831ad8, pid 26, pmac_thermal)
905 (0xc000000001f6e000:cpu3) 151684338924 =
/usr/src/sys/kern/subr_sleepqueue.c.837: sleepq_wakeup: thread =
0xc00000000a8315a0 (pid 26, pmac_thermal)
904 (0xc000000001f6e000:cpu3) 151684338918 =
/usr/src/sys/kern/subr_sleepqueue.c.989: sleepq_remove_matching calling =
sleepq_resume_thread: thread 0xc00000000a8315a0 (pid 26, pmac_thermal)
903 (0xc00000000a8315a0:cpu3) 151682628069 =
/usr/src/sys/kern/kern_synch.c.435: mi_switch: old thread 100078 =
(td_sched 0xc00000000a831ad8, pid 26, pmac_thermal)
902 (0xc00000000a8315a0:cpu3) 151682628004 =
/usr/src/sys/kern/subr_sleepqueue.c.409: sleepq_set_timeout_sbt: =
sbt=3Dcccccbe0 pr=3D0 flags=3D100 td_sleeptimo=3D11abd3054758 =
prec=3Dcccccbe flags=3D501
901 (0xc00000000a8315a0:cpu3) 151682628000 =
/usr/src/sys/kern/subr_sleepqueue.c.407: sleepq_set_timeout_sbt =
installing sleepq_timeout: thread 0xc00000000a8315a0 (pid 26, =
pmac_thermal)
900 (0xc00000000a8315a0:cpu3) 151682627960 =
/usr/src/sys/kern/kern_synch.c.180: sleep: thread 100078 (pid 26, =
pmac_thermal) on smu (0xe000000087fd1670)
899 (0xc00000000a8315a0:cpu3) 151682627706 =
/usr/src/sys/kern/subr_sleepqueue.c.631: sleepq resume: thread =
0xc00000000a8315a0 (pid 26, pmac_thermal)
898 (0xc00000000a8315a0:cpu3) 151682627683 =
/usr/src/sys/kern/kern_synch.c.445: mi_switch: new thread 100078 =
(td_sched 0xc00000000a831ad8, pid 26, pmac_thermal)
897 (0xc000000001f6e000:cpu0) 151682627254 =
/usr/src/sys/kern/subr_sleepqueue.c.837: sleepq_wakeup: thread =
0xc00000000a8315a0 (pid 26, pmac_thermal)
896 (0xc000000001f6e000:cpu0) 151682627242 =
/usr/src/sys/kern/subr_sleepqueue.c.989: sleepq_remove_matching calling =
sleepq_resume_thread: thread 0xc00000000a8315a0 (pid 26, pmac_thermal)
895 (0xc00000000a8315a0:cpu0) 151680915222 =
/usr/src/sys/kern/kern_synch.c.435: mi_switch: old thread 100078 =
(td_sched 0xc00000000a831ad8, pid 26, pmac_thermal)
894 (0xc00000000a8315a0:cpu0) 151680915139 =
/usr/src/sys/kern/subr_sleepqueue.c.409: sleepq_set_timeout_sbt: =
sbt=3Dcccccbe0 pr=3D0 flags=3D100 td_sleeptimo=3D11abc5f6f163 =
prec=3Dcccccbe flags=3D501
893 (0xc00000000a8315a0:cpu0) 151680915133 =
/usr/src/sys/kern/subr_sleepqueue.c.407: sleepq_set_timeout_sbt =
installing sleepq_timeout: thread 0xc00000000a8315a0 (pid 26, =
pmac_thermal)
892 (0xc00000000a8315a0:cpu0) 151680915085 =
/usr/src/sys/kern/kern_synch.c.180: sleep: thread 100078 (pid 26, =
pmac_thermal) on smu (0xe000000087fd1670)
891 (0xc00000000a8315a0:cpu0) 151680914811 =
/usr/src/sys/kern/subr_sleepqueue.c.631: sleepq resume: thread =
0xc00000000a8315a0 (pid 26, pmac_thermal)
890 (0xc00000000a8315a0:cpu0) 151680914784 =
/usr/src/sys/kern/kern_synch.c.445: mi_switch: new thread 100078 =
(td_sched 0xc00000000a831ad8, pid 26, pmac_thermal)
889 (0xc000000001f6e000:cpu2) 151680914304 =
/usr/src/sys/kern/subr_sleepqueue.c.837: sleepq_wakeup: thread =
0xc00000000a8315a0 (pid 26, pmac_thermal)
888 (0xc000000001f6e000:cpu2) 151680914284 =
/usr/src/sys/kern/subr_sleepqueue.c.989: sleepq_remove_matching calling =
sleepq_resume_thread: thread 0xc00000000a8315a0 (pid 26, pmac_thermal)
. . .
=3D=3D=3D
Mark Millard
marklmi at yahoo.com
( dsl-only.net went
away in early 2018-Mar)
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?1C8071BF-5B3B-416D-8CE4-437D4555EEB5>