Skip to contentSkip to conversation

x86/RAS: Dump error record to dmesg if no consumers

RFC PATCH In review Borislav Petkov 5 participants 21 messages Nov 1, 2016 – Jan 19, 2017 x86

lore
Share & tools
lore

Borislav Petkov

author maintainer
#0 lore raw

cover x86/RAS: Dump error record to dmesg if no consumers

From: Borislav Petkov <[email protected]>

Right,

so this is not a good thing: systems may not have any error record consumers registered and in such cases, any logged MCEs disappear into the void. And this shouldn't happen.

So let's dump them to dmesg as a last resort.

Borislav Petkov (3):
notifiers: Document notifier priority
x86/RAS: Add TSC to the injected MCE
x86/MCE: Dump MCE to dmesg if no consumers

 arch/x86/kernel/cpu/mcheck/mce.c | 52 +++++++++++++++++++++++++++++++++++-----
 arch/x86/ras/mce_amd_inj.c       |  2 ++
 include/linux/notifier.h         |  1 +
 3 files changed, 49 insertions(+), 6 deletions(-)
Signature · 1 line
2.10.0
author maintainer
#1 lore raw

RFC PATCH 1/3 notifiers: Document notifier priority

From: Borislav Petkov <[email protected]>

I always forget which is highest priority so document it.

Signed-off-by Borislav Petkov <[email protected]>
---
 include/linux/notifier.h | 1 +
 1 file changed, 1 insertion(+)
include/linux/notifier.h +1 -0
index 4149868de4e6..6bd3c691e562 100644
@@ -55,6 +55,7 @@ typedef	int (*notifier_fn_t)(struct notifier_block *nb,
 struct notifier_block {
 	notifier_fn_t notifier_call;
 	struct notifier_block __rcu *next;
+	/* Notifier priority: numerically higher gets executed earlier */
 	int priority;
 };
Signature · 1 line
2.10.0
author maintainer
#2 lore raw

RFC PATCH 2/3 x86/RAS: Add TSC to the injected MCE

In reply to Borislav Petkov

From: Borislav Petkov <[email protected]>

Add the TSC at the time of injection.

Signed-off-by Borislav Petkov <[email protected]>
---
 arch/x86/ras/mce_amd_inj.c | 2 ++
 1 file changed, 2 insertions(+)
arch/x86/ras/mce_amd_inj.c +2 -0
index 1ac76479c266..8730c2882fff 100644
@@ -275,6 +275,8 @@ static void do_inject(void)
 	unsigned int cpu = i_mce.extcpu;
 	u8 b = i_mce.bank;
 
+	rdtscll(i_mce.tsc);
+
 	if (i_mce.misc)
 		i_mce.status |= MCI_STATUS_MISCV;
Signature · 1 line
2.10.0
merge bot
#3 lore raw

[tip:ras/core] x86/RAS: Add TSC timestamp to the injected MCE

x86/RAS: Add TSC timestamp to the injected MCE
Commit-ID:  8c203dbb78ca7a9aed4e2570c866b0f43c752e41
Gitweb:     http://git.kernel.org/tip/8c203dbb78ca7a9aed4e2570c866b0f43c752e41
Author:     Borislav Petkov <[email protected]>
AuthorDate: Tue, 1 Nov 2016 13:04:41 +0100
Committer:  Thomas Gleixner <[email protected]>
CommitDate: Tue, 8 Nov 2016 17:10:13 +0100

x86/RAS: Add TSC timestamp to the injected MCE

The MCE injection code does not provide the time stamp information for the injected MCE. Add it.

Signed-off-by Borislav Petkov <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Thomas Gleixner <[email protected]>
---
 arch/x86/ras/mce_amd_inj.c | 2 ++
 1 file changed, 2 insertions(+)
arch/x86/ras/mce_amd_inj.c +2 -0
index 1ac7647..8730c28 100644
@@ -275,6 +275,8 @@ static void do_inject(void)
 	unsigned int cpu = i_mce.extcpu;
 	u8 b = i_mce.bank;
 
+	rdtscll(i_mce.tsc);
+
 	if (i_mce.misc)
 		i_mce.status |= MCI_STATUS_MISCV;
author maintainer
#4 lore raw

RFC PATCH 3/3 x86/MCE: Dump MCE to dmesg if no consumers

In reply to Borislav Petkov

From: Borislav Petkov <[email protected]>

When there are no error record consumers registered with the kernel, the only thing that appears in dmesg is something like:

  [  300.000326] mce: [Hardware Error]: Machine check events logged

and the error records are gone. Which is seriously counterproductive.

So let's dump them to dmesg instead, in such a case.

Signed-off-by Borislav Petkov <[email protected]>
---
 arch/x86/kernel/cpu/mcheck/mce.c | 52 +++++++++++++++++++++++++++++++++++-----
 1 file changed, 46 insertions(+), 6 deletions(-)
arch/x86/kernel/cpu/mcheck/mce.c +46 -6
index a7fdf453d895..4ca00474804b 100644
@@ -207,8 +207,12 @@ EXPORT_SYMBOL_GPL(mce_inject_log);
 
 static struct notifier_block mce_srao_nb;
 
+static atomic_t num_notifiers;
+
 void mce_register_decode_chain(struct notifier_block *nb)
 {
+	atomic_inc(&num_notifiers);
+
 	/* Ensure SRAO notifier has the highest priority in the decode chain. */
 	if (nb != &mce_srao_nb && nb->priority == INT_MAX)
 		nb->priority -= 1;

@@ -219,6 +223,8 @@ EXPORT_SYMBOL_GPL(mce_register_decode_chain);
 
 void mce_unregister_decode_chain(struct notifier_block *nb)
 {
+	atomic_dec(&num_notifiers);
+
 	atomic_notifier_chain_unregister(&x86_mce_decoder_chain, nb);
 }
 EXPORT_SYMBOL_GPL(mce_unregister_decode_chain);

@@ -270,17 +276,17 @@ struct mca_msr_regs msr_ops = {
 	.misc	= misc_reg
 };
 
-static void print_mce(struct mce *m)
+static void __print_mce(struct mce *m)
 {
-	int ret = 0;
-
-	pr_emerg(HW_ERR "CPU %d: Machine Check Exception: %Lx Bank %d: %016Lx\n",
-	       m->extcpu, m->mcgstatus, m->bank, m->status);
+	pr_emerg(HW_ERR "CPU %d: Machine Check%s: %Lx Bank %d: %016Lx\n",
+		 m->extcpu,
+		 (m->mcgstatus & MCG_STATUS_MCIP ? " Exception" : ""),
+		 m->mcgstatus, m->bank, m->status);
 
 	if (m->ip) {
 		pr_emerg(HW_ERR "RIP%s %02x:<%016Lx> ",
 			!(m->mcgstatus & MCG_STATUS_EIPV) ? " !INEXACT!" : "",
-				m->cs, m->ip);
+			m->cs, m->ip);
 
 		if (m->cs == __KERNEL_CS)
 			print_symbol("{%s}", m->ip);

@@ -308,6 +314,13 @@ static void print_mce(struct mce *m)
 	pr_emerg(HW_ERR "PROCESSOR %u:%x TIME %llu SOCKET %u APIC %x microcode %x\n",
 		m->cpuvendor, m->cpuid, m->time, m->socketid, m->apicid,
 		cpu_data(m->extcpu).microcode);
+}
+
+static void print_mce(struct mce *m)
+{
+	int ret = 0;
+
+	__print_mce(m);
 
 	/*
 	 * Print out human-readable details about the MCE error,

@@ -569,6 +582,32 @@ static struct notifier_block mce_srao_nb = {
 	.priority = INT_MAX,
 };
 
+static int mce_default_notifier(struct notifier_block *nb, unsigned long val,
+				void *data)
+{
+	struct mce *m = (struct mce *)data;
+
+	if (!m)
+		return NOTIFY_DONE;
+
+	/*
+	 * Run the default notifier if we have only the SRAO
+	 * notifier and us registered.
+	 */
+	if (atomic_read(&num_notifiers) > 2)
+		return NOTIFY_DONE;
+
+	__print_mce(m);
+
+	return NOTIFY_DONE;
+}
+
+static struct notifier_block mce_default_nb = {
+	.notifier_call	= mce_default_notifier,
+	/* lowest prio, we want it to run last. */
+	.priority	= 0,
+};
+
 /*
  * Read ADDR and MISC registers.
  */

@@ -2138,6 +2177,7 @@ int __init mcheck_init(void)
 {
 	mcheck_intel_therm_init();
 	mce_register_decode_chain(&mce_srao_nb);
+	mce_register_decode_chain(&mce_default_nb);
 	mcheck_vendor_init_severity();
 
 	INIT_WORK(&mce_work, mce_process_work);
Signature · 1 line
2.10.0
merge bot
#5 lore raw

[tip:ras/core] x86/MCE: Dump MCE to dmesg if no consumers

x86/MCE: Dump MCE to dmesg if no consumers
Commit-ID:  cd9c57cad3fe89ea949b9266cddc947c0838f7af
Gitweb:     http://git.kernel.org/tip/cd9c57cad3fe89ea949b9266cddc947c0838f7af
Author:     Borislav Petkov <[email protected]>
AuthorDate: Tue, 1 Nov 2016 12:52:27 +0100
Committer:  Thomas Gleixner <[email protected]>
CommitDate: Tue, 8 Nov 2016 17:10:13 +0100

x86/MCE: Dump MCE to dmesg if no consumers

When there are no error record consumers registered with the kernel, the only thing that appears in dmesg is something like:

  [  300.000326] mce: [Hardware Error]: Machine check events logged

and the error records are gone. Which is seriously counterproductive.

So let's dump them to dmesg instead, in such a case.

Requested-by Eric Morton <[email protected]>
Signed-off-by Borislav Petkov <[email protected]>
Cc Tony Luck <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Thomas Gleixner <[email protected]>
---
 arch/x86/kernel/cpu/mcheck/mce.c | 52 +++++++++++++++++++++++++++++++++++-----
 1 file changed, 46 insertions(+), 6 deletions(-)
arch/x86/kernel/cpu/mcheck/mce.c +46 -6
index a7fdf45..4ca0047 100644
@@ -207,8 +207,12 @@ EXPORT_SYMBOL_GPL(mce_inject_log);
 
 static struct notifier_block mce_srao_nb;
 
+static atomic_t num_notifiers;
+
 void mce_register_decode_chain(struct notifier_block *nb)
 {
+	atomic_inc(&num_notifiers);
+
 	/* Ensure SRAO notifier has the highest priority in the decode chain. */
 	if (nb != &mce_srao_nb && nb->priority == INT_MAX)
 		nb->priority -= 1;

@@ -219,6 +223,8 @@ EXPORT_SYMBOL_GPL(mce_register_decode_chain);
 
 void mce_unregister_decode_chain(struct notifier_block *nb)
 {
+	atomic_dec(&num_notifiers);
+
 	atomic_notifier_chain_unregister(&x86_mce_decoder_chain, nb);
 }
 EXPORT_SYMBOL_GPL(mce_unregister_decode_chain);

@@ -270,17 +276,17 @@ struct mca_msr_regs msr_ops = {
 	.misc	= misc_reg
 };
 
-static void print_mce(struct mce *m)
+static void __print_mce(struct mce *m)
 {
-	int ret = 0;
-
-	pr_emerg(HW_ERR "CPU %d: Machine Check Exception: %Lx Bank %d: %016Lx\n",
-	       m->extcpu, m->mcgstatus, m->bank, m->status);
+	pr_emerg(HW_ERR "CPU %d: Machine Check%s: %Lx Bank %d: %016Lx\n",
+		 m->extcpu,
+		 (m->mcgstatus & MCG_STATUS_MCIP ? " Exception" : ""),
+		 m->mcgstatus, m->bank, m->status);
 
 	if (m->ip) {
 		pr_emerg(HW_ERR "RIP%s %02x:<%016Lx> ",
 			!(m->mcgstatus & MCG_STATUS_EIPV) ? " !INEXACT!" : "",
-				m->cs, m->ip);
+			m->cs, m->ip);
 
 		if (m->cs == __KERNEL_CS)
 			print_symbol("{%s}", m->ip);

@@ -308,6 +314,13 @@ static void print_mce(struct mce *m)
 	pr_emerg(HW_ERR "PROCESSOR %u:%x TIME %llu SOCKET %u APIC %x microcode %x\n",
 		m->cpuvendor, m->cpuid, m->time, m->socketid, m->apicid,
 		cpu_data(m->extcpu).microcode);
+}
+
+static void print_mce(struct mce *m)
+{
+	int ret = 0;
+
+	__print_mce(m);
 
 	/*
 	 * Print out human-readable details about the MCE error,

@@ -569,6 +582,32 @@ static struct notifier_block mce_srao_nb = {
 	.priority = INT_MAX,
 };
 
+static int mce_default_notifier(struct notifier_block *nb, unsigned long val,
+				void *data)
+{
+	struct mce *m = (struct mce *)data;
+
+	if (!m)
+		return NOTIFY_DONE;
+
+	/*
+	 * Run the default notifier if we have only the SRAO
+	 * notifier and us registered.
+	 */
+	if (atomic_read(&num_notifiers) > 2)
+		return NOTIFY_DONE;
+
+	__print_mce(m);
+
+	return NOTIFY_DONE;
+}
+
+static struct notifier_block mce_default_nb = {
+	.notifier_call	= mce_default_notifier,
+	/* lowest prio, we want it to run last. */
+	.priority	= 0,
+};
+
 /*
  * Read ADDR and MISC registers.
  */

@@ -2138,6 +2177,7 @@ int __init mcheck_init(void)
 {
 	mcheck_intel_therm_init();
 	mce_register_decode_chain(&mce_srao_nb);
+	mce_register_decode_chain(&mce_default_nb);
 	mcheck_vendor_init_severity();
 
 	INIT_WORK(&mce_work, mce_process_work);
author maintainer
#6 lore raw

PATCH 1/1 x86/MCE: Remove MCP_TIMESTAMP

In reply to Borislav Petkov

Whoops,

one more:

---
From: Borislav Petkov <[email protected]>
Date: Sat, 5 Nov 2016 12:47:03 +0100
Subject: [PATCH] x86/MCE: Remove MCP_TIMESTAMP

MCP_TIMESTAMP controls whether current TSC value should be added to the MCE record. Most of machine_check_poll() callers supply it, except __mcheck_cpu_init_generic() but this is wrong because we could be logging an MCE right at the same time and thus log one without the TSC value.

What is more, machine_check_poll() did unconditionally clear mce.tsc which is another bug.

So, get rid of all that and simply log an MCE with a TSC value always. Simplifies the code a bit too.

Signed-off-by Borislav Petkov <[email protected]>
Cc Tony Luck <[email protected]>
---
 arch/x86/include/asm/mce.h             | 5 ++---
 arch/x86/kernel/cpu/mcheck/mce.c       | 6 +-----
 arch/x86/kernel/cpu/mcheck/mce_intel.c | 6 +++---
 3 files changed, 6 insertions(+), 11 deletions(-)
arch/x86/include/asm/mce.h +2 -3
index 748b8da8e627..3b53c260e0be 100644
@@ -265,9 +265,8 @@ typedef DECLARE_BITMAP(mce_banks_t, MAX_NR_BANKS);
 DECLARE_PER_CPU(mce_banks_t, mce_poll_banks);
 
 enum mcp_flags {
-	MCP_TIMESTAMP	= BIT(0),	/* log time stamp */
-	MCP_UC		= BIT(1),	/* log uncorrected errors */
-	MCP_DONTLOG	= BIT(2),	/* only clear, don't log */
+	MCP_UC		= BIT(0),	/* log uncorrected errors */
+	MCP_DONTLOG	= BIT(1),	/* only clear, don't log */
 };
 bool machine_check_poll(enum mcp_flags flags, mce_banks_t *b);
arch/x86/kernel/cpu/mcheck/mce.c +1 -5
index 4ca00474804b..82564156d6ab 100644
@@ -713,7 +713,6 @@ bool machine_check_poll(enum mcp_flags flags, mce_banks_t *b)
 		m.misc = 0;
 		m.addr = 0;
 		m.bank = i;
-		m.tsc = 0;
 
 		barrier();
 		m.status = mce_rdmsrl(msr_ops.status(i));

@@ -735,9 +734,6 @@ bool machine_check_poll(enum mcp_flags flags, mce_banks_t *b)
 
 		mce_read_aux(&m, i);
 
-		if (!(flags & MCP_TIMESTAMP))
-			m.tsc = 0;
-
 		severity = mce_severity(&m, mca_cfg.tolerant, NULL, false);
 
 		if (severity == MCE_DEFERRED_SEVERITY && memory_error(&m))

@@ -1394,7 +1390,7 @@ static void mce_timer_fn(unsigned long data)
 	iv = __this_cpu_read(mce_next_interval);
 
 	if (mce_available(this_cpu_ptr(&cpu_info))) {
-		machine_check_poll(MCP_TIMESTAMP, this_cpu_ptr(&mce_poll_banks));
+		machine_check_poll(0, this_cpu_ptr(&mce_poll_banks));
 
 		if (mce_intel_cmci_poll()) {
 			iv = mce_adjust_timer(iv);
arch/x86/kernel/cpu/mcheck/mce_intel.c +3 -3
index 1defb8ea882c..3262f0d726bb 100644
@@ -130,7 +130,7 @@ bool mce_intel_cmci_poll(void)
 	 * Reset the counter if we've logged an error in the last poll
 	 * during the storm.
 	 */
-	if (machine_check_poll(MCP_TIMESTAMP, this_cpu_ptr(&mce_banks_owned)))
+	if (machine_check_poll(0, this_cpu_ptr(&mce_banks_owned)))
 		this_cpu_write(cmci_backoff_cnt, INITIAL_CHECK_INTERVAL);
 	else
 		this_cpu_dec(cmci_backoff_cnt);

@@ -250,7 +250,7 @@ static void intel_threshold_interrupt(void)
 	if (cmci_storm_detect())
 		return;
 
-	machine_check_poll(MCP_TIMESTAMP, this_cpu_ptr(&mce_banks_owned));
+	machine_check_poll(0, this_cpu_ptr(&mce_banks_owned));
 }
 
 /*

@@ -342,7 +342,7 @@ void cmci_recheck(void)
 		return;
 
 	local_irq_save(flags);
-	machine_check_poll(MCP_TIMESTAMP, this_cpu_ptr(&mce_banks_owned));
+	machine_check_poll(0, this_cpu_ptr(&mce_banks_owned));
 	local_irq_restore(flags);
 }
Signature · 7 lines
2.10.0

-- 
Regards/Gruss,
    Boris.

Good mailing practices for 400: avoid top-posting and trim the reply.
#7 lore raw

RE: [PATCH] x86/MCE: Remove MCP_TIMESTAMP

Quoted 2 lines

So, get rid of all that and simply log an MCE with a TSC value always. Simplifies the code a bit too.

I'm not necessarily opposed to this ... but there was once some logic behind when logged TSC, and when we didn't. Essentially we wanted the TSC when we were logging from #CMCI or #MC .... because the detection of the error was fresh, and wanted as much precision on the logged time as possible to compare with logged errors from other banks/cpus. This might allow us to distinguish multiple errors logged in the same #CMCI, from errors logged in separate #CMCI a tenth of a second apart.

If we found the error while polling, we didn’t want to provide a false sense of precision. The error could have been logged up to five minutes previously (or when logging errors during the initial poll of the banks an arbitrary time in the past).

-Tony

author maintainer
#8 lore raw

Re: [PATCH] x86/MCE: Remove MCP_TIMESTAMP

Quoted 10 lines · Tony
Quoted 2 lines

So, get rid of all that and simply log an MCE with a TSC value always. Simplifies the code a bit too.

I'm not necessarily opposed to this ... but there was once some logic behind when logged TSC, and when we didn't. Essentially we wanted the TSC when we were logging from #CMCI or #MC .... because the detection of the error was fresh, and wanted as much precision on the logged time as possible to compare with logged errors from other banks/cpus. This might allow us to distinguish multiple errors logged in the same #CMCI, from errors logged in separate #CMCI a tenth of a second apart.

Quoted 3 lines

If we found the error while polling, we didn’t want to provide a false sense of precision. The error could have been logged up to five minutes previously (or when logging errors during the initial poll of the banks an arbitrary time in the past).

Right, looks like we've lost that logic:

Functions calling this function: machine_check_poll

File Function Line
0 mce-inject.c raise_poll 57 machine_check_poll(0, &b);

1 mce.c        mce_timer_fn              1358 machine_check_poll(MCP_TIMESTAMP, this_cpu_ptr(&mce_poll_banks));
2 mce.c        __mcheck_cpu_init_generic 1508 machine_check_poll(MCP_UC | m_fl, &all_banks);
3 mce_intel.c  mce_intel_cmci_poll        133 if (machine_check_poll(MCP_TIMESTAMP, this_cpu_ptr(&mce_banks_owned)))
4 mce_intel.c  intel_threshold_interrupt  253 machine_check_poll(MCP_TIMESTAMP, this_cpu_ptr(&mce_banks_owned));
5 mce_intel.c  cmci_recheck               345 machine_check_poll(MCP_TIMESTAMP, this_cpu_ptr(&mce_banks_owned));

So the TSC timestamp will be possibly inexact now in mce_timer_fn(), __mcheck_cpu_init_generic(), mce_intel_cmci_poll() and cmci_recheck().

Should we bother and add a flag to struct mce - maybe somewhere in the padding __u8 pad; - to denote that the logged TSC may not be exact?

Mind you, there's also

	m->time = get_seconds();

which also collects time and which could also be possibly inexact.

One other possibility would be to use ->time and write ->tsc *only* when exact - i.e., in the handler - and this is then enough info about timing.

->time will give you somewhere around where it happened and ->tsc - only if set - will give you exact, well, *timestamp* :)

This sounds like a pretty straightforward logic to me...

Signature · 4 lines
Regards/Gruss,
    Boris.

Good mailing practices for 400: avoid top-posting and trim the reply.
#9 lore raw

RE: [PATCH] x86/MCE: Remove MCP_TIMESTAMP

Quoted 8 lines

One other possibility would be to use ->time and write ->tsc *only* when exact - i.e., in the handler - and this is then enough info about timing.

->time will give you somewhere around where it happened and ->tsc - only if set - will give you exact, well, *timestamp* :)

This sounds like a pretty straightforward logic to me...

Also to me ... and I think that's what used to happen (or at least was the intent).

-Tony

author maintainer
#10 lore raw

Re: [PATCH] x86/MCE: Remove MCP_TIMESTAMP

Quoted 2 lines · Tony

Also to me ... and I think that's what used to happen (or at least was the intent).

How's that?

This still preserves the precise TSC timestamp in intel_threshold_interrupt().

---
From: Borislav Petkov <[email protected]>
Date: Tue, 8 Nov 2016 16:20:05 +0100
Subject: [PATCH] x86/MCE: Correct TSC timestamping of error records

We did have logic in the MCE code which would TSC-timestamp an error record only when it is exact - i.e., it wasn't detected by polling. This isn't the case anymore. So let's fix that:

We have a TSC timestamp in the error record only when it has been a precise detection, i.e., either in the #MC handler or in one of the interrupt handlers (thresholding, deferred, ...).

All other error records still have mce.time which contains the wall time in order to be able to place the error record in time approximately.

Also, this fixes another bug where machine_check_poll() would clear mce.tsc unconditionally even if we requested precise MCP_TIMESTAMP logging.

Signed-off-by Borislav Petkov <[email protected]>
Cc Tony Luck <[email protected]>
---
 arch/x86/kernel/cpu/mcheck/mce.c       | 3 +--
 arch/x86/kernel/cpu/mcheck/mce_intel.c | 4 ++--
 2 files changed, 3 insertions(+), 4 deletions(-)
arch/x86/kernel/cpu/mcheck/mce.c +1 -2
index 4ca00474804b..b7a976d657f3 100644
@@ -713,7 +713,6 @@ bool machine_check_poll(enum mcp_flags flags, mce_banks_t *b)
 		m.misc = 0;
 		m.addr = 0;
 		m.bank = i;
-		m.tsc = 0;
 
 		barrier();
 		m.status = mce_rdmsrl(msr_ops.status(i));

@@ -1394,7 +1393,7 @@ static void mce_timer_fn(unsigned long data)
 	iv = __this_cpu_read(mce_next_interval);
 
 	if (mce_available(this_cpu_ptr(&cpu_info))) {
-		machine_check_poll(MCP_TIMESTAMP, this_cpu_ptr(&mce_poll_banks));
+		machine_check_poll(0, this_cpu_ptr(&mce_poll_banks));
 
 		if (mce_intel_cmci_poll()) {
 			iv = mce_adjust_timer(iv);
arch/x86/kernel/cpu/mcheck/mce_intel.c +2 -2
index 1defb8ea882c..be0b2fad47c5 100644
@@ -130,7 +130,7 @@ bool mce_intel_cmci_poll(void)
 	 * Reset the counter if we've logged an error in the last poll
 	 * during the storm.
 	 */
-	if (machine_check_poll(MCP_TIMESTAMP, this_cpu_ptr(&mce_banks_owned)))
+	if (machine_check_poll(0, this_cpu_ptr(&mce_banks_owned)))
 		this_cpu_write(cmci_backoff_cnt, INITIAL_CHECK_INTERVAL);
 	else
 		this_cpu_dec(cmci_backoff_cnt);

@@ -342,7 +342,7 @@ void cmci_recheck(void)
 		return;
 
 	local_irq_save(flags);
-	machine_check_poll(MCP_TIMESTAMP, this_cpu_ptr(&mce_banks_owned));
+	machine_check_poll(0, this_cpu_ptr(&mce_banks_owned));
 	local_irq_restore(flags);
 }
Signature · 7 lines
2.10.0

-- 
Regards/Gruss,
    Boris.

Good mailing practices for 400: avoid top-posting and trim the reply.
Acked-by
#11 lore raw

RE: [PATCH] x86/MCE: Remove MCP_TIMESTAMP

Quoted 1 line

This still preserves the precise TSC timestamp in intel_threshold_interrupt().

Yup - this looks right.

Acked-by Tony Luck <[email protected]>

-Tony

#12 lore raw

Re: [PATCH] x86/MCE: Remove MCP_TIMESTAMP

In reply to Borislav Petkov

arch/x86/kernel/cpu/mcheck/mce.c bool machine_check_poll(enum mcp_flags flags, mce_banks_t *b) · line 716

Quoted 10 lines · Borislav Petkov

Also, this fixes another bug where machine_check_poll() would clear mce.tsc unconditionally even if we requested precise MCP_TIMESTAMP logging.

arch/x86/kernel/cpu/mcheck/mce.c +0 -1
@@ -713,7 +713,6 @@ bool machine_check_poll(enum mcp_flags flags, mce_banks_t *b)
 		m.misc = 0;
 		m.addr = 0;
 		m.bank = i;
-		m.tsc = 0;

That does not make any sense. Where is m.tsc initialized? I couldn't find any place which does, except this and the conditional clear farther down in that function.

Thanks,

tglx

author maintainer
#13 lore raw

Re: [PATCH] x86/MCE: Remove MCP_TIMESTAMP

Quoted 3 lines · Thomas Gleixner

That does not make any sense. Where is m.tsc initialized? I couldn't find any place which does, except this and the conditional clear farther down in that function.

mce_gather_info->mce_setup does

m->tsc = rdtsc();

And we do that *everytime* but then we go and clear the damn thing. I know, I know, I wanted to flip that logic too and read the TSC *only* when we want a precise timestamp but that would require more changes as mce_setup() is used at a bunch of places.

Signature · 4 lines
Regards/Gruss,
    Boris.

Good mailing practices for 400: avoid top-posting and trim the reply.
#14 lore raw

Re: [PATCH] x86/MCE: Remove MCP_TIMESTAMP

Quoted 5 lines · Borislav Petkov
Quoted 3 lines · Thomas Gleixner

That does not make any sense. Where is m.tsc initialized? I couldn't find any place which does, except this and the conditional clear farther down in that function.

Quoted 8 lines

mce_gather_info->mce_setup does

m->tsc = rdtsc();

And we do that *everytime* but then we go and clear the damn thing. I know, I know, I wanted to flip that logic too and read the TSC *only* when we want a precise timestamp but that would require more changes as mce_setup() is used at a bunch of places.

And yes, you should spend the extra cycles. Adding a flags argument to mce_setup() and propagate it through the various callsites shouldn't be that hard and would make the stuff obvious instead of obfuscated.

Thanks,

tglx

author maintainer
#15 lore raw

Re: [PATCH] x86/MCE: Remove MCP_TIMESTAMP

Quoted 3 lines · Thomas Gleixner

And yes, you should spend the extra cycles. Adding a flags argument to mce_setup() and propagate it through the various callsites shouldn't be that hard and would make the stuff obvious instead of obfuscated.

Sure, that's already on my TODO. I want to take a look at it when I have a quiet moment.

Signature · 4 lines
Regards/Gruss,
    Boris.

Good mailing practices for 400: avoid top-posting and trim the reply.
#16 lore raw

Re: [PATCH] x86/MCE: Remove MCP_TIMESTAMP

Quoted 7 lines · Borislav Petkov
Quoted 3 lines · Thomas Gleixner

And yes, you should spend the extra cycles. Adding a flags argument to mce_setup() and propagate it through the various callsites shouldn't be that hard and would make the stuff obvious instead of obfuscated.

Sure, that's already on my TODO. I want to take a look at it when I have a quiet moment.

So for now we should fold something like the below into this patch.

Thanks,

tglx

8<--------------------

arch/x86/kernel/cpu/mcheck/mce.c +9 -3
@@ -706,6 +706,15 @@ bool machine_check_poll(enum mcp_flags f
 
 	mce_gather_info(&m, NULL);
 
+	/*
+	 * m.tsc was set in mce_setup(). Clear it if not requested.
+	 *
+	 * FIXME: Propagate @flags to mce_gather_info/mce_setup() to avoid
+	 *	  that dance
+	 */
+	if (!(flags & MCP_TIMESTAMP))
+		m.tsc = 0;
+
 	for (i = 0; i < mca_cfg.banks; i++) {
 		if (!mce_banks[i].ctl || !test_bit(i, *b))
 			continue;

@@ -734,9 +743,6 @@ bool machine_check_poll(enum mcp_flags f
 
 		mce_read_aux(&m, i);
 
-		if (!(flags & MCP_TIMESTAMP))
-			m.tsc = 0;
-
 		severity = mce_severity(&m, mca_cfg.tolerant, NULL, false);
 
 		if (severity == MCE_DEFERRED_SEVERITY && memory_error(&m))
author maintainer
#17 lore raw

Re: [PATCH] x86/MCE: Remove MCP_TIMESTAMP

Quoted 1 line · Thomas Gleixner

So for now we should fold something like the below into this patch.

Ok, how's that?

---
From: Borislav Petkov <[email protected]>
Date: Tue, 8 Nov 2016 16:20:05 +0100
Subject: [PATCH] x86/MCE: Correct TSC timestamping of error records

We did have logic in the MCE code which would TSC-timestamp an error record only when it is exact - i.e., when it wasn't detected by polling. This isn't the case anymore. So let's fix that:

We have a valid TSC timestamp in the error record only when it has been a precise detection, i.e., either in the #MC handler or in one of the interrupt handlers (thresholding, deferred, ...).

All other error records still have mce.time which contains the wall time in order to be able to place the error record in time at least approximately.

Also, this fixes another bug where machine_check_poll() would clear mce.tsc unconditionally even if we requested precise MCP_TIMESTAMP logging.

The proper fix would be to generate timestamp only when it has been requested and not always. But that would require a more thorough code audit of all mce_gather_info/mce_setup() users. Add a FIXME for now, courtesy of tglx.

Signed-off-by Borislav Petkov <[email protected]>
Cc Tony Luck <[email protected]>
Cc Thomas Gleixner <[email protected]>
---
 arch/x86/kernel/cpu/mcheck/mce.c       | 18 ++++++++++++------
 arch/x86/kernel/cpu/mcheck/mce_intel.c |  4 ++--
 2 files changed, 14 insertions(+), 8 deletions(-)
arch/x86/kernel/cpu/mcheck/mce.c +12 -6
index 4ca00474804b..3fbe80066b4e 100644
@@ -706,6 +706,17 @@ bool machine_check_poll(enum mcp_flags flags, mce_banks_t *b)
 
 	mce_gather_info(&m, NULL);
 
+	/*
+	 * m.tsc was set in mce_setup(). Clear it if not requested.
+	 *
+	 * FIXME: Propagate @flags to mce_gather_info/mce_setup() to avoid
+	 *	  that dance.
+	 */
+	if (!(flags & MCP_TIMESTAMP)) {
+		WARN_ON_ONCE(m.tsc);
+		m.tsc = 0;
+	}
+
 	for (i = 0; i < mca_cfg.banks; i++) {
 		if (!mce_banks[i].ctl || !test_bit(i, *b))
 			continue;

@@ -713,14 +724,12 @@ bool machine_check_poll(enum mcp_flags flags, mce_banks_t *b)
 		m.misc = 0;
 		m.addr = 0;
 		m.bank = i;
-		m.tsc = 0;
 
 		barrier();
 		m.status = mce_rdmsrl(msr_ops.status(i));
 		if (!(m.status & MCI_STATUS_VAL))
 			continue;
 
-
 		/*
 		 * Uncorrected or signalled events are handled by the exception
 		 * handler when it is enabled, so don't process those here.

@@ -735,9 +744,6 @@ bool machine_check_poll(enum mcp_flags flags, mce_banks_t *b)
 
 		mce_read_aux(&m, i);
 
-		if (!(flags & MCP_TIMESTAMP))
-			m.tsc = 0;
-
 		severity = mce_severity(&m, mca_cfg.tolerant, NULL, false);
 
 		if (severity == MCE_DEFERRED_SEVERITY && memory_error(&m))

@@ -1394,7 +1400,7 @@ static void mce_timer_fn(unsigned long data)
 	iv = __this_cpu_read(mce_next_interval);
 
 	if (mce_available(this_cpu_ptr(&cpu_info))) {
-		machine_check_poll(MCP_TIMESTAMP, this_cpu_ptr(&mce_poll_banks));
+		machine_check_poll(0, this_cpu_ptr(&mce_poll_banks));
 
 		if (mce_intel_cmci_poll()) {
 			iv = mce_adjust_timer(iv);
arch/x86/kernel/cpu/mcheck/mce_intel.c +2 -2
index 1defb8ea882c..be0b2fad47c5 100644
@@ -130,7 +130,7 @@ bool mce_intel_cmci_poll(void)
 	 * Reset the counter if we've logged an error in the last poll
 	 * during the storm.
 	 */
-	if (machine_check_poll(MCP_TIMESTAMP, this_cpu_ptr(&mce_banks_owned)))
+	if (machine_check_poll(0, this_cpu_ptr(&mce_banks_owned)))
 		this_cpu_write(cmci_backoff_cnt, INITIAL_CHECK_INTERVAL);
 	else
 		this_cpu_dec(cmci_backoff_cnt);

@@ -342,7 +342,7 @@ void cmci_recheck(void)
 		return;
 
 	local_irq_save(flags);
-	machine_check_poll(MCP_TIMESTAMP, this_cpu_ptr(&mce_banks_owned));
+	machine_check_poll(0, this_cpu_ptr(&mce_banks_owned));
 	local_irq_restore(flags);
 }
Signature · 7 lines
2.10.0

-- 
Regards/Gruss,
    Boris.

Good mailing practices for 400: avoid top-posting and trim the reply.
author maintainer
#18 lore raw

Re: [PATCH] x86/MCE: Remove MCP_TIMESTAMP

Quoted 5 lines · Borislav Petkov
arch/x86/kernel/cpu/mcheck/mce.c +0 -0
index 4ca00474804b..3fbe80066b4e 100644

arch/x86/kernel/cpu/mcheck/mce.c bool machine_check_poll(enum mcp_flags flags, mce_banks_t *b) · line 714

Quoted 9 lines
arch/x86/kernel/cpu/mcheck/mce.c +6 -0
@@ -706,6 +706,17 @@ bool machine_check_poll(enum mcp_flags flags, mce_banks_t *b)
 
 	mce_gather_info(&m, NULL);
 
+	/*
+	 * m.tsc was set in mce_setup(). Clear it if not requested.
+	 *
+	 * FIXME: Propagate @flags to mce_gather_info/mce_setup() to avoid
+	 *	  that dance.
+	 */

Lemme try to address that FIXME. So it doesn't look particularly easy to do without touching/changing a bunch of places. That's why I'm trying tricks first.

For example, the mce-apei.c case I'm addressing by setting ->tsc only for errors of panic severity. The idea there is, that, panic errors will have raised an #MC and not polled.

And then instead of propagating a flag to mce_setup(), it seems easier/less code to set ->tsc depending on the call sites, i.e., are we polling or are we preparing an MCE record in an exception handler/thresholding interrupt.

I'll run it tomorrow.

---

arch/x86/kernel/cpu/mcheck/mce-apei.c +4 -1
index 83f1a98d37db..2eee85379689 100644
@@ -52,8 +52,11 @@ void apei_mce_report_mem_error(int severity, struct cper_sec_mem_err *mem_err)
 
 	if (severity >= GHES_SEV_RECOVERABLE)
 		m.status |= MCI_STATUS_UC;
-	if (severity >= GHES_SEV_PANIC)
+
+	if (severity >= GHES_SEV_PANIC) {
 		m.status |= MCI_STATUS_PCC;
+		m.tsc = rdtsc();
+	}
 
 	m.addr = mem_err->physical_addr;
 	mce_log(&m);
arch/x86/kernel/cpu/mcheck/mce.c +3 -9
index 6eef6fde0f02..ca15a7e1f97d 100644
@@ -128,7 +128,6 @@ void mce_setup(struct mce *m)
 {
 	memset(m, 0, sizeof(struct mce));
 	m->cpu = m->extcpu = smp_processor_id();
-	m->tsc = rdtsc();
 	/* We hope get_seconds stays lockless */
 	m->time = get_seconds();
 	m->cpuvendor = boot_cpu_data.x86_vendor;

@@ -710,14 +709,8 @@ bool machine_check_poll(enum mcp_flags flags, mce_banks_t *b)
 
 	mce_gather_info(&m, NULL);
 
-	/*
-	 * m.tsc was set in mce_setup(). Clear it if not requested.
-	 *
-	 * FIXME: Propagate @flags to mce_gather_info/mce_setup() to avoid
-	 *	  that dance.
-	 */
-	if (!(flags & MCP_TIMESTAMP))
-		m.tsc = 0;
+	if (flags & MCP_TIMESTAMP)
+		m.tsc = rdtsc();
 
 	for (i = 0; i < mca_cfg.banks; i++) {
 		if (!mce_banks[i].ctl || !test_bit(i, *b))

@@ -1156,6 +1149,7 @@ void do_machine_check(struct pt_regs *regs, long error_code)
 		goto out;
 
 	mce_gather_info(&m, regs);
+	m.tsc = rdtsc();
 
 	final = this_cpu_ptr(&mces_seen);
 	*final = m;
arch/x86/kernel/cpu/mcheck/mce_amd.c +2 -1
index 776379e4a39c..9e5427df3243 100644
@@ -778,7 +778,8 @@ __log_error(unsigned int bank, bool deferred_err, bool threshold_err, u64 misc)
 	mce_setup(&m);
 
 	m.status = status;
-	m.bank = bank;
+	m.bank   = bank;
+	m.tsc	 = rdtsc();
 
 	if (threshold_err)
 		m.misc = misc;
Signature · 4 lines
Regards/Gruss,
    Boris.

Good mailing practices for 400: avoid top-posting and trim the reply.
author maintainer
#19 lore raw

Re: [PATCH] x86/MCE: Remove MCP_TIMESTAMP

Quoted 1 line · Borislav Petkov

I'll run it tomorrow.

Ok, here it is, it looks ok while testing in a guest and injecting MCEs.

---
From: Borislav Petkov <[email protected]>
Date: Wed, 18 Jan 2017 21:34:41 +0100
Subject: [PATCH] x86/MCE: Flip the TSC-adding logic

Add the TSC value to the MCE record only when the MCE being logged is precise, i.e., it is logged as an exception or an MCE-related interrupt.

So it doesn't look particularly easy to do without touching/changing a bunch of places. That's why I'm trying tricks first.

For example, the mce-apei.c case I'm addressing by setting ->tsc only for errors of panic severity. The idea there is, that, panic errors will have raised an #MC and not polled.

And then instead of propagating a flag to mce_setup(), it seems easier/less code to set ->tsc depending on the call sites, i.e., are we polling or are we preparing an MCE record in an exception handler/thresholding interrupt.

Signed-off-by Borislav Petkov <[email protected]>
---
 arch/x86/kernel/cpu/mcheck/mce-apei.c |  5 ++++-
 arch/x86/kernel/cpu/mcheck/mce.c      | 12 +++---------
 arch/x86/kernel/cpu/mcheck/mce_amd.c  |  3 ++-
 3 files changed, 9 insertions(+), 11 deletions(-)
arch/x86/kernel/cpu/mcheck/mce-apei.c +4 -1
index 83f1a98d37db..2eee85379689 100644
@@ -52,8 +52,11 @@ void apei_mce_report_mem_error(int severity, struct cper_sec_mem_err *mem_err)
 
 	if (severity >= GHES_SEV_RECOVERABLE)
 		m.status |= MCI_STATUS_UC;
-	if (severity >= GHES_SEV_PANIC)
+
+	if (severity >= GHES_SEV_PANIC) {
 		m.status |= MCI_STATUS_PCC;
+		m.tsc = rdtsc();
+	}
 
 	m.addr = mem_err->physical_addr;
 	mce_log(&m);
arch/x86/kernel/cpu/mcheck/mce.c +3 -9
index 6eef6fde0f02..ca15a7e1f97d 100644
@@ -128,7 +128,6 @@ void mce_setup(struct mce *m)
 {
 	memset(m, 0, sizeof(struct mce));
 	m->cpu = m->extcpu = smp_processor_id();
-	m->tsc = rdtsc();
 	/* We hope get_seconds stays lockless */
 	m->time = get_seconds();
 	m->cpuvendor = boot_cpu_data.x86_vendor;

@@ -710,14 +709,8 @@ bool machine_check_poll(enum mcp_flags flags, mce_banks_t *b)
 
 	mce_gather_info(&m, NULL);
 
-	/*
-	 * m.tsc was set in mce_setup(). Clear it if not requested.
-	 *
-	 * FIXME: Propagate @flags to mce_gather_info/mce_setup() to avoid
-	 *	  that dance.
-	 */
-	if (!(flags & MCP_TIMESTAMP))
-		m.tsc = 0;
+	if (flags & MCP_TIMESTAMP)
+		m.tsc = rdtsc();
 
 	for (i = 0; i < mca_cfg.banks; i++) {
 		if (!mce_banks[i].ctl || !test_bit(i, *b))

@@ -1156,6 +1149,7 @@ void do_machine_check(struct pt_regs *regs, long error_code)
 		goto out;
 
 	mce_gather_info(&m, regs);
+	m.tsc = rdtsc();
 
 	final = this_cpu_ptr(&mces_seen);
 	*final = m;
arch/x86/kernel/cpu/mcheck/mce_amd.c +2 -1
index 776379e4a39c..9e5427df3243 100644
@@ -778,7 +778,8 @@ __log_error(unsigned int bank, bool deferred_err, bool threshold_err, u64 misc)
 	mce_setup(&m);
 
 	m.status = status;
-	m.bank = bank;
+	m.bank   = bank;
+	m.tsc	 = rdtsc();
 
 	if (threshold_err)
 		m.misc = misc;
Signature · 7 lines
2.11.0

-- 
Regards/Gruss,
    Boris.

Good mailing practices for 400: avoid top-posting and trim the reply.
#20 lore raw
In reply to Borislav Petkov
Quoted 15 lines · Borislav Petkov

From: Borislav Petkov <[email protected]>

Right,

so this is not a good thing: systems may not have any error record consumers registered and in such cases, any logged MCEs disappear into the void. And this shouldn't happen.

So let's dump them to dmesg as a last resort.

Borislav Petkov (3):
notifiers: Document notifier priority
x86/RAS: Add TSC to the injected MCE
x86/MCE: Dump MCE to dmesg if no consumers

Quoted 4 lines
 arch/x86/kernel/cpu/mcheck/mce.c | 52 +++++++++++++++++++++++++++++++++++-----
 arch/x86/ras/mce_amd_inj.c       |  2 ++
 include/linux/notifier.h         |  1 +
 3 files changed, 49 insertions(+), 6 deletions(-)

Sounds good to me!

Thanks,

Ingo