On Sun, Dec 20, 2020 at 06:52:39PM +0000, James Cook wrote:
> On Sun, Dec 20, 2020 at 08:41:00PM +1100, Jonathan Gray wrote:
> > On Sun, Dec 20, 2020 at 06:27:33AM +0000, James Cook wrote:
> > > On Sat, Dec 19, 2020 at 07:33:42AM +0000, James Cook wrote:
> > > > > Suggestions are welcome. In the meantime I am slowly trying to debug
> > > > > this myself, mostly as a learning exercise. I've successfully built my
> > > > > own bsd.rd (using the instructions on the release(8) man page) with
> > > > > the
> > > > > intention of adding some debug output to narrow down where it's
> > > > > getting stuck, but I don't know my way around the kernel code.
> > > >
> > > > Minor progress: I have determined that the kernel gets at least as far
> > > > as exec-ing the init process (more precisely, calling sys_execve in
> > > > init_main.c).
> > >
> > > I found out init gets stuck calling sleep(2) in setctty in
> > > sbin/init/init.c. (Details below on how I determined that.)
> > >
> > > Any idea what could cause a call to sleep to just hang indefinitely?
> > >
> >
> > Can you try hpet instead of tsc?
> >
> > Either sysctl kern.timecounter.hardware=acpihpet0
>
> With (my custom) bsd.rd, that sysctl does not seem to exist, and it still
> hangs
> on boot with the below code change.
>
> With bsd.sp and bsd.mp, the sysctl was already set to acpihpet0. If I set it
> to
> tsc, then "sleep 1" gets somewhat slower but doesn't take on the order of
> minutes to an hour like it does with bsd.rd.
>
> If it's relevant: I noticed the time reported by the "date" command advances
> normally with bsd.sp/bsd.mp and acpihpet0 (I ran two date commands 15s apart
> according to my phone timer, and got dates 15s apart). With the sysctl set to
> tsc, or with bsd.rd, the time returned by date advances slowly.
>
> (With bsd.sp and bsd.mp, I tried "disable acpihpet*" at the boot_config
> prompt,
> but the sysctl was still set to acpihpet0 when I booted.)
Sorry Jonathan, I somehow didn't include you in my reply, which is
quoted above.
I have a bit more data to share.
It appears bsd.rd's tsleep_nsec is sleeping for about 2.5x as long as
needed, but its uptime increases at only 1/2500 the rate of real time,
so sys_nanosleep is calling tsleep_nsec about 1000 times to compensate.
(I didn't wait around for all 1000 loop iterations).
By contrast, bsd.sp's tsleep_nsec sleeps for about 4.2x as long as
requested, but it is able to measure real time accurately.
Based on my previous email, I guess bsd.rd is using tsc and bsd.sp is
using hpet.
In more detail:
I added some debug output to the sys_nanosleep function, printing the
"start" and "end" values returned by getnanouptime on each iteration of
the loop. Diff at bottom of email.
I've summarized in these two tables and explained them in the text
below.
bsd.rd:
requested nsecs | actual time per loop iteration | end - start
----------------+--------------------------------+-------------
2000000000 | 5s | 2ms
bsd.sp:
requested nsecs | end - start (plausibly matches actual time)
----------------+--------------------------------------------
1000000000 | 4.22s
2000000000 | 8.40s
5000000000 | 20.93s
10000000000 | 41.82s
requested nsecs:
This is the "nsecs" variable in the inner loop, matching what was
passed to the nanosleep system call. In the case of bsd.rd, I list the
value from the first loop iteration; for bsd.sp, there was always just
one iteration.
end - start:
This is the difference between the "stop" and "start" timespecs, filled
by getnanouptime before and after the call to tsleep_nsec.
Note that for bsd.rd, it only goes up by 2ms, only 1/1000 of what was
requested.
For bsd.sp, it seems to be about 0.04 + 4.18 * (requested time).
"actual time per loop iteration":
For bsd.rd, each loop iteration takes about 5s (as measured by my
phone's timer). So, real time is passing about 2500x as fast as the
kernel thinks it is.
As far as I can tell, bsd.sp measures real time intervals accurately
(as reported by date, or by comparing end-start to my phone's timer).
diff --git a/sys/kern/kern_time.c b/sys/kern/kern_time.c
index d34329ee642..8c63dfa462a 100644
--- a/sys/kern/kern_time.c
+++ b/sys/kern/kern_time.c
@@ -293,9 +293,12 @@ sys_nanosleep(struct proc *p, void *v, register_t *retval)
do {
getnanouptime(&start);
+ printf("YYY sys_nanosleep: start is %10llds + %9ldns\n",
start.tv_sec, start.tv_nsec);
nsecs = MAX(1, MIN(TIMESPEC_TO_NSEC(&request), MAXTSLP));
+ printf("YYY sys_nanosleep: calling tsleep_nsec with nsecs =
%llud\n", nsecs);
error = tsleep_nsec(&chan, PWAIT | PCATCH, "nanosleep", nsecs);
getnanouptime(&stop);
+ printf("YYY sys_nanosleep: finished tsleep_nsec; stop is
%10llds + %9ldns\n", stop.tv_sec, stop.tv_nsec);
timespecsub(&stop, &start, &elapsed);
timespecsub(&request, &elapsed, &request);
if (request.tv_sec < 0)
@@ -303,6 +306,7 @@ sys_nanosleep(struct proc *p, void *v, register_t *retval)
if (error != EWOULDBLOCK)
break;
} while (timespecisset(&request));
+ printf("YYY sys_nanosleep: finished loop\n");
if (error == ERESTART)
error = EINTR;
