On Tue, Dec 22, 2020 at 02:56:58AM +0000, James Cook wrote:
> 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).
I'm not sure if it will change anything but if the problem is with
tsc perhaps this will help?
Index: sys/arch/amd64/amd64/tsc.c
===================================================================
RCS file: /cvs/src/sys/arch/amd64/amd64/tsc.c,v
retrieving revision 1.21
diff -u -p -r1.21 tsc.c
--- sys/arch/amd64/amd64/tsc.c 6 Sep 2020 20:50:00 -0000 1.21
+++ sys/arch/amd64/amd64/tsc.c 20 Dec 2020 09:29:16 -0000
@@ -72,6 +72,7 @@ tsc_freq_cpuid(struct cpu_info *ci)
case 0x5e: /* Skylake desktop */
case 0x8e: /* Kabylake mobile */
case 0x9e: /* Kabylake desktop */
+ case 0xa6: /* Coffeelake mobile */
khz = 24000; /* 24.0 MHz */
break;
case 0x5f: /* Atom Denverton */
