Re: About the output interpretation of the wip RV

[Daniel Bristot de Oliveira <bristot@kernel.org>]

On 10/26/22 05:52, richard clark wrote:
> Hi Daniel,
> 
> On Tue, Oct 25, 2022 at 3:16 PM Daniel Bristot de Oliveira
> <bristot@kernel.org> wrote:
>>
>> Hi Richard!
>>
>> On 10/25/22 09:10, richard clark wrote:
>>> Hi Daniel,
>>> I got several dmsg outputs like this after I insmod the 'wip' into
>>> system(with printk+dump_stack reactor, trivial changes for the wip):
>>
>> Which version of the monitor are you using? I make this question because the
>> latest version of the monitor is not "loadable module" yet. So my guess is that
>> you are using a version from the paper?
> 
> After switching to the builtin 'wip' monitor and enable it and the
> 'printk' reactor...
>>
>>> [78706.972957] event sched_waking not expected in the state preemptive
>>> [78706.972963] CPU: 2 PID: 410 Comm: kworker/2:4 Tainted: G
>>> OE     5.15.70-rt50 #1
>>> [78706.972972] Workqueue: events igb_watchdog_task [igb]
>>> [78706.973000] Call Trace:
>>> [78706.973003]  <IRQ>
>>> [78706.973006]  dump_stack_lvl+0x61/0x86
>>> [78706.973016]  dump_stack+0x10/0x18
>>> [78706.973022]  handle_sched_wakeup+0x92/0xd0 [rv_poc]
>>> [78706.973028]  ttwu_do_wakeup+0xc3/0x1d0
>>> [78706.973038]  ttwu_do_activate+0x6e/0x100
>>> [78706.973044]  try_to_wake_up+0x209/0x700
>>> [78706.973049]  ? hrtimer_interrupt+0x11f/0x230
>>> [78706.973059]  wake_up_process+0x15/0x30
>>> [78706.973065]  irq_exit_rcu+0x9b/0xe0
>>> [78706.973074]  sysvec_apic_timer_interrupt+0x92/0xd0
>>> [78706.973082]  </IRQ>
>>> [78706.973083]  <TASK>
>>> [78706.973084]  asm_sysvec_apic_timer_interrupt+0x1b/0x20
>>>
>>> Does that mean something is not unexpected in the system?
>>
>> Not necessarily, this monitor shows a limitation of tracing, as explained in
>> the kernel documentation:
> 
> the dmesg shows below information with that enabled 'wip' monitor:
> 
> root@robotics:/sys/kernel/debug/tracing/rv/monitors# dmesg
> ...
> [  332.834168] rv: monitor wip does not allow event sched_waking on
> state preemptive
> [  353.833699] rv: monitor wip does not allow event sched_waking on
> state preemptive
> [  354.833679] rv: monitor wip does not allow event sched_waking on
> state preemptive
> ...
> I took a look at the discussion at
> https://lore.kernel.org/all/f2ca7336162b6dc45f413cfe4e0056e6aa32e7ed.1559051152.git.bristot@redhat.com/
> seems that patch was trying to resolve the limitation of the tracing:
> the __preempt_count_add() and its trace func is not atomic, does that
> mean this issue is still in my system from the dmesg output above?

It is like this on all systems. It is expected to have printk.

> Another question is, except that the trace limitation, do we have some
> specific examples to show that maybe an 'unexpected' event happens
> against the current state?

With regard to this monitor or any other monitor? To this monitor, the answer is
not that I know about. But tracing is your friend, you can enable trace the
system and the monitor yourself, and figure out what is going on.

-- Daniel

> Thanks!
> 
>>
>> https://docs.kernel.org/trace/rv/monitor_wip.html
>>
>> Anyway, I suggest you using the upstream version of the monitors...
>>
>> -- Daniel
>>
>>> Thanks,
>>> Richard
>>