Re: Unexpected switches to in-band

["Łukasz Majewski" <lukma@nabladev.com>]

Hi Philippe,

> > so either some
> > traces are missing,  
> 
> I will check if I can add more tracing.

On one console:
---------------
evl trace -eirq -f; sleep 1; latmus -c 2 -p 1000 -P 99


On the second one:
------------------
test_prog/stress_prog_NO_IO &
sleep 5
test_prog/stress_prog_NO_IO &

echo 0 > /sys/kernel/tracing/tracing_on
evl trace -p > Xenomai4-ISW-trace-6.6-logs.txt

First trace:
############

The relevant dmesg output:

[   75.214527] EVL: timer-responder:743 switching in-band [pid=745,
excpt=14, user_pc=0x77d08492a5fe]

When I do look into logs - there is also a "hole" when the ISW is
reported by dmesg.


However, there are some hints when we look around evl_latmus:

timer-responder-745     [002] d.~2.    75.868139: evl_latspot: **
latency peak: 18843.649 us **

On CPU 20:
stress_prog_NO_-752     [020] ...2.    75.868139: folio_add_lru_vma
<-__handle_mm_fault

Which ends with folio_add_lru()...
And after that we do have the ~18ms latency peak.

And the "folio_*" is a relatively new feature added to Linux kernel [1].

The logs can be fetched from:
https://nextcloud.swupdate.org/index.php/s/EjHo5EAwMTeY5ya


Second trace [*]:
#################


[ 1610.086961] EVL: timer-responder:768 switching in-band [pid=770,
excpt=14, user_pc=0x72e9d35af5fe]

<idle>-0 [008] *..1.  1610.076068: rcu_dyntick: Start 1 0 0x2ec
<idle>-0 [003] *.~1.  1610.102242: rcu_dyntick: Endirq 0 1 0x404
<idle>-0 [003] *.~2.  1610.102242: arch_handle_irq <-arch_pipeline_entry
<idle>-0 [003] *.~2.  1610.102242: irq_to_desc <-arch_handle_irq
<idle>-0 [003] *.~1.  1610.102242: ma_read: mtree_load  
	Node: 00000000c4071949 (0 18446744073709551615) range: 4355-4355
<idle>-0 [003] *.~2.  1610.102242: rcu_oob_prepare_lock <-mtree_load
<idle>-0 [003] *.~2.  1610.102242: __rcu_read_lock <-mtree_load
<idle>-0 [003] *.~2.  1610.102242: __rcu_read_unlock <-mtree_load


Now some questions:
1. Why '~' (i.e. oob stage) is on CPU=3 as we pinpointed execution
   of the 'latmus' to CPU=2 (and the command line has isolcpu=2) ?

2. The mtree_load() is called in the OOB context... IMHO, this shall be
done before we do start the latmus?

3. In this case - there is also a "hole" between the ISW time
(1610.086961) and the ones between rcu_dyntick: Start / Endirq


Link to the full log:
https://nextcloud.swupdate.org/index.php/s/nPRAnqCLFDibX6r


Note:
[*] - All ftrace options enabled in the kernel


Links:
[1] -
https://github.com/torvalds/linux/commit/49f8275c7d92?spm=a2c65.11461447.0.0.68003853Pbec3R

-- 
Best regards,

Lukasz Majewski

--
Nabla Software Engineering GmbH
HRB 40522 Augsburg
Phone: +49 821 45592596
E-Mail: office@nabladev.com
Geschftsfhrer : Stefano Babic