Re: A sparc oddity (hair-pulling bug)
> However, are there any other similar fallouts outside this initmsgbuf() > situation? There is only a risk on platforms where initmsgbuf() is invoked in (or before) pmap_bootstrap(), and where curcpu() will not necessarily point into the kernel data section for the boot processor. That description only matches sparc*.
Re: A sparc oddity (hair-pulling bug)
On Thu, Jan 07, 2021 at 11:51:02AM -, Miod Vallat wrote:
>
> >> Indeed. Wrappinge the mutex operations in msgbuf_putchar with if (!cold)
> >> makes the kernel boot again.
> >
> > Here is a diff for that.
>
> After a bit more thinking, it might be worth introduce a
> msgbuf_putchar_unlocked() routine for the inner part only, and have
> initmsgbuf() use it, since:
> - it has made sure the magic value test will suceed.
> - this is the only use of msgbuf_putchar() on sparc64 until the proper
> curcpu mappings are set up; all output from pmap_bootstrap() carefully
> uses the prom routines (and do not end up in the message buffer).
Here is a diff.
However, are there any other similar fallouts outside this initmsgbuf()
situation?
Index: kern/subr_log.c
===
RCS file: src/sys/kern/subr_log.c,v
retrieving revision 1.70
diff -u -p -r1.70 subr_log.c
--- kern/subr_log.c 25 Dec 2020 12:59:52 - 1.70
+++ kern/subr_log.c 7 Jan 2021 13:21:45 -
@@ -109,6 +109,7 @@ const struct filterops logread_filtops =
int dosendsyslog(struct proc *, const char *, size_t, int, enum uio_seg);
void logtick(void *);
size_t msgbuf_getlen(struct msgbuf *);
+void msgbuf_putchar_locked(struct msgbuf *, const char);
void
initmsgbuf(caddr_t buf, size_t bufsize)
@@ -137,9 +138,13 @@ initmsgbuf(caddr_t buf, size_t bufsize)
mbp->msg_bufs = new_bufs;
}
- /* Always start new buffer data on a new line. */
+ /*
+* Always start new buffer data on a new line.
+* Avoid using log_mtx because mutexes do not work during early boot
+* on some architectures.
+*/
if (mbp->msg_bufx > 0 && mbp->msg_bufc[mbp->msg_bufx - 1] != '\n')
- msgbuf_putchar(msgbufp, '\n');
+ msgbuf_putchar_locked(mbp, '\n');
/* mark it as ready for use. */
msgbufmapped = 1;
@@ -162,6 +167,13 @@ msgbuf_putchar(struct msgbuf *mbp, const
return;
mtx_enter(_mtx);
+ msgbuf_putchar_locked(mbp, c);
+ mtx_leave(_mtx);
+}
+
+void
+msgbuf_putchar_locked(struct msgbuf *mbp, const char c)
+{
mbp->msg_bufc[mbp->msg_bufx++] = c;
if (mbp->msg_bufx < 0 || mbp->msg_bufx >= mbp->msg_bufs)
mbp->msg_bufx = 0;
@@ -171,7 +183,6 @@ msgbuf_putchar(struct msgbuf *mbp, const
mbp->msg_bufr = 0;
mbp->msg_bufd++;
}
- mtx_leave(_mtx);
}
size_t
Re: A sparc oddity (hair-pulling bug)
> From: Miod Vallat > Date: Thu, 7 Jan 2021 11:51:02 - (UTC) > > >> Indeed. Wrappinge the mutex operations in msgbuf_putchar with if (!cold) > >> makes the kernel boot again. > > > > Here is a diff for that. > > After a bit more thinking, it might be worth introduce a > msgbuf_putchar_unlocked() routine for the inner part only, and have > initmsgbuf() use it, since: > - it has made sure the magic value test will suceed. > - this is the only use of msgbuf_putchar() on sparc64 until the proper > curcpu mappings are set up; all output from pmap_bootstrap() carefully > uses the prom routines (and do not end up in the message buffer). I was thinking the same thing.
Re: A sparc oddity (hair-pulling bug)
>> Indeed. Wrappinge the mutex operations in msgbuf_putchar with if (!cold) >> makes the kernel boot again. > > Here is a diff for that. After a bit more thinking, it might be worth introduce a msgbuf_putchar_unlocked() routine for the inner part only, and have initmsgbuf() use it, since: - it has made sure the magic value test will suceed. - this is the only use of msgbuf_putchar() on sparc64 until the proper curcpu mappings are set up; all output from pmap_bootstrap() carefully uses the prom routines (and do not end up in the message buffer). $.02
Re: A sparc oddity (hair-pulling bug)
On Thu, Jan 07, 2021 at 07:08:05AM +, Miod Vallat wrote:
> > The per-CPU struct is mapped using a 64K locked TLB entry. That TLB
> > entry is installed by sun4u_bootstrap_cpu(), which gets called *after*
> > initsmgbuf() is called. So this issue was introduced when locking was
> > added to msgbuf_putchar().
> >
> > Now the real question is why this doesn't crash even on a cold boot?
> > I suspect that is because on a cold boot the buffer is clean and the
> > msgbuf_putchar() call in initmsgbuf() is skipped.
> >
> > It may be possible to do some reordering in pmap_bootstrap(), but
> > frankly I think the locking added to msgbuf_putchar() was a mistake.
> > Or maybe the locking code should be bypassed when cold.
>
> Indeed. Wrappinge the mutex operations in msgbuf_putchar with if (!cold)
> makes the kernel boot again.
Here is a diff for that.
Index: kern/subr_log.c
===
RCS file: src/sys/kern/subr_log.c,v
retrieving revision 1.70
diff -u -p -r1.70 subr_log.c
--- kern/subr_log.c 25 Dec 2020 12:59:52 - 1.70
+++ kern/subr_log.c 7 Jan 2021 09:25:16 -
@@ -157,11 +157,17 @@ initconsbuf(void)
void
msgbuf_putchar(struct msgbuf *mbp, const char c)
{
+ int dolock;
+
if (mbp->msg_magic != MSG_MAGIC)
/* Nothing we can do */
return;
- mtx_enter(_mtx);
+ /* Mutex cannot be used during early boot on some architectures. */
+ dolock = (cold == 0);
+
+ if (dolock)
+ mtx_enter(_mtx);
mbp->msg_bufc[mbp->msg_bufx++] = c;
if (mbp->msg_bufx < 0 || mbp->msg_bufx >= mbp->msg_bufs)
mbp->msg_bufx = 0;
@@ -171,7 +177,8 @@ msgbuf_putchar(struct msgbuf *mbp, const
mbp->msg_bufr = 0;
mbp->msg_bufd++;
}
- mtx_leave(_mtx);
+ if (dolock)
+ mtx_leave(_mtx);
}
size_t
Re: A sparc oddity (hair-pulling bug)
> The per-CPU struct is mapped using a 64K locked TLB entry. That TLB > entry is installed by sun4u_bootstrap_cpu(), which gets called *after* > initsmgbuf() is called. So this issue was introduced when locking was > added to msgbuf_putchar(). > > Now the real question is why this doesn't crash even on a cold boot? > I suspect that is because on a cold boot the buffer is clean and the > msgbuf_putchar() call in initmsgbuf() is skipped. > > It may be possible to do some reordering in pmap_bootstrap(), but > frankly I think the locking added to msgbuf_putchar() was a mistake. > Or maybe the locking code should be bypassed when cold. Indeed. Wrappinge the mutex operations in msgbuf_putchar with if (!cold) makes the kernel boot again.
Re: A sparc oddity (hair-pulling bug)
> Date: Wed, 6 Jan 2021 19:14:08 +
> From: Miod Vallat
>
> I have been confused by a very strange issue on sparc64 over the last
> few days, and I can't figure out its cause.
>
> What happens is that cold boots work, but warm boots (i.e. rebooting)
> almost always fail like this:
>
> Rebooting with command: boot
> Boot device: disk File and args:
> OpenBSD IEEE 1275 Bootblock 2.1
> ..>> OpenBSD BOOT 1.20
> Trying bsd...
> NOTE: random seed is being reused.
> Booting /sbus@1f,0/SUNW,fas@e,880/sd@0,0:a/bsd
> 9956944@0x100+4528@0x197ee50+191788@0x1c0+4002516@0x1c2ed2c
> symbols @ 0xffde0400 476705+165+641112+443003 start=0x100
> [ using 1562024 bytes of bsd ELF symbol table ]
> Fast Data Access MMU Miss
> ok
>
> However, sometimes, a bsd.rd -> bsd transition works (i.e. boot bsd.rd,
> install or upgrade or even do nothing, then reboot to bsd). But most of
> the time it fails in the same way. And once it has failed, there does
> not seem to be a way to boot a kernel without having to poweroff
> (reset-all will not help).
>
> At first I thought this was a subtle relinking problem, but it isn't.
> From the prom, I have been able to get this trace:
> mtx_enter+0x58
> msgbuf_putchar+0x2c
> initmsgbuf+0x80
> pmap_bootstrap+0x140
> bootstrap+0x18c
>
> This is a on an Ultra 1, thus single-processor machine. The code for
> mtx_enter() is:
>
> void
> mtx_enter(struct mutex *mtx)
> {
> struct cpu_info *ci = curcpu();
>
> /* Avoid deadlocks after panic or in DDB */
> if (panicstr || db_active)
> return;
>
> WITNESS_CHECKORDER(MUTEX_LOCK_OBJECT(mtx),
> LOP_EXCLUSIVE | LOP_NEWORDER, NULL);
>
> #ifdef DIAGNOSTIC
> if (__predict_false(mtx->mtx_owner == ci))
> panic("mtx %p: locking against myself", mtx);
> #endif
>
> if (mtx->mtx_wantipl != IPL_NONE)
> mtx->mtx_oldipl = splraise(mtx->mtx_wantipl);
>
> mtx->mtx_owner = ci;
>
> #ifdef DIAGNOSTIC
> ci->ci_mutex_level++;
> #endif
> WITNESS_LOCK(MUTEX_LOCK_OBJECT(mtx), LOP_EXCLUSIVE);
> }
>
> and the "Fast Data Access MMU Miss" occurs on the
> ci->ci_mutex_level++;
> line.
>
> It turns out that, being a single-processor kernel, ci == CPUINFO_VA ==
> 0xe0018000 (KERNEND + 64KB + 32KB).
>
> And the prom tells me that:
>
> ok e0018000 map?
> VA:e0018000
> G:0 W:0 P:0 E:0 CV:0 CP:0 L:0 Soft1:0 PA[40:13]:0 PA:0
> Diag:0 Soft2:0 IE:0 NFO:0 Size:0 V:0
> Invalid
>
> Is this a PROM mapping which got invalidated by mistake, or a mapping
> which ought to have been set up by the boot blocks but is no longer set
> up correctly? I see no obvious change to blame about this in the last
> few releases.
>
> Any ideas on where to look or what to try to get to understand that
> problem better?
The per-CPU struct is mapped using a 64K locked TLB entry. That TLB
entry is installed by sun4u_bootstrap_cpu(), which gets called *after*
initsmgbuf() is called. So this issue was introduced when locking was
added to msgbuf_putchar().
Now the real question is why this doesn't crash even on a cold boot?
I suspect that is because on a cold boot the buffer is clean and the
msgbuf_putchar() call in initmsgbuf() is skipped.
It may be possible to do some reordering in pmap_bootstrap(), but
frankly I think the locking added to msgbuf_putchar() was a mistake.
Or maybe the locking code should be bypassed when cold.
Re: A sparc oddity (hair-pulling bug)
> I think the window this occurs is something like: > > bad > OpenBSD 6.8-current (GENERIC) #510: Thu Oct 29 19:58:32 MDT 2020 > > good > OpenBSD 6.8-current (GENERIC) #508: Thu Oct 29 06:05:29 MDT 2020 I was trying to find a narrow window, but since it does not always happen, I ended up with a botched dichotomy. I thought I had narrowed between 20201101 and 20201026, but could actually reproduce with a 20201026 kernel. And there are no sparc64 changes (except a minor interrupt diff in vpci) between 20201026 and 20201101 anyway. I'll reinstall 6.8 tomorrow and restart checking, more carefully. (Unrelated to this, pmap_bootstrap() always uses 4 pages for the message buffer regardless of MSGBUFSIZE, this might be worth fixing)
Re: A sparc oddity (hair-pulling bug)
On Wed, Jan 06, 2021 at 07:14:08PM +, Miod Vallat wrote:
> I have been confused by a very strange issue on sparc64 over the last
> few days, and I can't figure out its cause.
>
> What happens is that cold boots work, but warm boots (i.e. rebooting)
> almost always fail like this:
>
> Rebooting with command: boot
> Boot device: disk File and args:
> OpenBSD IEEE 1275 Bootblock 2.1
> ..>> OpenBSD BOOT 1.20
> Trying bsd...
> NOTE: random seed is being reused.
> Booting /sbus@1f,0/SUNW,fas@e,880/sd@0,0:a/bsd
> 9956944@0x100+4528@0x197ee50+191788@0x1c0+4002516@0x1c2ed2c
> symbols @ 0xffde0400 476705+165+641112+443003 start=0x100
> [ using 1562024 bytes of bsd ELF symbol table ]
> Fast Data Access MMU Miss
> ok
>
> However, sometimes, a bsd.rd -> bsd transition works (i.e. boot bsd.rd,
> install or upgrade or even do nothing, then reboot to bsd). But most of
> the time it fails in the same way. And once it has failed, there does
> not seem to be a way to boot a kernel without having to poweroff
> (reset-all will not help).
>
> At first I thought this was a subtle relinking problem, but it isn't.
> >From the prom, I have been able to get this trace:
> mtx_enter+0x58
> msgbuf_putchar+0x2c
> initmsgbuf+0x80
> pmap_bootstrap+0x140
> bootstrap+0x18c
>
> This is a on an Ultra 1, thus single-processor machine. The code for
> mtx_enter() is:
>
> void
> mtx_enter(struct mutex *mtx)
> {
> struct cpu_info *ci = curcpu();
>
> /* Avoid deadlocks after panic or in DDB */
> if (panicstr || db_active)
> return;
>
> WITNESS_CHECKORDER(MUTEX_LOCK_OBJECT(mtx),
> LOP_EXCLUSIVE | LOP_NEWORDER, NULL);
>
> #ifdef DIAGNOSTIC
> if (__predict_false(mtx->mtx_owner == ci))
> panic("mtx %p: locking against myself", mtx);
> #endif
>
> if (mtx->mtx_wantipl != IPL_NONE)
> mtx->mtx_oldipl = splraise(mtx->mtx_wantipl);
>
> mtx->mtx_owner = ci;
>
> #ifdef DIAGNOSTIC
> ci->ci_mutex_level++;
> #endif
> WITNESS_LOCK(MUTEX_LOCK_OBJECT(mtx), LOP_EXCLUSIVE);
> }
>
> and the "Fast Data Access MMU Miss" occurs on the
> ci->ci_mutex_level++;
> line.
>
> It turns out that, being a single-processor kernel, ci == CPUINFO_VA ==
> 0xe0018000 (KERNEND + 64KB + 32KB).
>
> And the prom tells me that:
>
> ok e0018000 map?
> VA:e0018000
> G:0 W:0 P:0 E:0 CV:0 CP:0 L:0 Soft1:0 PA[40:13]:0 PA:0
> Diag:0 Soft2:0 IE:0 NFO:0 Size:0 V:0
> Invalid
>
> Is this a PROM mapping which got invalidated by mistake, or a mapping
> which ought to have been set up by the boot blocks but is no longer set
> up correctly? I see no obvious change to blame about this in the last
> few releases.
>
> Any ideas on where to look or what to try to get to understand that
> problem better?
I saw something like this on a V120.
Booting /pci@1f,0/pci@1/scsi@8/disk@0,0:a/bsd.1105
9901216@0x100+2912@0x19714a0+191348@0x1c0+4002956@0x1c2eb74
symbols @ 0xfee82400 479089+165+641136+442948 start=0x100
[ using 1564376 bytes of bsd ELF symbol table ]
Fast Data Access MMU Miss
ok
instead of
9910440@0x100+1880@0x19738a8+188572@0x1c0+4005732@0x1c2e09c
symbols @ 0xfee80400 481463+165+641016+442891 start=0x100
[ using 1566568 bytes of bsd ELF symbol table ]
console is /pci@1f,0/pci@1,1/isa@7/serial@0,3f8
...
(with bsd did not occur with bsd.rd)
Booting a known good kernel was not enough to clear this state
or even reset-all at the ok prompt. I had to do power-off at
ok prompt and poweron at lom prompt.
I think the window this occurs is something like:
bad
OpenBSD 6.8-current (GENERIC) #510: Thu Oct 29 19:58:32 MDT 2020
good
OpenBSD 6.8-current (GENERIC) #508: Thu Oct 29 06:05:29 MDT 2020
