On Fri, Oct 12, 2007 at 01:15:31PM +0200, Jan Kiszka wrote:

> > [EMAIL PROTECTED] cat /proc/ipipe/trace/max
> 
> /frozen holds the result. Also, a bit more post_trace_points may help to
> see what goes on after that function is called.

Ah, sorry. Here it comes, with post_trace_points set to 100:

[EMAIL PROTECTED]:~# echo 1 > /proc/ipipe/trace/enable 
[EMAIL PROTECTED]:~# echo 100 > /proc/ipipe/trace/post_trace_points 
[EMAIL PROTECTED]:~# echo rthal_timer_request > /proc/ipipe/trace/trigger
[EMAIL PROTECTED]:~# modprobe xeno_native
[EMAIL PROTECTED]:~# cat /proc/ipipe/trace/frozen 
I-pipe frozen back-tracing service on 2.6.22.9-xeno/ipipe-1.10-07
------------------------------------------------------------
CPU: 0, Freeze: 533994599352 cycles, Trace Points: 100 (+100)
Calibrated minimum trace-point overhead: 0.094 us

 +----- Hard IRQs ('|': locked)
 |+---- <unused>
 ||+--- <unused>
 |||+-- Xenomai
 ||||+- Linux ('*': domain stalled, '+': current, '#': current+stalled)
 |||||                        +---------- Delay flag ('+': > 1 us, '!': > 10 us)
 |||||                        |        +- NMI noise ('N')
 |||||                        |        |
      Type    User Val.   Time    Delay  Function (Parent)
:|   #begin   0x80000000   -37    0.094  __ipipe_unstall_root+0x4d 
(__ipipe_restore_root+0x27)
:|   +end     0x80000000   -37    0.184  __ipipe_unstall_root+0x3f 
(__ipipe_restore_root+0x27)
:    +func                 -37    0.089  ipipe_check_context+0xc 
(cache_alloc_refill+0x406)
:    #func                 -37    0.094  ipipe_check_context+0xc 
(cache_alloc_refill+0x418)
:    #func                 -37    0.094  ipipe_check_context+0xc 
(cache_alloc_refill+0x441)
:    #func                 -37    0.139  ipipe_check_context+0xc 
(cache_alloc_refill+0x66)
:    #func                 -36    0.109  ipipe_check_context+0xc 
(cache_alloc_refill+0x165)
:    #func                 -36    0.099  __ipipe_restore_root+0x8 
(__kmalloc+0x90)
:    #func                 -36    0.099  __ipipe_unstall_root+0x8 
(__ipipe_restore_root+0x27)
:|   #begin   0x80000000   -36    0.094  __ipipe_unstall_root+0x4d 
(__ipipe_restore_root+0x27)
:|   +end     0x80000000   -36    0.209  __ipipe_unstall_root+0x3f 
(__ipipe_restore_root+0x27)
:    +func                 -36    0.384  xnheap_init+0xe (xnpod_init+0x243)
:    +func                 -35+   7.850  init_extent+0xe (xnheap_init+0x111)
:    +func                 -28    0.144  xnthread_init+0xe (xnpod_init+0x2af)
:    +func                 -27    0.119  __xntimer_init+0xe (xnthread_init+0x53)
:    +func                 -27    0.084  snprintf+0xb (__xntimer_init+0x96)
:    +func                 -27    0.159  vsnprintf+0xe (snprintf+0x22)
:    +func                 -27    0.259  number+0xe (vsnprintf+0x2d8)
:|   +begin   0x80000000   -27    0.129  __xntimer_init+0x14b 
(xnthread_init+0x53)
:|  *+func                 -27    0.134  __ipipe_restore_pipeline_head+0xd 
(__xntimer_init+0x117)
:|   +end     0x80000000   -27    0.159  __ipipe_restore_pipeline_head+0x9e 
(__xntimer_init+0x117)
:    +func                 -26    0.094  __xntimer_init+0xe (xnthread_init+0x9b)
:    +func                 -26    0.074  snprintf+0xb (__xntimer_init+0x96)
:    +func                 -26    0.104  vsnprintf+0xe (snprintf+0x22)
:    +func                 -26    0.219  number+0xe (vsnprintf+0x2d8)
:|   +begin   0x80000000   -26    0.129  __xntimer_init+0x14b 
(xnthread_init+0x9b)
:|  *+func                 -26    0.084  __ipipe_restore_pipeline_head+0xd 
(__xntimer_init+0x117)
:|   +end     0x80000000   -26    0.443  __ipipe_restore_pipeline_head+0x9e 
(__xntimer_init+0x117)
:    +func                 -25    0.234  xnregistry_init+0xb (xnpod_init+0x359)
:    +func                 -25    0.094  rthal_apc_alloc+0xe 
(xnregistry_init+0x1c)
:|   +begin   0x80000000   -25    0.129  rthal_apc_alloc+0xbb 
(xnregistry_init+0x1c)
:|  *+func                 -25    0.124  __ipipe_restore_pipeline_head+0xd 
(rthal_apc_alloc+0xa7)
:|   +end     0x80000000   -25    0.239  __ipipe_restore_pipeline_head+0x9e 
(rthal_apc_alloc+0xa7)
:    +func                 -24    0.229  create_proc_entry+0xd 
(xnregistry_init+0x3e)
:    +func                 -24    0.219  proc_create+0xe 
(create_proc_entry+0x54)
:    +func                 -24    0.099  __kmalloc+0xe (proc_create+0x8f)
:    +func                 -24    0.089  ipipe_check_context+0xc 
(__kmalloc+0xb4)
:    +func                 -24    0.104  ipipe_check_context+0xc 
(__kmalloc+0x5c)
:    #func                 -24    0.074  __ipipe_restore_root+0x8 
(__kmalloc+0x90)
:    #func                 -24    0.089  __ipipe_unstall_root+0x8 
(__ipipe_restore_root+0x27)
:|   #begin   0x80000000   -24    0.094  __ipipe_unstall_root+0x4d 
(__ipipe_restore_root+0x27)
:|   +end     0x80000000   -23    0.144  __ipipe_unstall_root+0x3f 
(__ipipe_restore_root+0x27)
:    +func                 -23    0.209  proc_register+0xe 
(create_proc_entry+0x72)
:    +func                 -23    0.129  idr_pre_get+0xa (proc_register+0x2f)
:    +func                 -23    0.204  ipipe_check_context+0xc 
(proc_register+0x3d)
:    +func                 -23    0.169  idr_get_new+0x9 (proc_register+0x4c)
:    +func                 -23    0.274  idr_get_new_above_int+0xe 
(idr_get_new+0x12)
:    +func                 -22    0.234  find_next_bit+0xe 
(idr_get_new_above_int+0xd6)
:    +func                 -22    0.214  find_next_bit+0xe 
(idr_get_new_above_int+0xd6)
:    +func                 -22    0.099  ipipe_check_context+0xc 
(proc_register+0x58)
:    +func                 -22    0.129  ipipe_check_context+0xc 
(proc_register+0x87)
:    +func                 -22+   9.970  ipipe_check_context+0xc 
(proc_register+0x9d)
:    +func                 -12    0.189  kmem_cache_alloc+0xe 
(xnregistry_init+0x141)
:    +func                 -11    0.084  ipipe_check_context+0xc 
(kmem_cache_alloc+0x8a)
:    +func                 -11    0.089  ipipe_check_context+0xc 
(kmem_cache_alloc+0x21)
:    #func                 -11    0.084  __ipipe_restore_root+0x8 
(kmem_cache_alloc+0x55)
:    #func                 -11    0.089  __ipipe_unstall_root+0x8 
(__ipipe_restore_root+0x27)
:|   #begin   0x80000000   -11    0.094  __ipipe_unstall_root+0x4d 
(__ipipe_restore_root+0x27)
:|   +end     0x80000000   -11    0.758  __ipipe_unstall_root+0x3f 
(__ipipe_restore_root+0x27)
:    +func                 -10    0.389  xnsynch_init+0x8 
(xnregistry_init+0x16e)
:    +func                 -10    0.094  xnshadow_grab_events+0x8 
(xnpod_init+0x365)
:    +func                 -10    0.139  ipipe_catch_event+0xe 
(xnshadow_grab_events+0x1c)
:    +func                 -10    0.094  ipipe_critical_enter+0x9 
(ipipe_catch_event+0x47)
:|   +begin   0x80000001   -10    0.234  ipipe_critical_enter+0x1b 
(ipipe_catch_event+0x47)
:|   +func                  -9    0.089  ipipe_critical_exit+0x9 
(ipipe_catch_event+0xc8)
:|   +end     0x80000001    -9    0.109  ipipe_critical_exit+0x1a 
(ipipe_catch_event+0xc8)
:    +func                  -9    0.109  ipipe_catch_event+0xe 
(xnshadow_grab_events+0x30)
:    +func                  -9    0.089  ipipe_critical_enter+0x9 
(ipipe_catch_event+0x47)
:|   +begin   0x80000001    -9    0.119  ipipe_critical_enter+0x1b 
(ipipe_catch_event+0x47)
:|   +func                  -9    0.074  ipipe_critical_exit+0x9 
(ipipe_catch_event+0xc8)
:|   +end     0x80000001    -9    0.094  ipipe_critical_exit+0x1a 
(ipipe_catch_event+0xc8)
:    +func                  -9    0.079  ipipe_catch_event+0xe 
(xnshadow_grab_events+0x44)
:    +func                  -9    0.084  ipipe_critical_enter+0x9 
(ipipe_catch_event+0x47)
:|   +begin   0x80000001    -8    0.104  ipipe_critical_enter+0x1b 
(ipipe_catch_event+0x47)
:|   +func                  -8    0.074  ipipe_critical_exit+0x9 
(ipipe_catch_event+0xc8)
:|   +end     0x80000001    -8    0.094  ipipe_critical_exit+0x1a 
(ipipe_catch_event+0xc8)
:    +func                  -8    0.079  ipipe_catch_event+0xe 
(xnshadow_grab_events+0x58)
:    +func                  -8    0.084  ipipe_critical_enter+0x9 
(ipipe_catch_event+0x47)
:|   +begin   0x80000001    -8    0.114  ipipe_critical_enter+0x1b 
(ipipe_catch_event+0x47)
:|   +func                  -8    0.074  ipipe_critical_exit+0x9 
(ipipe_catch_event+0xc8)
:|   +end     0x80000001    -8    0.094  ipipe_critical_exit+0x1a 
(ipipe_catch_event+0xc8)
:    +func                  -8    0.109  ipipe_catch_event+0xe 
(xnshadow_grab_events+0x6c)
:    +func                  -8    0.084  ipipe_critical_enter+0x9 
(ipipe_catch_event+0x47)
:|   +begin   0x80000001    -8    0.109  ipipe_critical_enter+0x1b 
(ipipe_catch_event+0x47)
:|   +func                  -7    0.074  ipipe_critical_exit+0x9 
(ipipe_catch_event+0xc8)
:|   +end     0x80000001    -7    0.204  ipipe_critical_exit+0x1a 
(ipipe_catch_event+0xc8)
:    +func                  -7    0.164  xnpod_enable_timesource+0xd 
(xnpod_init+0x36a)
:|   +begin   0x80000000    -7    0.189  xnpod_enable_timesource+0x16b 
(xnpod_init+0x36a)
:|  *+func                  -7    0.099  xnintr_init+0x9 
(xnpod_enable_timesource+0x69)
:|  *+func                  -7    0.124  __ipipe_restore_pipeline_head+0xd 
(xnpod_enable_timesource+0x179)
:|   +end     0x80000000    -7    0.214  __ipipe_restore_pipeline_head+0x9e 
(xnpod_enable_timesource+0x179)
:    +func                  -6    0.174  xnarch_get_host_time+0xd 
(xnpod_enable_timesource+0x97)
:    +func                  -6    0.109  do_gettimeofday+0xe 
(xnarch_get_host_time+0x15)
:    +func                  -6    0.239  read_tsc+0x8 (do_gettimeofday+0x42)
:    +func                  -6    0.209  xnarch_get_cpu_time+0x8 
(xnpod_enable_timesource+0xa0)
:    +func                  -6    0.094  rthal_get_8254_tsc+0xe 
(xnarch_get_cpu_time+0xd)
:|   +begin   0x80000001    -6+   5.770  rthal_get_8254_tsc+0x9b 
(xnarch_get_cpu_time+0xd)
:|   +end     0x80000001     0    0.109  rthal_get_8254_tsc+0x77 
(xnarch_get_cpu_time+0xd)
:    +func                   0    0.159  xnarch_tsc_to_ns+0xa 
(xnarch_get_cpu_time+0x12)
<    +func                   0    0.219  rthal_timer_request+0xe 
(xnpod_enable_timesource+0xcb)
     +func                   0    0.089  ipipe_request_tickdev+0xe 
(rthal_timer_request+0x21)
     +func                   0    0.084  ipipe_critical_enter+0x9 
(ipipe_request_tickdev+0x1d)
 |   +begin   0x80000001     0    0.224  ipipe_critical_enter+0x1b 
(ipipe_request_tickdev+0x1d)
 |   +func                   0    0.099  __ipipe_check_tickdev+0x8 
(ipipe_request_tickdev+0xb1)
 |   +func                   0    0.074  ipipe_critical_exit+0x9 
(ipipe_request_tickdev+0x36)
 |   +end     0x80000001     0    0.244  ipipe_critical_exit+0x1a 
(ipipe_request_tickdev+0x36)
 |   +begin   0x80000001     1   11.102  rthal_timer_request+0x14b 
(xnpod_enable_timesource+0xcb)
 |   +func                  12    0.089  __const_udelay+0x8 
(rthal_timer_request+0xb7)
 |   +func                  12    0.094  __delay+0x8 (__const_udelay+0x23)
 |   +func                  12   16.832  delay_tsc+0x9 (__delay+0xe)
 |   +end     0x80000001    29    0.119  rthal_timer_request+0x15a 
(xnpod_enable_timesource+0xcb)
     +func                  29    0.119  rthal_irq_request+0xc 
(rthal_timer_request+0xe5)
     +func                  29    0.204  ipipe_virtualize_irq+0xe 
(rthal_irq_request+0x45)
     +func                  29    0.094  __ipipe_spin_lock_irqsave+0x9 
(ipipe_virtualize_irq+0x65)
 |   +begin   0x80000001    29    0.174  __ipipe_spin_lock_irqsave+0x4b 
(ipipe_virtualize_irq+0x65)
 |   #func                  29    0.104  __ipipe_enable_irqdesc+0x8 
(ipipe_virtualize_irq+0x111)
 |   #func                  29    0.099  __ipipe_spin_unlock_irqrestore+0x9 
(ipipe_virtualize_irq+0x97)
 |   +end     0x80000001    30    0.129  __ipipe_spin_unlock_irqrestore+0x36 
(ipipe_virtualize_irq+0x97)
 |   +begin   0x80000000    30    0.109  xnpod_enable_timesource+0x18b 
(xnpod_init+0x36a)
 |  *+func                  30    0.109  xntimer_start_aperiodic+0xe 
(xnpod_enable_timesource+0x1b5)
 |  *+func                  30    5.870  rthal_get_8254_tsc+0xe 
(xntimer_start_aperiodic+0x38)
 |  *+func                  36    0.314  xnarch_ns_to_tsc+0xe 
(xntimer_start_aperiodic+0x11d)
 |  *+func                  36    0.124  xntimer_next_local_shot+0xe 
(xntimer_start_aperiodic+0x13a)
 |  *+func                  36    5.780  rthal_get_8254_tsc+0xe 
(xntimer_next_local_shot+0x35)
 |  *+func                  42    0.139  ipipe_trigger_irq+0xe 
(xntimer_next_local_shot+0x97)
 |  *+func                  42    0.134  __ipipe_handle_irq+0xe 
(ipipe_trigger_irq+0x8f)
 |  *+func                  42    0.119  __ipipe_dispatch_wired+0xb 
(__ipipe_handle_irq+0x51)
 |  *+func                  42    0.169  __ipipe_set_irq_pending+0xb 
(__ipipe_dispatch_wired+0xc9)
 |  *+func                  43    0.129  __ipipe_restore_pipeline_head+0xd 
(xnpod_enable_timesource+0x159)
 |   +func                  43    0.119  __ipipe_walk_pipeline+0xa 
(__ipipe_restore_pipeline_head+0xdc)
 |  + func                  43    0.104  ipipe_suspend_domain+0xe 
(__ipipe_walk_pipeline+0x78)
 |  + func                  43    0.249  __ipipe_sync_stage+0xe 
(ipipe_suspend_domain+0x84)
 |  # func                  43    0.134  xnintr_clock_handler+0xe 
(__ipipe_sync_stage+0x105)
 |  # func                  43    5.740  rthal_get_8254_tsc+0xe 
(xnintr_clock_handler+0x1b)
 |  # func                  49    0.099  xntimer_tick_aperiodic+0xe 
(xnintr_clock_handler+0x2f)
 |  # func                  49    5.785  rthal_get_8254_tsc+0xe 
(xntimer_tick_aperiodic+0x1d)
 |  # func                  55    0.408  xntimer_next_local_shot+0xe 
(xntimer_tick_aperiodic+0x164)
 |  # func                  55    0.199  rthal_irq_host_pend+0x8 
(xnintr_clock_handler+0xa2)
 |  # func                  56    0.129  __ipipe_schedule_irq+0xe 
(rthal_irq_host_pend+0x16)
 |  # func                  56    0.109  __ipipe_set_irq_pending+0xb 
(__ipipe_schedule_irq+0x68)
 |  # func                  56    5.735  rthal_get_8254_tsc+0xe 
(xnintr_clock_handler+0xb3)
 |  # func                  62    5.805  rthal_get_8254_tsc+0xe 
(xnintr_clock_handler+0xce)
 |   +func                  67    0.124  __ipipe_sync_stage+0xe 
(ipipe_suspend_domain+0x84)
 |   #end     0x80000000    67    0.144  __ipipe_sync_stage+0x192 
(ipipe_suspend_domain+0x84)
     #func                  68    0.099  do_IRQ+0xe (__ipipe_sync_stage+0x1dd)
     #func                  68    0.094  irq_enter+0x8 (do_IRQ+0x35)
     #func                  68    0.094  handle_level_irq+0xb (do_IRQ+0x3c)
     #func                  68    0.124  ipipe_check_context+0xc 
(handle_level_irq+0x19)
     #func                  68    0.079  ipipe_check_context+0xc 
(handle_level_irq+0x50)
     #func                  68    0.104  handle_IRQ_event+0xe 
(handle_level_irq+0x59)
     #func                  68    0.099  timer_interrupt+0x8 
(handle_IRQ_event+0x31)
     #func                  68    0.074  tick_handle_periodic+0xe 
(timer_interrupt+0x13)
     #func                  68    0.079  tick_periodic+0x8 
(tick_handle_periodic+0x17)
     #func                  68    0.089  ipipe_check_context+0xc 
(tick_periodic+0x4a)
     #func                  69    0.079  do_timer+0xe (tick_periodic+0x71)
     #func                  69    0.094  update_wall_time+0xe (do_timer+0x23)
     #func                  69    0.184  read_tsc+0x8 (update_wall_time+0x24)
     #func                  69    0.089  clocksource_get_next+0xa 
(update_wall_time+0x220)
     #func                  69    0.084  ipipe_check_context+0xc 
(clocksource_get_next+0x14)
     #func                  69    0.099  ipipe_check_context+0xc 
(clocksource_get_next+0x2e)
     #func                  69    0.089  __ipipe_restore_root+0x8 
(clocksource_get_next+0x48)
     #func                  69    0.089  ipipe_check_context+0xc 
(clocksource_get_next+0x52)
     #func                  69    0.094  ipipe_check_context+0xc 
(tick_periodic+0x81)
     #func                  69    0.089  update_process_times+0xa 
(tick_periodic+0x2b)
     #func                  70    0.114  account_system_time+0xb 
(update_process_times+0x61)
     #func                  70    0.099  run_local_timers+0x8 
(update_process_times+0x27)
     #func                  70    0.089  raise_softirq+0xb 
(run_local_timers+0x12)
     #func                  70    0.089  ipipe_check_context+0xc 
(raise_softirq+0x17)
     #func                  70    0.114  __ipipe_restore_root+0x8 
(raise_softirq+0x67)
     #func                  70    0.099  softlockup_tick+0xe 
(run_local_timers+0x17)
     #func                  70    0.084  rcu_pending+0x8 
(update_process_times+0x2e)
     #func                  70    0.094  __rcu_pending+0x8 (rcu_pending+0x17)
     #func                  70    0.104  __rcu_pending+0x8 (rcu_pending+0x3f)
     #func                  70    0.099  scheduler_tick+0xb 
(update_process_times+0x40)
     #func                  71    0.124  sched_clock+0xa (scheduler_tick+0x10)
     #func                  71    0.099  idle_cpu+0x8 (scheduler_tick+0x21)
     #func                  71    0.114  task_running_tick+0xe 
(scheduler_tick+0x53)
     #func                  71    0.154  ipipe_check_context+0xc 
(task_running_tick+0x34)
     #func                  71    0.124  dequeue_task+0xa 
(task_running_tick+0x13a)
     #func                  71    0.124  effective_prio+0x8 
(task_running_tick+0x149)
     #func                  71    0.154  static_prio_timeslice+0x8 
(task_running_tick+0x156)
     #func                  71    0.099  enqueue_task+0xa 
(task_running_tick+0x1d1)
     #func                  72    0.114  ipipe_check_context+0xc 
(task_running_tick+0x89)
     #func                  72    0.114  run_posix_cpu_timers+0xe 
(update_process_times+0x47)
     #func                  72    0.089  profile_tick+0xa (tick_periodic+0x35)
     #func                  72    0.124  profile_pc+0x8 (profile_tick+0x37)
     #func                  72    0.109  ipipe_check_context+0xc 
(handle_IRQ_event+0x67)
     #func                  72    0.099  note_interrupt+0xe 
(handle_level_irq+0xab)
     #func                  72    0.099  ipipe_check_context+0xc 
(handle_level_irq+0x6d)
     #func                  72    0.084  enable_8259A_irq+0xb 
(handle_level_irq+0x8b)
     #func                  72    0.094  __ipipe_spin_lock_irqsave+0x9 
(enable_8259A_irq+0x20)
 |   #begin   0x80000001    72    0.109  __ipipe_spin_lock_irqsave+0x4b 
(enable_8259A_irq+0x20)
 |   #func                  73    0.104  __ipipe_spin_unlock_irqrestore+0x9 
(enable_8259A_irq+0x61)
 |   #end     0x80000001    73    0.114  __ipipe_spin_unlock_irqrestore+0x36 
(enable_8259A_irq+0x61)
     #func                  73    0.104  ipipe_check_context+0xc 
(handle_level_irq+0x95)
     #func                  73    0.124  irq_exit+0x8 (do_IRQ+0x41)
     #func                  73    0.079  do_softirq+0xa (irq_exit+0x45)
     #func                  73    0.104  ipipe_check_context+0xc 
(do_softirq+0x2a)
     #func                  73    0.089  __do_softirq+0xb (do_softirq+0x65)
     #func                  73    0.000  __ipipe_unstall_root+0x8 
(__do_softirq+0x3f)
[EMAIL PROTECTED]:~#

> 
> > 
> >> BTW, does the latency test of Xenomai work?
> > 
> > No. It hangs after "warming up". I'm able to interrupt with ^C and then
> > it prints a single line showing a max latency of 208983.492 ms (same value
> > on several invocations).
> 
> Ah, then we may fail to program the APIC appropriately.

[EMAIL PROTECTED]:# zgrep APIC /proc/config.gz
# CONFIG_X86_UP_APIC is not set

Do you mean the PIT ?

> That would need
> a closer look if you want to dig into this.

I'm not sure how much time I have to investigate this, but yes, I can take a
look if you tell me what I should look for.

> /me is going to be
> distracted from this for now.

Thanks,

Stelian.
-- 
Stelian Pop <[EMAIL PROTECTED]>    

_______________________________________________
Xenomai-core mailing list
Xenomai-core@gna.org
https://mail.gna.org/listinfo/xenomai-core

Reply via email to