I ask about this on account of boot delays reported in the following: http://www.spinics.net/lists/linux-initramfs/msg04173.html http://www.spinics.net/lists/linux-initramfs/msg04175.html http://www.spinics.net/lists/linux-initramfs/msg04275.html
I was looking at early portions of dmesg for anything resembling clues and noticed that early microcode messages are not always reported for every core present. Here are examples of 'dmesg | grep croco', all taken from machines with two cpu cores. Notice that some refer to two different cores, while others make no mention of the existence of more than one core:
Linux big31 4.7.4-200.fc24.x86_64 #1 SMP Thu Sep 15 18:42:09 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [ 0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28 [ 0.835393] microcode: CPU0 sig=0x1067a, pf=0x1, revision=0xa0b [ 0.840090] microcode: CPU1 sig=0x1067a, pf=0x1, revision=0xa0b
Linux big31 4.8.8-200.fc24.x86_64 #1 SMP Tue Nov 15 19:41:51 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [ 0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28 [ 0.851345] microcode: sig=0x1067a, pf=0x1, revision=0xa0b
Linux big31 4.8.0-0.rc8.git0.1.fc25.x86_64 #1 SMP Mon Sep 26 17:12:24 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [ 0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28 [ 0.830256] microcode: sig=0x1067a, pf=0x1, revision=0xa0b
Linux big31 4.8.8-300.fc25.x86_64 #1 SMP Tue Nov 15 18:10:06 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [ 0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28 [ 0.601683] microcode: sig=0x1067a, pf=0x1, revision=0xa0b
Linux big31 4.8.0-0.rc1.git3.1.fc26.x86_64 #1 SMP Thu Aug 11 01:00:58 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [ 0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28 [ 1.157172] microcode: sig=0x1067a, pf=0x1, revision=0xa0b
Linux big31 4.8.0-0.rc8.git1.1.fc26.x86_64 #1 SMP Wed Sep 28 23:21:40 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [ 0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28 [ 0.965454] microcode: sig=0x1067a, pf=0x1, revision=0xa0b
Linux big31 4.9.0-0.rc5.git4.1.fc26.x86_64 #1 SMP Fri Nov 18 17:52:58 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [ 0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28 [ 1.146158] microcode: sig=0x1067a, pf=0x1, revision=0xa0b
Linux big41 4.6.5-300.fc24.x86_64 #1 SMP Thu Jul 28 01:10:12 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [ 0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28 [ 0.716008] microcode: CPU0 sig=0x1067a, pf=0x1, revision=0xa0b [ 0.716801] microcode: CPU1 sig=0x1067a, pf=0x1, revision=0xa0b
Linux big41 4.8.7-200.fc24.x86_64 #1 SMP Fri Nov 11 15:44:18 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [ 0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28 [ 0.617156] microcode: sig=0x1067a, pf=0x1, revision=0xa0b
Is it possible that the varying reference or not to CPUx is indicative of some kind of installation mishandling lurking in microcode installation, possibly causing microcode to be installed in only one of the two cores, which could be at root of or affecting the boot initialization delay described in my linux-initramfs posts? If so, should I file a bug? If yes, in which tracker, and against which component (kernel? dracut? microcode_ctl? other?).
On 11/22/2016 06:06 AM, Felix Miata wrote:
I ask about this on account of boot delays reported in the following: http://www.spinics.net/lists/linux-initramfs/msg04173.html http://www.spinics.net/lists/linux-initramfs/msg04175.html http://www.spinics.net/lists/linux-initramfs/msg04275.html
I was looking at early portions of dmesg for anything resembling clues and noticed that early microcode messages are not always reported for every core present. Here are examples of 'dmesg | grep croco', all taken from machines with two cpu cores. Notice that some refer to two different cores, while others make no mention of the existence of more than one core:
Linux big31 4.7.4-200.fc24.x86_64 #1 SMP Thu Sep 15 18:42:09 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [ 0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28 [ 0.835393] microcode: CPU0 sig=0x1067a, pf=0x1, revision=0xa0b [ 0.840090] microcode: CPU1 sig=0x1067a, pf=0x1, revision=0xa0b
Linux big31 4.8.8-200.fc24.x86_64 #1 SMP Tue Nov 15 19:41:51 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [ 0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28 [ 0.851345] microcode: sig=0x1067a, pf=0x1, revision=0xa0b
Linux big31 4.8.0-0.rc8.git0.1.fc25.x86_64 #1 SMP Mon Sep 26 17:12:24 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [ 0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28 [ 0.830256] microcode: sig=0x1067a, pf=0x1, revision=0xa0b
Linux big31 4.8.8-300.fc25.x86_64 #1 SMP Tue Nov 15 18:10:06 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [ 0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28 [ 0.601683] microcode: sig=0x1067a, pf=0x1, revision=0xa0b
Linux big31 4.8.0-0.rc1.git3.1.fc26.x86_64 #1 SMP Thu Aug 11 01:00:58 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [ 0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28 [ 1.157172] microcode: sig=0x1067a, pf=0x1, revision=0xa0b
Linux big31 4.8.0-0.rc8.git1.1.fc26.x86_64 #1 SMP Wed Sep 28 23:21:40 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [ 0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28 [ 0.965454] microcode: sig=0x1067a, pf=0x1, revision=0xa0b
Linux big31 4.9.0-0.rc5.git4.1.fc26.x86_64 #1 SMP Fri Nov 18 17:52:58 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [ 0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28 [ 1.146158] microcode: sig=0x1067a, pf=0x1, revision=0xa0b
Linux big41 4.6.5-300.fc24.x86_64 #1 SMP Thu Jul 28 01:10:12 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [ 0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28 [ 0.716008] microcode: CPU0 sig=0x1067a, pf=0x1, revision=0xa0b [ 0.716801] microcode: CPU1 sig=0x1067a, pf=0x1, revision=0xa0b
Linux big41 4.8.7-200.fc24.x86_64 #1 SMP Fri Nov 11 15:44:18 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [ 0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28 [ 0.617156] microcode: sig=0x1067a, pf=0x1, revision=0xa0b
Is it possible that the varying reference or not to CPUx is indicative of some kind of installation mishandling lurking in microcode installation, possibly causing microcode to be installed in only one of the two cores, which could be at root of or affecting the boot initialization delay described in my linux-initramfs posts? If so, should I file a bug? If yes, in which tracker, and against which component (kernel? dracut? microcode_ctl? other?).
The problem you have above is that you haven't organized the output above relative to the kernel versions you're booting. If you did that you would see that a change went in ~4.8. It is important to keep kernel versions in mind when looking at issues like this.
This isn't a bug. The messaging was changed in the commit below to only output a single message instead of one for each cpu.
Sorry for the cut-and-paste of this output.
[prarit@prarit ~]$ cd git-kernel/linux [prarit@prarit linux]$ git grep revision | grep sig | grep pf arch/x86/kernel/cpu/microcode/intel.c:874: pr_info("sig=0x%x, pf=0x%x, revision=0x%x\n", [prarit@prarit linux]$ git wtf arch/x86/kernel/cpu/microcode/intel.c:874 354542d034ab2 (Andi Kleen 2016-06-09 06:41:41 -0700 874) pr_info("sig=0x%x, pf=0x%x, revision=0x%x\n", [prarit@prarit linux]$ git show 354542d034ab2 commit 354542d034ab2a849a284edcc661e76b753a57dc Author: Andi Kleen ak@linux.intel.com Date: Thu Jun 9 06:41:41 2016 -0700
x86/microcode/intel: Do not issue microcode updates messages on each CPU
On large systems the microcode driver is very noisy, because it prints a line for each CPU. The lines are redundant because usually all CPUs are updated to the same microcode revision.
All other subsystems have been patched previously to not print a line for each CPU. Only the microcode driver is left.
Only print an microcode revision update when something changed. This results in typically only a single line being printed.
Signed-off-by: Andi Kleen ak@linux.intel.com Signed-off-by: Borislav Petkov bp@suse.de Cc: Andy Lutomirski luto@amacapital.net Cc: Borislav Petkov bp@alien8.de Cc: Brian Gerst brgerst@gmail.com Cc: Denys Vlasenko dvlasenk@redhat.com Cc: H. Peter Anvin hpa@zytor.com Cc: Linus Torvalds torvalds@linux-foundation.org Cc: Peter Zijlstra peterz@infradead.org Cc: Thomas Gleixner tglx@linutronix.de Cc: Tony Luck tony.luck@intel.com Cc: elliott@hpe.com Cc: hmh@hmh.eng.br Link: http://lkml.kernel.org/r/20160609134141.5981-1-andi@firstfloor.org Signed-off-by: Ingo Molnar mingo@kernel.org
diff --git a/arch/x86/kernel/cpu/microcode/intel.c b/arch/x86/kernel/cpu/microco index 8962d6acee39..6515c802346a 100644 --- a/arch/x86/kernel/cpu/microcode/intel.c +++ b/arch/x86/kernel/cpu/microcode/intel.c @@ -843,6 +843,7 @@ void reload_ucode_intel(void)
static int collect_cpu_info(int cpu_num, struct cpu_signature *csig) { + static struct cpu_signature prev; struct cpuinfo_x86 *c = &cpu_data(cpu_num); unsigned int val[2];
@@ -857,8 +858,13 @@ static int collect_cpu_info(int cpu_num, struct cpu_signatu }
csig->rev = c->microcode; - pr_info("CPU%d sig=0x%x, pf=0x%x, revision=0x%x\n", - cpu_num, csig->sig, csig->pf, csig->rev); + + /* No extra locking on prev, races are harmless. */ + if (csig->sig != prev.sig || csig->pf != prev.pf || csig->rev != prev.re + pr_info("sig=0x%x, pf=0x%x, revision=0x%x\n", + csig->sig, csig->pf, csig->rev); + prev = *csig; + }
return 0; } @@ -887,6 +893,7 @@ static int apply_microcode_intel(int cpu) struct ucode_cpu_info *uci; struct cpuinfo_x86 *c; unsigned int val[2]; + static int prev_rev; struct ucode_cpu_info *uci; struct cpuinfo_x86 *c; unsigned int val[2]; + static int prev_rev;
/* We should bind the task to the CPU */ if (WARN_ON(raw_smp_processor_id() != cpu)) @@ -921,11 +928,14 @@ static int apply_microcode_intel(int cpu) return -1; }
- pr_info("CPU%d updated to revision 0x%x, date = %04x-%02x-%02x\n", - cpu, val[1], - mc->hdr.date & 0xffff, - mc->hdr.date >> 24, - (mc->hdr.date >> 16) & 0xff); + if (val[1] != prev_rev) { + pr_info("updated to revision 0x%x, date = %04x-%02x-%02x\n", + val[1], + mc->hdr.date & 0xffff, + mc->hdr.date >> 24, + (mc->hdr.date >> 16) & 0xff); + prev_rev = val[1]; [prarit@prarit linux]$ git describe --contains 354542d034ab2 v4.8-rc1~88^2~5 [prarit@prarit linux]$
HTH,
P.
Am 22.11.2016 um 12:06 schrieb Felix Miata:
I was looking at early portions of dmesg for anything resembling clues and noticed that early microcode messages are not always reported for every core present
well, i doubt that every *core* needs to get the microcode or different cores can even have different microcodes because the microocode is for the CPU as whole
kernel@lists.fedoraproject.org
-
Felix Miata -
Prarit Bhargava -
Reindl Harald