I-pipe frozen back-tracing service on 2.6.20/ipipe-1.8-08 ------------------------------------------------------------ ******** WARNING ******** The following debugging options will increase the observed latencies: o CONFIG_XENO_OPT_DEBUG Freeze: 4268773560534 cycles, Trace Points: 128 (+10) Calibrated minimum trace-point overhead: 0.247 us +----- Hard IRQs ('|': locked) |+---- ||+--- Xenomai |||+-- IShield ||||+- Linux ('*': domain stalled, '+': current, '#': current+stalled) ||||| +---------- Delay flag ('+': > 1 us, '!': > 10 us) ||||| | +- NMI noise ('N') ||||| | | Type User Val. Time Delay Function (Parent) : +func -138 0.681 __tcp_select_window+0xe (tcp_transmit_skb+0x19b) : +func -137 0.523 tcp_v4_send_check+0x14 (tcp_transmit_skb+0x45a) : +func -137 0.301 ip_queue_xmit+0xe (tcp_transmit_skb+0x3b0) : +func -137 0.698 __sk_dst_check+0x11 (ip_queue_xmit+0x29e) : +func -136 0.539 ip_output+0xe (ip_queue_xmit+0x1ac) : +func -135 0.325 dev_queue_xmit+0xe (ip_output+0x10b) : +func -135 0.284 local_bh_disable+0x8 (dev_queue_xmit+0x43) : +func -135 0.382 ipipe_check_context+0xc (dev_queue_xmit+0x5d) : +func -134 0.374 pfifo_fast_enqueue+0xa (dev_queue_xmit+0x71) : +func -134 0.293 __qdisc_run+0xe (dev_queue_xmit+0x1df) : +func -134 0.346 pfifo_fast_dequeue+0x9 (__qdisc_run+0x99) : +func -133 0.342 ipipe_check_context+0xc (__qdisc_run+0x10a) : +func -133 0.263 ipipe_check_context+0xc (__qdisc_run+0x54) : +func -133 0.265 dev_hard_start_xmit+0xe (__qdisc_run+0x64) : +func -132 0.326 ipipe_check_context+0xc (dev_hard_start_xmit+0x4f) : +func -132 0.382 skb_clone+0xe (dev_hard_start_xmit+0xa9) : +func -132 0.267 kmem_cache_alloc+0x14 (skb_clone+0x3c) : +func -131 0.290 ipipe_check_context+0xc (kmem_cache_alloc+0x27) : #func -131 0.284 __ipipe_restore_root+0x8 (kmem_cache_alloc+0x68) : #func -131 0.379 __ipipe_unstall_root+0x8 (__ipipe_restore_root+0x1b) :| #begin 0x80000000 -131 0.331 __ipipe_unstall_root+0x4b (__ipipe_restore_root+0x1b) :| +end 0x80000000 -130 0.612 __ipipe_unstall_root+0x3a (__ipipe_restore_root+0x1b) : +func -130 0.295 packet_rcv_spkt+0x14 (dev_hard_start_xmit+0xfe) : +func -129 0.468 strlcpy+0x14 (packet_rcv_spkt+0x8e) : +func -129 0.265 sock_queue_rcv_skb+0x14 (packet_rcv_spkt+0xa0) : +func -129 0.285 local_bh_disable+0x8 (sock_queue_rcv_skb+0x45) : +func -128 0.595 sk_run_filter+0x14 (sock_queue_rcv_skb+0x5c) : +func -128 0.370 local_bh_enable+0xb (sock_queue_rcv_skb+0xd5) : +func -127 0.296 ipipe_check_context+0xc (local_bh_enable+0x49) : +func -127 0.260 kfree_skb+0x8 (packet_rcv_spkt+0xab) : +func -127 0.301 __kfree_skb+0x11 (kfree_skb+0x1e) : +func -126 0.459 kfree_skbmem+0x9 (__kfree_skb+0x47) : +func -126 0.330 skb_release_data+0xa (kfree_skbmem+0x10) : +func -126 0.260 kmem_cache_free+0xe (kfree_skbmem+0x3d) : +func -125 0.278 ipipe_check_context+0xc (kmem_cache_free+0x40) : #func -125 0.356 __ipipe_restore_root+0x8 (kmem_cache_free+0x84) : #func -125 0.308 __ipipe_unstall_root+0x8 (__ipipe_restore_root+0x1b) :| #begin 0x80000000 -124 0.310 __ipipe_unstall_root+0x4b (__ipipe_restore_root+0x1b) :| +end 0x80000000 -124 0.441 __ipipe_unstall_root+0x3a (__ipipe_restore_root+0x1b) : +func -124 0.387 ipipe_check_context+0xc (dev_hard_start_xmit+0x10d) : +func -123 0.348 boomerang_start_xmit+0xe (dev_hard_start_xmit+0x1cb) : +func -123 0.301 ipipe_check_context+0xc (boomerang_start_xmit+0x123) : #func -123 0.303 ipipe_check_context+0xc (boomerang_start_xmit+0x163) : #func -122 0.349 issue_and_wait+0xe (boomerang_start_xmit+0x170) : #func -122 0.349 iowrite16+0x8 (issue_and_wait+0x2a) : #func -122! 12.419 ioread16+0x8 (issue_and_wait+0x45) : #func -109+ 1.352 ioread32+0x8 (boomerang_start_xmit+0x188) : #func -108 0.418 iowrite16+0x8 (boomerang_start_xmit+0x1c9) : #func -107 0.336 __ipipe_restore_root+0x8 (boomerang_start_xmit+0x1d0) : #func -107 0.316 __ipipe_unstall_root+0x8 (__ipipe_restore_root+0x1b) :| #begin 0x80000000 -107 0.310 __ipipe_unstall_root+0x4b (__ipipe_restore_root+0x1b) :| +end 0x80000000 -106 0.464 __ipipe_unstall_root+0x3a (__ipipe_restore_root+0x1b) : +func -106 0.439 ipipe_check_context+0xc (boomerang_start_xmit+0x1da) : +func -106 0.267 ipipe_check_context+0xc (__qdisc_run+0x134) : +func -105 0.296 ipipe_check_context+0xc (__qdisc_run+0x7a) : +func -105 0.484 pfifo_fast_dequeue+0x9 (__qdisc_run+0x99) : +func -105 0.265 ipipe_check_context+0xc (dev_queue_xmit+0x93) : +func -104 0.275 local_bh_enable+0xb (dev_queue_xmit+0xa1) : +func -104 0.357 ipipe_check_context+0xc (local_bh_enable+0x49) : +func -104 0.408 update_send_head+0xa (tcp_push_one+0xca) : +func -103 0.374 tcp_cwnd_validate+0x8 (tcp_push_one+0xd4) : +func -103 0.310 __alloc_skb+0xe (tcp_sendmsg+0x36c) : +func -103 0.267 kmem_cache_alloc+0x14 (__alloc_skb+0x30) : +func -102 0.349 ipipe_check_context+0xc (kmem_cache_alloc+0x8a) : +func -102 0.267 cond_resched+0x8 (kmem_cache_alloc+0x8f) : +func -102 0.286 ipipe_check_context+0xc (kmem_cache_alloc+0x27) : #func -101 0.284 __ipipe_restore_root+0x8 (kmem_cache_alloc+0x68) : #func -101 0.372 __ipipe_unstall_root+0x8 (__ipipe_restore_root+0x1b) :| #begin 0x80000000 -101 0.310 __ipipe_unstall_root+0x4b (__ipipe_restore_root+0x1b) :| +end 0x80000000 -100 0.344 __ipipe_unstall_root+0x3a (__ipipe_restore_root+0x1b) : +func -100 0.331 __kmalloc+0xe (__alloc_skb+0x4d) : +func -100 0.363 ipipe_check_context+0xc (__kmalloc+0xb2) : +func -99 0.269 cond_resched+0x8 (__kmalloc+0xb7) : +func -99 0.280 ipipe_check_context+0xc (__kmalloc+0x4e) : #func -99 0.286 __ipipe_restore_root+0x8 (__kmalloc+0x8a) : #func -99 0.377 __ipipe_unstall_root+0x8 (__ipipe_restore_root+0x1b) :| #begin 0x80000000 -98 0.374 __ipipe_unstall_root+0x4b (__ipipe_restore_root+0x1b) :| +end 0x80000000 -98+ 1.428 __ipipe_unstall_root+0x3a (__ipipe_restore_root+0x1b) :| +begin 0xffffff16 -96 0.349 ipipe_ipi3+0x2e (__alloc_skb+0xdd) :| +func -96 0.396 __ipipe_handle_irq+0x14 (ipipe_ipi3+0x33) :| +func -96 0.312 __ipipe_ack_apic+0x8 (__ipipe_handle_irq+0xaf) :| +func -95 0.454 __ipipe_dispatch_wired+0x16 (__ipipe_handle_irq+0x68) :| # func -95 0.329 xnintr_clock_handler+0x8 (__ipipe_dispatch_wired+0x9f) :| # func -95 0.400 xnintr_irq_handler+0xe (xnintr_clock_handler+0x17) :| # func -94 0.312 xnpod_announce_tick+0x8 (xnintr_irq_handler+0x3b) :| # func -94 0.497 xntimer_do_tick_aperiodic+0xe (xnpod_announce_tick+0xf) :| # func -93 0.301 xnthread_periodic_handler+0x8 (xntimer_do_tick_aperiodic+0x217) :| # func -93 0.375 xnpod_resume_thread+0xe (xnthread_periodic_handler+0x2c) :| # [ 4196] samplin 99 -93 0.933 xnpod_resume_thread+0x56 (xnthread_periodic_handler+0x2c) :| # func -92 0.327 xnpod_schedule+0xe (xnintr_irq_handler+0x135) :| # [ 3457] konsole -1 -91+ 1.299 xnpod_schedule+0x90 (xnintr_irq_handler+0x135) :| # func -90 0.639 __switch_to+0xe (xnpod_schedule+0x493) :| # [ 4196] samplin 99 -89 0.642 xnpod_schedule+0x56b (xnpod_suspend_thread+0x18b) :| # func -89 0.353 __ipipe_restore_pipeline_head+0x12 (xnpod_wait_thread_period+0x12b) :| + end 0x80000000 -88+ 1.363 __ipipe_restore_pipeline_head+0x5c (xnpod_wait_thread_period+0x12b) :| + begin 0xfffffffa -87 0.530 common_interrupt+0x29 (__ipipe_restore_pipeline_head+0x60) :| + func -87 0.454 __ipipe_handle_irq+0x14 (common_interrupt+0x2e) :| + func -86 0.263 __ipipe_ack_irq+0x8 (__ipipe_handle_irq+0x151) :| + func -86 0.307 __ipipe_ack_level_irq+0x12 (__ipipe_ack_irq+0x19) :| + func -86 0.352 mask_and_ack_8259A+0x14 (__ipipe_ack_level_irq+0x22) :| + func -85! 30.267 __ipipe_spin_lock_irqsave+0x9 (mask_and_ack_8259A+0x29) :| # func -55 0.385 __ipipe_spin_unlock_irqrestore+0x9 (mask_and_ack_8259A+0x73) :| + func -54 0.349 __ipipe_walk_pipeline+0xe (__ipipe_handle_irq+0x81) :| + end 0xfffffffa -54+ 2.204 common_interrupt+0x38 (__ipipe_restore_pipeline_head+0x60) :| + begin 0xfffffff1 -52 0.331 common_interrupt+0x29 (__ipipe_restore_pipeline_head+0x60) :| + func -52 0.804 __ipipe_handle_irq+0x14 (common_interrupt+0x2e) :| + func -51 0.371 __ipipe_ack_irq+0x8 (__ipipe_handle_irq+0x151) :| + func -50 0.321 __ipipe_ack_level_irq+0x12 (__ipipe_ack_irq+0x19) :| + func -50 0.252 mask_and_ack_8259A+0x14 (__ipipe_ack_level_irq+0x22) :| + func -50! 38.784 __ipipe_spin_lock_irqsave+0x9 (mask_and_ack_8259A+0x29) :| # func -11 0.367 __ipipe_spin_unlock_irqrestore+0x9 (mask_and_ack_8259A+0x73) :| + func -11 0.346 __ipipe_walk_pipeline+0xe (__ipipe_handle_irq+0x81) :| + end 0xfffffff1 -10 0.715 common_interrupt+0x38 (__ipipe_restore_pipeline_head+0x60) :| + begin 0x80000001 -10 0.351 __ipipe_dispatch_event+0x180 (__ipipe_syscall_root+0x44) :| + end 0x80000001 -9+ 3.002 __ipipe_dispatch_event+0x154 (__ipipe_syscall_root+0x44) : + func -6 0.349 __ipipe_syscall_root+0xa (system_call+0x29) : + func -6 0.297 __ipipe_dispatch_event+0xe (__ipipe_syscall_root+0x44) :| + begin 0x80000001 -6 0.383 __ipipe_dispatch_event+0x1a0 (__ipipe_syscall_root+0x44) :| + end 0x80000001 -5 0.292 __ipipe_dispatch_event+0x18f (__ipipe_syscall_root+0x44) : + func -5+ 1.207 hisyscall_event+0x14 (__ipipe_dispatch_event+0xb5) : + func -4+ 1.024 xnshadow_sys_trace+0x16 (hisyscall_event+0x189) : + func -3 0.569 ipipe_trace_frozen_reset+0x9 (xnshadow_sys_trace+0xd7) : + func -2 0.259 __ipipe_global_path_lock+0x8 (ipipe_trace_frozen_reset+0x13) : + func -2 0.355 __ipipe_spin_lock_irqsave+0x9 (__ipipe_global_path_lock+0x12) :| + begin 0x80000001 -2+ 1.393 __ipipe_spin_lock_irqsave+0x3d (__ipipe_global_path_lock+0x12) :| # func 0 0.297 __ipipe_spin_unlock_irqcomplete+0x9 (__ipipe_global_path_unlock+0x63) :| + end 0x80000001 0 0.360 __ipipe_spin_unlock_irqcomplete+0x2e (__ipipe_global_path_unlock+0x63) < + freeze 0x00015719 0 0.605 xnshadow_sys_trace+0xa0 (hisyscall_event+0x189) | + begin 0x80000001 0 0.316 __ipipe_dispatch_event+0x180 (__ipipe_syscall_root+0x44) | + end 0x80000001 0 0.989 __ipipe_dispatch_event+0x154 (__ipipe_syscall_root+0x44) + func 1 0.310 __ipipe_syscall_root+0xa (system_call+0x29) + func 2 0.571 __ipipe_dispatch_event+0xe (__ipipe_syscall_root+0x44) | + begin 0xffffff16 2 0.289 ipipe_ipi3+0x2e (__ipipe_dispatch_event+0x15) | + func 3 0.312 __ipipe_handle_irq+0x14 (ipipe_ipi3+0x33) | + func 3 0.319 __ipipe_ack_apic+0x8 (__ipipe_handle_irq+0xaf) | + func 3 0.367 __ipipe_dispatch_wired+0x16 (__ipipe_handle_irq+0x68) | # func 4 0.289 xnintr_clock_handler+0x8 (__ipipe_dispatch_wired+0x9f) | # func 4 0.000 xnintr_irq_handler+0xe (xnintr_clock_handler+0x17)