Re: [PATCH] x86/mce/dev-mcelog: Call mce_register_decode_chain() much earlier

["Luck, Tony" <tony.luck@intel.com>]

On Fri, Aug 20, 2021 at 05:48:21PM +0200, Borislav Petkov wrote:
> On Fri, Aug 20, 2021 at 07:43:14AM -0700, Luck, Tony wrote:
> > How can the kernel tell that all consumers have registered? Is there
> > some new kernel crystal ball functionality that can predict that an
> > EDAC driver module is going to be loaded at some point in the future
> > when user space is up and running :-)
> 
> The crystal ball is called mcheck_late_init(). There's even:
> 
>         /*
>          * Flush out everything that has been logged during early boot, now that
>          * everything has been initialized (workqueues, decoders, ...).
>          */
>         mce_schedule_work();
> 
> in there. That thing is late_initcall() and by that time mcelog should
> have been registered. And I wonder why isn't that working as expected...
> 
> > I think the best we could do would be to set a timer for some point
> > far enough out (one minute?, two minutes?) to give a chance for
> > modules to load.
> 
> Forget modules - only the built-in stuff. We cannot be waiting
> indefinitely until someone loads mcelog for decoding.

I added some traces:

$ dmesg | grep mce:
[    0.033648] mce: mce_register_decode_chain fn=mce_early_notifier+0x0/0x50 pri=6
[    0.033655] mce: mce_register_decode_chain fn=uc_decode_notifier+0x0/0xd0 pri=5
[    0.033659] mce: mce_register_decode_chain fn=mce_default_notifier+0x0/0x30 pri=0
[    4.392631] mce: [Hardware Error]: Machine check events logged
[    4.393356] mce: [Hardware Error]: CPU 0: Machine Check: 0 Bank 0: a000000000004321
[    4.395352] mce: [Hardware Error]: TSC 0
[    4.396352] mce: [Hardware Error]: PROCESSOR 0:406f1 TIME 1629743651 SOCKET 0 APIC 0 microcode b000019
[   15.172861] mce: mce_register_decode_chain fn=dev_mce_log+0x0/0x110 pri=1
[   15.192101] mce: mcheck_late_init: calling mce_schedule_work()
[   31.618245] mce: mce_register_decode_chain fn=sbridge_mce_check_error+0x0/0x92 [sb_edac] pri=2

So you are right that mcheck_late_init() is called after dev_mce_log()
is registered.  But it seems someone kicks the queue long before that
happens.  Probably this:

void mce_log(struct mce *m)
{
        if (!mce_gen_pool_add(m))
                irq_work_queue(&mce_irq_work);
}

Could we add a flag:

static bool mce_ready_to_rock; // better name needed :-)

Which gets set in mcheck_late_init(). Then mce_log() becomes:

void mce_log(struct mce *m)
{
        if (!mce_gen_pool_add(m) && mce_ready_to_rock)
                irq_work_queue(&mce_irq_work);
}

-Tony