All of lore.kernel.org
 help / color / mirror / Atom feed
* gdb  test failure debug status update
@ 2021-04-28  3:19 Chen, Hongzhan
  2021-04-28 14:18 ` Philippe Gerum
  0 siblings, 1 reply; 16+ messages in thread
From: Chen, Hongzhan @ 2021-04-28  3:19 UTC (permalink / raw)
  To: xenomai


According to my validation, gdb test fail on dovetail 5.10 branch but pass on v5.9-evl4 tag with same for-upstream/dovetail
xenomai code base.

After further debug , the issue is more clear for me. Gdb test failure because low priority thread smokey  userspace  is still
executed after "cobalt_shadow_relaxed: state=0x4488c0 info=0x200"  like log [1] on dovetail-5.10 branch.
The weird thing is that its following first ftrace log  happen at 62235.848583 after cobalt_shadow_relaxed in log [1].
It is almost 3ms happened after cobalt_shadow_relaxed. The low priority smoke thread user space is executed during this
3ms period so that test fail.

But in success case with v5.9-evl4 like in  log [2], the time interval between cobalt_shadow_relaxed and the following first ftrace log
is only about 1us. It seems that low priority smokey userspace do not have chance to execute in this 1us because gdb test is successful.

My question is why there is even no interrupt happened during that about 3ms period in failure case?  Tick seems in abnormal behavior.
Please comment if you have any ideas to further debug it.

PS: All my tests run on same up Xtream board.

1:
          smokey-2024    [000] ..s1 62235.845648: softirq_exit: vec=6 [action=TASKLET]
          smokey-2024    [000] d.s2 62235.845648: rcu_dyntick: ++= 4000000000000000 4000000000000002 0x312
          smokey-2024    [000] d.s1 62235.845648: irq_disable: caller=__do_softirq+0x280/0x428 parent=0x0
          smokey-2024    [000] d.s2 62235.845648: rcu_dyntick: --= 4000000000000002 4000000000000000 0x312
          smokey-2024    [000] *..2 62235.845649: rcu_dyntick: ++= 4000000000000000 4000000000000002 0x312
          smokey-2024    [000] *..1 62235.845649: irq_enable: caller=sync_current_irq_stage+0x259/0x280 parent=0x0
          smokey-2024    [000] *..2 62235.845649: rcu_dyntick: --= 4000000000000002 4000000000000000 0x312
          smokey-2024    [000] ...1 62235.845650: cobalt_shadow_relaxed: state=0x4488c0 info=0x200
          smokey-2024    [000] *..1 62235.848583: irq_disable: caller=irqentry_enter+0x40/0xe0 parent=0x0
          smokey-2024    [000] *.~1 62235.848583: irq_pipeline_entry: irq=4354
          smokey-2024    [000] *.~1 62235.848584: irq_handler_entry: irq=4354 name=Out-of-band LAPIC timer interrupt
          smokey-2024    [000] *.~1 62235.848584: local_timer_entry: vector=236
          smokey-2024    [000] *.~1 62235.848585: cobalt_timer_expire: timer=000000002aae459f
          smokey-2024    [000] *.~1 62235.848585: local_timer_exit: vector=236
          smokey-2024    [000] *.~1 62235.848585: irq_handler_exit: irq=4354 ret=handled
          smokey-2024    [000] *.~1 62235.848585: irq_pipeline_exit: irq=4354
          smokey-2024    [000] *.~1 62235.848586: irq_enable: caller=arch_pipeline_entry+0x4e/0xc0 parent=0x0
          smokey-2024    [000] *..2 62235.848586: rcu_dyntick: ++= 4000000000000000 4000000000000002 0x312
          smokey-2024    [000] *..1 62235.848586: irq_disable: caller=sync_current_irq_stage+0x246/0x280 parent=0x0
          smokey-2024    [000] *..2 62235.848586: rcu_dyntick: --= 4000000000000002 4000000000000000 0x312
          smokey-2024    [000] d.h1 62235.848587: irq_handler_entry: irq=124 name=proxy tick
          smokey-2024    [000] d.h2 62235.848587: lock_acquire: 000000004fef83e9 hrtimer_bases.lock
          smokey-2024    [000] d.h2 62235.848588: lock_acquire: 00000000ed2aa56a read tk_core.seq.seqcount
          smokey-2024    [000] d.h2 62235.848588: lock_release: 00000000ed2aa56a tk_core.seq.seqcount
          smokey-2024    [000] d.h2 62235.848588: hrtimer_cancel: hrtimer=000000009dcbf7ab
          smokey-2024    [000] d.h2 62235.848588: lock_release: 000000004fef83e9 hrtimer_bases.lock
          smokey-2024    [000] d.h1 62235.848589: hrtimer_expire_entry: hrtimer=000000009dcbf7ab function=tick_sched_timer now=62232458752330
          smokey-2024    [000] d.h1 62235.848589: lock_acquire: 00000000ed2aa56a read tk_core.seq.seqcount
          smokey-2024    [000] d.h1 62235.848589: lock_release: 00000000ed2aa56a tk_core.seq.seqcount
          smokey-2024    [000] d.h2 62235.848590: lock_acquire: 000000002286d635 jiffies_lock
          smokey-2024    [000] d.h2 62235.848590: lock_acquire: 000000007174a29a (null)
          smokey-2024    [000] d.h2 62235.848590: lock_release: 000000007174a29a (null)


[2] :
         smokey-703     [000] d.s2  5674.404286: rcu_dyntick: ++= 4000000000000000 4000000000000002 0x26e
          smokey-703     [000] d.s1  5674.404286: irq_disable: caller=inband_irq_save+0x20/0x30 parent=0x0
          smokey-703     [000] d.s2  5674.404286: rcu_dyntick: --= 4000000000000002 4000000000000000 0x26e
          smokey-703     [000] d.s1  5674.404287: rcu_batch_end: rcu_sched CBs-invoked=8 idle=....
          smokey-703     [000] d.s2  5674.404287: rcu_dyntick: ++= 4000000000000000 4000000000000002 0x26e
          smokey-703     [000] d.s1  5674.404287: irq_enable: caller=rcu_core+0x3b6/0xb60 parent=0x0
          smokey-703     [000] d.s2  5674.404287: rcu_dyntick: --= 4000000000000002 4000000000000000 0x26e
          smokey-703     [000] ..s1  5674.404288: rcu_utilization: End RCU core
          smokey-703     [000] ..s1  5674.404288: softirq_exit: vec=9 [action=RCU]
          smokey-703     [000] d.s2  5674.404288: rcu_dyntick: ++= 4000000000000000 4000000000000002 0x26e
          smokey-703     [000] d.s1  5674.404288: irq_disable: caller=__do_softirq+0x2bd/0x471 parent=0x0
          smokey-703     [000] d.s2  5674.404289: rcu_dyntick: --= 4000000000000002 4000000000000000 0x26e
          smokey-703     [000] *..2  5674.404289: rcu_dyntick: ++= 4000000000000000 4000000000000002 0x26e
          smokey-703     [000] *..1  5674.404289: irq_enable: caller=sync_current_irq_stage+0x259/0x280 parent=0x0
          smokey-703     [000] *..2  5674.404290: rcu_dyntick: --= 4000000000000002 4000000000000000 0x26e
          smokey-703     [000] ...1  5674.404290: cobalt_shadow_relaxed: state=0x4488c0 info=0x200
          smokey-703     [000] *..2  5674.404291: rcu_dyntick: ++= 4000000000000000 4000000000000002 0x26e
          smokey-703     [000] *..1  5674.404291: irq_disable: caller=arch_pipeline_entry+0x13a/0x170 parent=0x0
          smokey-703     [000] *..2  5674.404292: rcu_dyntick: --= 4000000000000002 4000000000000000 0x26e
          smokey-703     [000] d..2  5674.404292: rcu_dyntick: ++= 4000000000000000 4000000000000002 0x26e
          smokey-703     [000] d..1  5674.404292: irq_enable: caller=exit_to_user_mode_prepare+0x118/0x1e0 parent=0x0
          smokey-703     [000] d..2  5674.404292: rcu_dyntick: --= 4000000000000002 4000000000000000 0x26e
          smokey-703     [000] d..2  5674.404293: rcu_dyntick: ++= 4000000000000000 4000000000000002 0x26e
          smokey-703     [000] d..1  5674.404293: irq_disable: caller=_raw_spin_lock_irq+0x12/0x50 parent=0x0
          smokey-703     [000] d..2  5674.404293: rcu_dyntick: --= 4000000000000002 4000000000000000 0x26e
          smokey-703     [000] d..2  5674.404294: lock_acquire: 000000007f29b2fb &sighand->siglock
          smokey-703     [000] d..2  5674.404294: kmem_cache_free: call_site=__dequeue_signal+0xf7/0x150 ptr=000000003929a99e
          smokey-703     [000] d..3  5674.404295: lock_acquire: 000000002505fb17 &p->pi_lock
          smokey-703     [000] d..3  5674.404295: lock_release: 000000002505fb17 &p->pi_lock
          smokey-703     [000] d..2  5674.404296: lock_release: 000000007f29b2fb &sighand->siglock
          smokey-703     [000] d..3  5674.404296: rcu_dyntick: ++= 4000000000000000 4000000000000002 0x26e
          smokey-703     [000] d..2  5674.404296: irq_enable: caller=_raw_spin_unlock_irq+0x1f/0x30 parent=0x0
          smokey-703     [000] d..3  5674.404296: rcu_dyntick: --= 4000000000000002 4000000000000000 0x26e
          smokey-703     [000] ...2  5674.404297: lock_acquire: 00000000e714a308 read tasklist_lock
          smokey-703     [000] ...3  5674.404297: lock_acquire: 00000000909a50fe read rcu_read_lock

Regards

Hongzhan Chen

^ permalink raw reply	[flat|nested] 16+ messages in thread

end of thread, other threads:[~2021-05-15 15:55 UTC | newest]

Thread overview: 16+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-04-28  3:19 gdb test failure debug status update Chen, Hongzhan
2021-04-28 14:18 ` Philippe Gerum
2021-04-28 14:30   ` Philippe Gerum
2021-04-29  6:31     ` Chen, Hongzhan
2021-04-30  5:25       ` Chen, Hongzhan
2021-04-30  5:51         ` Chen, Hongzhan
2021-04-30  7:36           ` Philippe Gerum
2021-04-30  7:34         ` Philippe Gerum
2021-04-30  8:00           ` Philippe Gerum
2021-04-30  8:07             ` Chen, Hongzhan
     [not found]               ` <DM5PR11MB18529649C47BF241930A2217F25E9@DM5PR11MB1852.namprd11.prod.outlook.com>
     [not found]                 ` <8735v82jmd.fsf@xenomai.org>
2021-05-06  2:00                   ` Chen, Hongzhan
2021-05-07  1:10                     ` Chen, Hongzhan
2021-05-09 17:46                       ` Philippe Gerum
2021-05-09 17:49                         ` Philippe Gerum
2021-05-10  2:16                           ` Chen, Hongzhan
2021-05-15 15:55                         ` Philippe Gerum

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.