[PATCH] powerpc/perf: Fix PMU callbacks to clear pending PMI before resetting an overflown PMC

Nicholas Piggin npiggin at gmail.com
Mon Apr 12 13:08:26 AEST 2021


Excerpts from Athira Rajeev's message of April 9, 2021 10:53 pm:
> 
> 
>> On 09-Apr-2021, at 6:38 AM, Nicholas Piggin <npiggin at gmail.com> wrote:
>> 
> Hi Nick,
> 
> Thanks for checking the patch and sharing review comments.
> 
>> I was going to nitpick "overflown" here as something birds do, but some
>> sources says overflown is okay for past tense.
>> 
>> You could use "overflowed" for that, but I understand the issue with the 
>> word: you are talking about counters that are currently in an "overflow" 
>> state, but the overflow occurred in the past and is not still happening
>> so you "overflowing" doesn't exactly fit either.
>> 
>> overflown kind of works for some reason you can kind of use it for
>> present tense!
> 
> Ok sure, Yes counter is currently in an “overflow” state.
> 
>> 
>> Excerpts from Athira Rajeev's message of April 7, 2021 12:47 am:
>>> Running perf fuzzer showed below in dmesg logs:
>>> "Can't find PMC that caused IRQ"
>>> 
>>> This means a PMU exception happened, but none of the PMC's (Performance
>>> Monitor Counter) were found to be overflown. There are some corner cases
>>> that clears the PMCs after PMI gets masked. In such cases, the perf
>>> interrupt handler will not find the active PMC values that had caused
>>> the overflow and thus leads to this message while replaying.
>>> 
>>> Case 1: PMU Interrupt happens during replay of other interrupts and
>>> counter values gets cleared by PMU callbacks before replay:
>>> 
>>> During replay of interrupts like timer, __do_irq and doorbell exception, we
>>> conditionally enable interrupts via may_hard_irq_enable(). This could
>>> potentially create a window to generate a PMI. Since irq soft mask is set
>>> to ALL_DISABLED, the PMI will get masked here.
>> 
>> I wonder if may_hard_irq_enable shouldn't enable if PMI is soft
>> disabled. And also maybe replay should not set ALL_DISABLED if
>> there are no PMI interrupts pending.
>> 
>> Still, I think those are a bit more tricky and might take a while
>> to get right or just not be worth while, so I think your patch is
>> fine.
> 
> Ok Nick.
>> 
>>> We could get IPIs run before
>>> perf interrupt is replayed and the PMU events could deleted or stopped.
>>> This will change the PMU SPR values and resets the counters. Snippet of
>>> ftrace log showing PMU callbacks invoked in "__do_irq":
>>> 
>>> <idle>-0 [051] dns. 132025441306354: __do_irq <-call_do_irq
>>> <idle>-0 [051] dns. 132025441306430: irq_enter <-__do_irq
>>> <idle>-0 [051] dns. 132025441306503: irq_enter_rcu <-__do_irq
>>> <idle>-0 [051] dnH. 132025441306599: xive_get_irq <-__do_irq
>>> <<>>
>>> <idle>-0 [051] dnH. 132025441307770: generic_smp_call_function_single_interrupt <-smp_ipi_demux_relaxed
>>> <idle>-0 [051] dnH. 132025441307839: flush_smp_call_function_queue <-smp_ipi_demux_relaxed
>>> <idle>-0 [051] dnH. 132025441308057: _raw_spin_lock <-event_function
>>> <idle>-0 [051] dnH. 132025441308206: power_pmu_disable <-perf_pmu_disable
>>> <idle>-0 [051] dnH. 132025441308337: power_pmu_del <-event_sched_out
>>> <idle>-0 [051] dnH. 132025441308407: power_pmu_read <-power_pmu_del
>>> <idle>-0 [051] dnH. 132025441308477: read_pmc <-power_pmu_read
>>> <idle>-0 [051] dnH. 132025441308590: isa207_disable_pmc <-power_pmu_del
>>> <idle>-0 [051] dnH. 132025441308663: write_pmc <-power_pmu_del
>>> <idle>-0 [051] dnH. 132025441308787: power_pmu_event_idx <-perf_event_update_userpage
>>> <idle>-0 [051] dnH. 132025441308859: rcu_read_unlock_strict <-perf_event_update_userpage
>>> <idle>-0 [051] dnH. 132025441308975: power_pmu_enable <-perf_pmu_enable
>>> <<>>
>>> <idle>-0 [051] dnH. 132025441311108: irq_exit <-__do_irq
>>> <idle>-0 [051] dns. 132025441311319: performance_monitor_exception <-replay_soft_interrupts
>>> 
>>> Case 2: PMI's masked during local_* operations, example local_add.
>>> If the local_add operation happens within a local_irq_save, replay of
>>> PMI will be during local_irq_restore. Similar to case 1, this could
>>> also create a window before replay where PMU events gets deleted or
>>> stopped.
>> 
>> Here as well perhaps PMIs should be replayed if they are unmasked
>> even if other interrupts are still masked. Again that might be more
>> complexity than it's worth.
> Ok..
> 
>> 
>>> 
>>> Patch adds a fix to update the PMU callback functions (del,stop,enable) to
>>> check for pending perf interrupt. If there is an overflown PMC and pending
>>> perf interrupt indicated in Paca, clear the PMI bit in paca to drop that
>>> sample. In case of power_pmu_del, also clear the MMCR0 PMAO bit which
>>> otherwise could lead to spurious interrupts in some corner cases. Example,
>>> a timer after power_pmu_del which will re-enable interrupts since PMI is
>>> cleared and triggers a PMI again since PMAO bit is still set.
>>> 
>>> We can't just replay PMI any time. Hence this approach is preferred rather
>>> than replaying PMI before resetting overflown PMC. Patch also documents
>>> core-book3s on a race condition which can trigger these PMC messages during
>>> idle path in PowerNV.
>>> 
>>> Fixes: f442d004806e ("powerpc/64s: Add support to mask perf interrupts and replay them")
>>> Reported-by: Nageswara R Sastry <nasastry at in.ibm.com>
>>> Suggested-by: Nicholas Piggin <npiggin at gmail.com>
>>> Suggested-by: Madhavan Srinivasan <maddy at linux.ibm.com>
>>> Signed-off-by: Athira Rajeev <atrajeev at linux.vnet.ibm.com>
>>> ---
>>> arch/powerpc/include/asm/pmc.h  | 11 +++++++++
>>> arch/powerpc/perf/core-book3s.c | 55 +++++++++++++++++++++++++++++++++++++++++
>>> 2 files changed, 66 insertions(+)
>>> 
>>> diff --git a/arch/powerpc/include/asm/pmc.h b/arch/powerpc/include/asm/pmc.h
>>> index c6bbe9778d3c..97b4bd8de25b 100644
>>> --- a/arch/powerpc/include/asm/pmc.h
>>> +++ b/arch/powerpc/include/asm/pmc.h
>>> @@ -34,11 +34,22 @@ static inline void ppc_set_pmu_inuse(int inuse)
>>> #endif
>>> }
>>> 
>>> +static inline int clear_paca_irq_pmi(void)
>>> +{
>>> +	if (get_paca()->irq_happened & PACA_IRQ_PMI) {
>>> +		WARN_ON_ONCE(mfmsr() & MSR_EE);
>>> +		get_paca()->irq_happened &= ~PACA_IRQ_PMI;
>>> +		return 1;
>>> +	}
>>> +	return 0;
>>> +}
>> 
>> Could you put this in arch/powerpc/include/asm/hw_irq.h and
>> rather than paca_irq, call it irq_pending perhaps
>> 
>>  clear_pmi_irq_pending()
>> 
>>  get_clear_pmi_irq_pending() if you're also testing it.
> 
> Sure,  I will use “get_clear_pmi_irq_pending()” and try with moving this to arch/powerpc/include/asm/hw_irq.h
> 
>> 
>> Could you add a little comment about the corner cases above it too?
>> The root cause seem to be interrupt replay while a masked PMI is
>> pending can result in other interrupts arriving which clear the PMU
>> overflow so the pending PMI must be cleared.
> 
> Ok, I will add comment and fix this in next version.
> 
>> 
>>> +
>>> extern void power4_enable_pmcs(void);
>>> 
>>> #else /* CONFIG_PPC64 */
>>> 
>>> static inline void ppc_set_pmu_inuse(int inuse) { }
>>> +static inline int clear_paca_irq_pmi(void) { return 0; }
>>> 
>>> #endif
>>> 
>>> diff --git a/arch/powerpc/perf/core-book3s.c b/arch/powerpc/perf/core-book3s.c
>>> index 766f064f00fb..18ca3c90f866 100644
>>> --- a/arch/powerpc/perf/core-book3s.c
>>> +++ b/arch/powerpc/perf/core-book3s.c
>>> @@ -847,6 +847,20 @@ static void write_pmc(int idx, unsigned long val)
>>> 	}
>>> }
>>> 
>>> +static int pmc_overflown(int idx)
>>> +{
>>> +	unsigned long val[8];
>>> +	int i;
>>> +
>>> +	for (i = 0; i < ppmu->n_counter; i++)
>>> +		val[i] = read_pmc(i + 1);
>>> +
>>> +	if ((int)val[idx-1] < 0)
>>> +		return 1;
>>> +
>>> +	return 0;
>>> +}
>>> +
>>> /* Called from sysrq_handle_showregs() */
>>> void perf_event_print_debug(void)
>>> {
>>> @@ -1438,6 +1452,15 @@ static void power_pmu_enable(struct pmu *pmu)
>>> 		event = cpuhw->event[i];
>>> 		if (event->hw.idx && event->hw.idx != hwc_index[i] + 1) {
>>> 			power_pmu_read(event);
>>> +			/*
>>> +			 * if the PMC corresponding to event->hw.idx is
>>> +			 * overflown, check if there is any pending perf
>>> +			 * interrupt set in paca. If so, disable the interrupt
>>> +			 * by clearing the paca bit for PMI since we are going
>>> +			 * to reset the PMC.
>>> +			 */
>>> +			if (pmc_overflown(event->hw.idx))
>>> +				clear_paca_irq_pmi();
>> 
>> If the pmc is not overflown, could there still be a PMI pending?
> 
> I didn’t hit that scenario where PMI is pending without an overflown PMC.
> Also I believe if such a case happens, we will need an investigation there. It could be a different case to be handled.

Okay, so a PMI will not occur without an overflown PMC, and the 
overflown PMC will only be cleared in places where you also clear a 
possible pending PMI?

> 
> I actually considered below two points for adding this PMC check instead of just clearing the PMI.
> 
> 1. Make sure we are not masking any bug here by just clearing PACA_IRQ_PMI.
> Ideally if PMI is set in irq_happened, it means there was a counter overflow.
> 2. If there is more than one PMU event, say two events. Make sure we are clearing PMI only for the
> event whose counter is overflown.

Those are good points. Would you consider also adding a warning for the 
case of no PMCs overflown but PMI is pending? That way you might have more 
information about such a problem if it ever happens.

We try to add a good deal of warnings around the soft-mask code because 
it's very tricky to change without causing more bugs, so even for future
changes to the code this would probably be useful.

>>> @@ -1636,6 +1664,22 @@ static void power_pmu_del(struct perf_event *event, int ef_flags)
>>> 			--cpuhw->n_events;
>>> 			ppmu->disable_pmc(event->hw.idx - 1, &cpuhw->mmcr);
>>> 			if (event->hw.idx) {
>>> +				/*
>>> +				 * if the PMC corresponding to event->hw.idx is
>>> +				 * overflown, check if there is any pending perf
>>> +				 * interrupt set in paca. If so, disable the interrupt
>>> +				 * and clear the MMCR0 PMAO bit since we are going
>>> +				 * to reset the PMC and delete the event.
>>> +				 */
>>> +				if (pmc_overflown(event->hw.idx)) {
>>> +					if (clear_paca_irq_pmi()) {
>>> +						val_mmcr0 = mfspr(SPRN_MMCR0);
>>> +						val_mmcr0 &= ~MMCR0_PMAO;
>>> +						write_mmcr0(cpuhw, val_mmcr0);
>>> +						mb();
>>> +						isync();
>> 
>> I don't know the perf subsystem, but just out of curiosity why does
>> MMCR0 need to be cleared only in this case?
> 
> I got a corner case in power_pmu_del, with only clearing PACA_IRQ_PMI and without resetting MMCR0 PMAO bit.
> Here is the flow:
> 
> 1. We clear the PMI bit Paca, but MMCR0 has the PMAO bit still set. PMAO bit indicates a PMI has occurred.
> 2. A timer interrupt is replayed after power_pmu_del which does a “may_hard_irq_enable”.
> This will re-enable interrupts and triggers a PMI again since PMAO bit is still set.
> 
> So clear PMAO bit to avoid such spurious interrupts.
> Ftrace logs showing the same with some debug trace_printks :
> 
>      <idle>-0    [134] d.h. 327287888478: power_pmu_del <-event_sched_out.isra.126
>      <<>>    Here we cleared the PMI
>      <idle>-0    [134] d.h. 327287889272: write_pmc <-power_pmu_del
>      <idle>-0    [134] d.h. 327287889346: rcu_read_unlock_strict <-perf_event_update_userpage
>      <idle>-0    [134] d.h. 327287889711: power_pmu_del: In power_pmu_del MMCR0 is 82004090, local_paca->irq_happened is 9
>      <idle>-0    [134] d.h. 327287889811: power_pmu_enable <-perf_pmu_enable
>      <idle>-0    [134] d.h. 327287889982: irq_exit <-doorbell_exception
>      <idle>-0    [134] d... 327287890053: idle_cpu <-irq_exit
>      <idle>-0    [134] d... 327287890158: tick_nohz_irq_exit <-irq_exit
>      <idle>-0    [134] d... 327287890219: ktime_get <-tick_nohz_irq_exit
>      <idle>-0    [134] d... 327287890328: replay_soft_interrupts <-interrupt_exit_kernel_prepare
>      <idle>-0    [134] d... 327287890399: irq_enter <-timer_interrupt
>      <<>>
>      <idle>-0    [134] d.h. 327287891163: timer_interrupt: Before may_hard_irq_enable MMCR0 is 82004090, local_paca->irq_happened is 1
>      <<>>
>      <idle>-0    [134] d.h. 327287894310: timer_interrupt: After may_hard_irq_enable MMCR0 is 82004090, local_paca->irq_happened is 21
> 
> In case of other callbacks like pmu enable, we are programming MMCR0. But in case of event getting deleted, there is no
> way we clear PMAO unless an event gets scheduled again in that cpu. Hence added this check only in pmu_del callback.
>  
> 
>> What if we disabled MSR[EE]
>> right before a perf interrupt came in, so we don't get a pending PMI
>> but the condition is still close to the same.
> 
> Nick, I didn’t get this question exactly. Can you please help explain a bit ?
> From my understanding, consider that we disabled MSR[EE] before perf interrupt came in.
> So once the interrupts are re-enabled:
> 
> 1. If soft mask is set to IRQS_DISABLED, perf interrupt will be triggered as NMI.
> 2. In case of ALL_DISABLED, it will be masked for replay. If PMU callbacks are invoked before replay,
> our present patch will take care of clearing PMI in corner cases.

Well I'm wondering about the same PMAO bug. Above you said:

  1. We clear the PMI bit Paca, but MMCR0 has the PMAO bit still set. PMAO bit indicates a PMI has occurred.
  2. A timer interrupt is replayed after power_pmu_del which does a “may_hard_irq_enable”.
  This will re-enable interrupts and triggers a PMI again since PMAO bit is still set.

So in this situation, what if we had disabled interrupts and that had 
caused MSR[EE] to be cleared (let's say due to a PCI interrupt 
arriving), and then a PMC overflows and causes PMAO to be set.

Then you run this code:

+				/*
+				 * if the PMC corresponding to event->hw.idx is
+				 * overflown, check if there is any pending perf
+				 * interrupt set in paca. If so, disable the interrupt
+				 * and clear the MMCR0 PMAO bit since we are going
+				 * to reset the PMC and delete the event.
+				 */
+				if (pmc_overflown(event->hw.idx)) {
+					if (clear_paca_irq_pmi()) {
+						val_mmcr0 = mfspr(SPRN_MMCR0);
+						val_mmcr0 &= ~MMCR0_PMAO;
+						write_mmcr0(cpuhw, val_mmcr0);
+						mb();
+						isync();

And this does not clear PMAO because we had no pending PMI, but we still 
have the pending PMAO exception.

The only difference was that MSR[EE] happened to be disabled when the 
PMC overflowed so no pending PMI was recorded, but otherwise everything 
is the same so I wonder why it's not subject to the same problem?

Thanks,
Nick


More information about the Linuxppc-dev mailing list