November 5, 2015

Linux ftrace: UDP transmit packet kernel code path

Checkout earlier blog entry on setting up ftrace to capture this trace. I have removed most details with in ip filter related functions

Below trace is for udp_sendmsg (edited for clarity)

 0)               |  udp_sendmsg() {
 0)   0.093 us    |    sock_tx_timestamp();
 0)               |    sk_dst_check() {
 0)   0.070 us    |      ipv4_dst_check();
 0)   1.307 us    |    }
 0)               |    ip_make_skb() {
 0)               |      ip_setup_cork() {
 0)   0.209 us    |        ipv4_mtu();
 0)   0.909 us    |      }
 0)               |      __ip_append_data.isra.45() {
 0)               |        sock_alloc_send_skb() {
 0)               |          sock_alloc_send_pskb() {
 0)               |            __alloc_skb() {
 0)               |              kmem_cache_alloc_node() {
 0)   0.141 us    |                __might_sleep();
 0)   0.070 us    |                _cond_resched();
 0)   0.116 us    |                should_failslab();
 0)   0.102 us    |                kmemleak_alloc();
 0)   2.454 us    |              }
 0)               |              __kmalloc_reserve.isra.26() {
 0)               |                __kmalloc_node_track_caller() {
 0)   0.157 us    |                  kmalloc_slab();
 0)   0.133 us    |                  __might_sleep();
 0)   0.065 us    |                  _cond_resched();
 0)   0.074 us    |                  should_failslab();
 0)   0.075 us    |                  kmemleak_alloc();
 0)   3.474 us    |                }
 0)   3.980 us    |              }
 0)   0.252 us    |              ksize();
 0)   8.598 us    |            }
 0)   9.271 us    |          }
 0)   9.910 us    |        }
 0)   0.060 us    |        skb_put();
 0)               |        ip_generic_getfrag() {
 0)               |          memcpy_fromiovecend() {
 0)               |            might_fault() {
 0)   0.150 us    |              __might_sleep();
 0)   0.961 us    |            }
 0)   1.595 us    |          }
 0)   2.192 us    |        }
 0) + 14.200 us   |      }
 0)               |      __ip_make_skb() {
 0)   0.063 us    |        ipv4_mtu();
 0)               |        __ip_select_ident() {
 0)   1.272 us    |          inet_getpeer();
 0)               |          inet_putpeer() {
 0)   0.084 us    |            __smp_mb__before_atomic();
 0)   0.556 us    |          }
 0)   2.828 us    |        }
 0)   0.078 us    |        kfree();
 0)   0.070 us    |        dst_release();
 0)   5.206 us    |      }
 0) + 22.094 us   |    }
 0)               |    udp_send_skb() {
 0)               |      ip_send_skb() {
 0)               |        ip_local_out_sk() {
 0)               |          __ip_local_out() {
 0)               |            nf_hook_slow() {    
                                               ...edited...
 0) + 88.178 us   |            }
 0) + 88.869 us   |          }
 0)               |          ip_output() {
 0)               |            nf_hook_slow() {    
                                              ... edited ...
 0) + 50.133 us   |            }
 0)               |            ip_finish_output() {
 0)   0.070 us    |              ipv4_mtu();
 0)               |              local_bh_disable() {
 0)   0.092 us    |                __local_bh_disable();
 0)   0.625 us    |              }
 0)   0.130 us    |              rcu_read_lock_bh_held();
 0)   0.070 us    |              rcu_read_lock_bh_held();
 0)   0.062 us    |              skb_push();
 0)               |              dev_queue_xmit() {  http://lxr.free-electrons.com/source/net/core/dev.c?v=3.10#L2777
 0)               |                local_bh_disable() {
 0)   0.091 us    |                  __local_bh_disable();
 0)   0.551 us    |                }
 0)   0.086 us    |                rcu_read_lock_bh_held();
 0)   0.156 us    |                netdev_pick_tx();
 0)   0.066 us    |                rcu_read_lock_bh_held();
 0)   0.072 us    |                rcu_read_lock_bh_held();
 0)   0.637 us    |                _raw_spin_lock();
 0)               |                sch_direct_xmit() {
 0)   0.259 us    |                  _raw_spin_unlock();
 0)   0.579 us    |                  _raw_spin_lock();
 0)               |                  dev_hard_start_xmit() { http://lxr.free-electrons.com/source/net/core/dev.c?v=3.10#L2512
 0)   0.077 us    |                    dst_release();
 0)               |                    netif_skb_features() {
 0)               |                      harmonize_features.part.86() {
 0)   0.096 us    |                        skb_network_protocol();
 0)   0.704 us    |                      }
 0)   1.307 us    |                    }
 

In this function common code calls 'driver' specific transmit function, as shown at http://lxr.free-electrons.com/source/net/core/dev.c?v=3.10#L2580
 2580                 rc = ops->ndo_start_xmit(skb, dev);
Here ops is a pointer to net_device_ops, as defined http://lxr.free-electrons.com/source/include/linux/netdevice.h?v=3.10#L906
In the driver code, it set's up this struct and assign's it's functions to the generic function pointers as shown http://lxr.free-electrons.com/source/drivers/net/ethernet/intel/e1000e/netdev.c?v=3.10#L6457

6457 static const struct net_device_ops e1000e_netdev_ops = {
6458         .ndo_open               = e1000_open,
6459         .ndo_stop               = e1000_close,
6460         .ndo_start_xmit         = e1000_xmit_frame,
6461         .ndo_get_stats64        = e1000e_get_stats64,
6462         .ndo_set_rx_mode        = e1000e_set_rx_mode,
6463         .ndo_set_mac_address    = e1000_set_mac,
6464         .ndo_change_mtu         = e1000_change_mtu,
6465         .ndo_do_ioctl           = e1000_ioctl,
6466         .ndo_tx_timeout         = e1000_tx_timeout,
6467         .ndo_validate_addr      = eth_validate_addr,
6468 
6469         .ndo_vlan_rx_add_vid    = e1000_vlan_rx_add_vid,
6470         .ndo_vlan_rx_kill_vid   = e1000_vlan_rx_kill_vid,
6471 #ifdef CONFIG_NET_POLL_CONTROLLER
6472         .ndo_poll_controller    = e1000_netpoll,
6473 #endif
6474         .ndo_set_features = e1000_set_features,
6475 };
Underlying driver code get's executed
 0)               |                    e1000_xmit_frame [e1000]() {
 0)   0.187 us    |                      skb_pad();
 0)               |                      nommu_map_page() {
 0)   0.177 us    |                        check_addr();
 0)   0.861 us    |                      }
 0)   0.730 us    |                      _raw_spin_lock_irqsave();
 0)   0.348 us    |                      _raw_spin_unlock_irqrestore();
 0)   0.539 us    |                      _raw_spin_lock_irqsave();
 0)   0.333 us    |                      _raw_spin_unlock_irqrestore();
 0)               |                      save_stack_trace() {
 0)               |                        dump_trace() {
 0) + 20.129 us   |                          print_context_stack();
 0) + 21.455 us   |                        }
 0) + 22.056 us   |                      }
 0)   0.321 us    |                      _raw_spin_lock_irqsave();
 0)   0.249 us    |                      _raw_spin_unlock_irqrestore();
 0)   0.261 us    |                      _raw_spin_lock_irqsave();
 0)   0.226 us    |                      _raw_spin_unlock_irqrestore();
 0)               |                      skb_clone_tx_timestamp() {
 0)   0.059 us    |                        classify();
 0)   0.778 us    |                      }
 0)   ==========> |
 0)               |                      do_IRQ() {
 0)               |                        irq_enter() {
 0)   0.142 us    |                          rcu_irq_enter();
 0)   0.735 us    |                        }
 0)   0.071 us    |                        exit_idle();
 0)               |                        handle_irq() {
 0)   0.813 us    |                          irq_to_desc();
 0)               |                          handle_fasteoi_irq() {
 0)   1.031 us    |                            _raw_spin_lock();
 0)               |                            handle_irq_event() {
 0)   0.342 us    |                              _raw_spin_unlock();
 0)               |                              handle_irq_event_percpu() {
 0)               |                                e1000_intr [e1000]() {
 0)               |                                  __napi_schedule() {
 0)   0.078 us    |                                    __raise_softirq_irqoff();
 0)   0.932 us    |                                  }
 0) + 49.101 us   |                                }
 0)   0.655 us    |                                add_interrupt_randomness();
 0)   0.132 us    |                                note_interrupt();
 0) + 51.976 us   |                              }
 0)   0.840 us    |                              _raw_spin_lock();
 0) + 54.969 us   |                            }
 0)               |                            ack_apic_level() {
 0)   0.212 us    |                              irq_complete_move();
 0) + 41.956 us   |                            }
 0)   0.570 us    |                            _raw_spin_unlock();
 0) ! 101.772 us  |                          }
 0) ! 104.131 us  |                        }
 0)               |                        irq_exit() {
 0)   0.099 us    |                          idle_cpu();
 0)   0.164 us    |                          rcu_irq_exit();
 0)   1.684 us    |                        }
 0) ! 108.989 us  |                      }
 0)   <========== |
 0) ! 285.379 us  |                    }
 0) ! 289.474 us  |                  }
 0)   1.046 us    |                  _raw_spin_unlock();
 0)   1.076 us    |                  _raw_spin_lock();
 0) ! 295.938 us  |                }
 0)   0.261 us    |                _raw_spin_unlock();
 0)   0.211 us    |                local_bh_enable();
 0) ! 304.568 us  |              }   ==> dev_queue_xmit ends here

Below code looks to be cleaning up the ring buffer/memory used for the TX packet

 0)               |              local_bh_enable() {
 0)               |                do_softirq() {
 0)               |                  __do_softirq() {
 0)   0.082 us    |                    msecs_to_jiffies();
 0)   0.187 us    |                    __local_bh_disable();
 0)               |                    run_timer_softirq() {
 0)   0.089 us    |                      hrtimer_run_pending();
 0)   0.971 us    |                      _raw_spin_lock_irq();
 0)   0.545 us    |                      _raw_spin_unlock_irq();
 0)   4.199 us    |                    }
 0)   0.075 us    |                    rcu_bh_qs();
 0)               |                    net_rx_action() {
 0)               |                      e1000_clean [e1000]() {
 0)   0.186 us    |                        e1000_unmap_and_free_tx_resource.isra.36 [e1000]();
 0)               |                        e1000_unmap_and_free_tx_resource.isra.36 [e1000]() {
 0)   1.078 us    |                          _raw_spin_lock_irqsave();
 0)   0.833 us    |                          _raw_spin_lock_irqsave();
 0)   0.382 us    |                          _raw_spin_unlock_irqrestore();
 0)   0.404 us    |                          _raw_spin_unlock_irqrestore();
 0)               |                          dev_kfree_skb_any() {
 0)               |                            consume_skb() {
 0)               |                              skb_release_all() {
 0)               |                                skb_release_head_state() {
 0)               |                                  sock_wfree() {
 0)   1.178 us    |                                    sock_def_write_space();
 0)   2.294 us    |                                  }
 0)   3.436 us    |                                }
 0)               |                                skb_release_data() {
 0)               |                                  skb_free_head() {
 0)               |                                    kfree() {
 0)   0.223 us    |                                      kmemleak_free();
 0)   0.814 us    |                                      _raw_spin_lock_irqsave();
 0)   0.247 us    |                                      _raw_spin_unlock_irqrestore();
 0)   4.380 us    |                                    }
 0)   5.180 us    |                                  }
 0)   6.080 us    |                                }
 0) + 11.199 us   |                              }
 0)               |                              kfree_skbmem() {
 0)               |                                kmem_cache_free() {
 0)   0.091 us    |                                  kmemleak_free();
 0)   0.634 us    |                                  _raw_spin_lock_irqsave();
 0)   0.254 us    |                                  _raw_spin_unlock_irqrestore();
 0)   3.368 us    |                                }
 0)   4.317 us    |                              }
 0) + 17.709 us   |                            }
 0) + 18.576 us   |                          }
 0) + 26.477 us   |                        }
 0)   0.327 us    |                        e1000_clean_rx_irq [e1000]();
 0)   0.182 us    |                        e1000_update_itr [e1000]();
 0)   0.094 us    |                        e1000_update_itr [e1000]();
 0)               |                        napi_complete() {
 0)   0.094 us    |                          napi_gro_flush();
 0)               |                          __napi_complete() {
 0)   0.073 us    |                            __smp_mb__before_atomic();
 0)   1.002 us    |                          }
 0)   2.888 us    |                        }
 0) + 53.550 us   |                      }
 0)   0.162 us    |                      net_rps_action_and_irq_enable.isra.84();
 0) + 56.990 us   |                    }
 0)   0.084 us    |                    rcu_bh_qs();
 0)   0.185 us    |                    __local_bh_enable();
 0) + 67.206 us   |                  }
 0) + 68.256 us   |                }
 0) + 69.261 us   |              }
 0) ! 380.182 us  |            }
 0) ! 431.741 us  |          }
 0) ! 521.827 us  |        }
 0) ! 522.526 us  |      }
 0) ! 523.713 us  |    }
 0)   0.084 us    |    dst_release();
 0) ! 551.849 us  |  }

No comments:

Post a Comment