* About the output interpretation of the wip RV
@ 2022-10-25 7:10 richard clark
2022-10-25 7:16 ` Daniel Bristot de Oliveira
0 siblings, 1 reply; 6+ messages in thread
From: richard clark @ 2022-10-25 7:10 UTC (permalink / raw)
To: bristot; +Cc: linux-trace-devel
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):
[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?
Thanks,
Richard
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: About the output interpretation of the wip RV
2022-10-25 7:10 About the output interpretation of the wip RV richard clark
@ 2022-10-25 7:16 ` Daniel Bristot de Oliveira
2022-10-25 9:18 ` richard clark
2022-10-26 3:52 ` richard clark
0 siblings, 2 replies; 6+ messages in thread
From: Daniel Bristot de Oliveira @ 2022-10-25 7:16 UTC (permalink / raw)
To: richard clark; +Cc: linux-trace-devel
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?
> [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:
https://docs.kernel.org/trace/rv/monitor_wip.html
Anyway, I suggest you using the upstream version of the monitors...
-- Daniel
> Thanks,
> Richard
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: About the output interpretation of the wip RV
2022-10-25 7:16 ` Daniel Bristot de Oliveira
@ 2022-10-25 9:18 ` richard clark
2022-10-26 3:52 ` richard clark
1 sibling, 0 replies; 6+ messages in thread
From: richard clark @ 2022-10-25 9:18 UTC (permalink / raw)
To: Daniel Bristot de Oliveira; +Cc: linux-trace-devel
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?
>
Right, from the paper...
> > [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:
>
> https://docs.kernel.org/trace/rv/monitor_wip.html
>
> Anyway, I suggest you using the upstream version of the monitors...
OK, I'll use the upstream version, happens has 6.0.1 kernel version
installed, will be back to you if any question.. Thanks~
>
> -- Daniel
>
> > Thanks,
> > Richard
>
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: About the output interpretation of the wip RV
2022-10-25 7:16 ` Daniel Bristot de Oliveira
2022-10-25 9:18 ` richard clark
@ 2022-10-26 3:52 ` richard clark
2022-10-28 3:37 ` richard clark
2022-10-28 7:24 ` Daniel Bristot de Oliveira
1 sibling, 2 replies; 6+ messages in thread
From: richard clark @ 2022-10-26 3:52 UTC (permalink / raw)
To: Daniel Bristot de Oliveira; +Cc: linux-trace-devel
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?
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?
Thanks!
>
> https://docs.kernel.org/trace/rv/monitor_wip.html
>
> Anyway, I suggest you using the upstream version of the monitors...
>
> -- Daniel
>
> > Thanks,
> > Richard
>
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: About the output interpretation of the wip RV
2022-10-26 3:52 ` richard clark
@ 2022-10-28 3:37 ` richard clark
2022-10-28 7:24 ` Daniel Bristot de Oliveira
1 sibling, 0 replies; 6+ messages in thread
From: richard clark @ 2022-10-28 3:37 UTC (permalink / raw)
To: Daniel Bristot de Oliveira; +Cc: linux-trace-devel
Hi Daniel,
Any comments for this thread?
On Wed, Oct 26, 2022 at 11:52 AM richard clark
<richard.xnu.clark@gmail.com> 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?
> 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?
>
> Thanks!
>
> >
> > https://docs.kernel.org/trace/rv/monitor_wip.html
> >
> > Anyway, I suggest you using the upstream version of the monitors...
> >
> > -- Daniel
> >
> > > Thanks,
> > > Richard
> >
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: About the output interpretation of the wip RV
2022-10-26 3:52 ` richard clark
2022-10-28 3:37 ` richard clark
@ 2022-10-28 7:24 ` Daniel Bristot de Oliveira
1 sibling, 0 replies; 6+ messages in thread
From: Daniel Bristot de Oliveira @ 2022-10-28 7:24 UTC (permalink / raw)
To: richard clark; +Cc: linux-trace-devel
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
>>
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2022-10-28 7:24 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2022-10-25 7:10 About the output interpretation of the wip RV richard clark
2022-10-25 7:16 ` Daniel Bristot de Oliveira
2022-10-25 9:18 ` richard clark
2022-10-26 3:52 ` richard clark
2022-10-28 3:37 ` richard clark
2022-10-28 7:24 ` Daniel Bristot de Oliveira
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).