On Mon, 24 Jun 2019, Gleixner, Thomas wrote:
>
> The best way to figure out how the timing is of all those moving parts is
> to enable trace points and selective function tracing. That should give us
> a good picture.
>
> Thanks,
>
> tglx
>
>
Here are 2 logs, using ftrace with filter for do_IRQ(),
synchronize_irq(), some IRQ deactivation functions, and
irq_handler_entry event. The IRQ is assigned to the core#1, and the test
script (opening and closing the serial port) is running on core#0.
First time, I did not see the error message:
CPU 2 is empty
CPU 3 is empty
cpus=4
sh-2843 [001] 177.742582: function: do_IRQ <--
ret_from_intr
sh-2843 [001] 177.742591: irq_handler_entry: irq=3
name=ttyS1
cat-2837 [000] 177.742598: function:
synchronize_hardirq <-- __free_irq
cat-2837 [000] 177.742601: function:
x86_vector_deactivate <-- __irq_domain_deactivate_irq
cat-2837 [000] 177.742602: function:
clear_irq_vector <-- x86_vector_deactivate
cat-2837 [000] 177.749014: function:
reserve_irq_vector_locked <-- x86_vector_deactivate
As you see, do_IRQ() hit before synchronize_hardirq, and clear_irq_vector.
The second time, I got the error message:
CPU 2 is empty
CPU 3 is empty
cpus=4
cat-5240 [000] 1678.875391: function:
synchronize_hardirq <-- __free_irq
cat-5240 [000] 1678.875395: function:
x86_vector_deactivate <-- __irq_domain_deactivate_irq
cat-5240 [000] 1678.875396: function:
clear_irq_vector <-- x86_vector_deactivate
<idle>-0 [001] 1678.875521: function: *do_IRQ <--
ret_from_intr*
cat-5240 [000] 1678.885972: function:
reserve_irq_vector_locked <-- x86_vector_deactivate
cat-5240 [000] 1678.885986: function: do_IRQ <--
ret_from_intr
cat-5240 [000] 1678.885989: irq_handler_entry: irq=5
name=ttyS3
<idle>-0 [000] 1678.894122: function:
do_IRQ <-- ret_from_intr
<idle>-0 [000] 1678.894125: irq_handler_entry:
irq=5 name=ttyS3
<idle>-0 [000] 1678.902480: function:
do_IRQ <-- ret_from_intr
<idle>-0 [000] 1678.902483: irq_handler_entry:
irq=5 name=ttyS3
<idle>-0 [000] 1678.910752: function:
do_IRQ <-- ret_from_intr
<idle>-0 [000] 1678.910755: irq_handler_entry:
irq=5 name=ttyS3
Note, that you can see additional do_IRQ() calls, but after those, you
can see irq_handler_entry events as well, with the corresponding IRQ line.
It seems, either the core#1 is busy with something else (other, higher
priority IRQ), and the UART interrupt is pending in the local APIC. Or
the masking in the IO-APIC is not working (is that possible?).
Here's a complete ftrace log (nothing filtered out):
https://drive.google.com/open?id=1fTvfjPELE-xjc1xRVcwW04-U5QZCXGI1
Robert
