How to get Packet Processing(packet_in, flow_match, output) time in OVS switch?

I'm trying to evaluate a routing technique implemented by me with Mininet, Open vSwitch and Ryu controller. But currently I'm unable to figure out the measurement techniques of packet processing time within switch. I can measure probe message processing time as packet_in occurs for those and reports back to controller program. But how to measure processing time for packets whose presence will not be reported back to the controller by switch(packet_in will not occur)? Probably ovs-ofctl command has some options that can report me the time. But still not sure how to do that. Please help me in this circumstance. I have not got enough resources over the internet. Thanks in advance for your help.

Solution

As long as you're using the kernel datapath of Open vSwitch, you should be able to retrieve the processing delay for each packet using the usual Linux tracing toolkits.

Below is an example using the BPF infrastructure (requires Linux v4.4+) and the bcc toolkit (I have version 0.5.0-1). Note, however, that for high packet rates, the overhead from running this tool may be significant. Another way to measure the overhead your modifications add is to measure the maximum throughput the switch can achieve with and without your modifications.

#!/usr/bin/env python
from bcc import BPF
import sys
import ctypes as ct

prog = """
#include <uapi/linux/ptrace.h>
#include <linux/openvswitch.h>

struct vport;

enum action_t {
    DROP = 0,
    OUTPUT,
};

struct proc_record_t {
    u64 delay;
    enum action_t action;
};

BPF_HASH(pkts, struct sk_buff *, u64, 1024);
BPF_PERF_OUTPUT(events);

// Take a timestamp at packet reception by Open vSwitch.
int
kprobe__ovs_vport_receive(struct pt_regs *ctx, struct vport *port, struct sk_buff *skb) {
    u64 ts = bpf_ktime_get_ns();
    pkts.update(&skb, &ts);
    return 0;
}

// Once the packet has been processed by the switch, measure the processing delay and send to userspace using perf_submit.
static inline void
end_processing(struct pt_regs *ctx, struct sk_buff *skb, enum action_t action) {
    u64 *tsp = pkts.lookup(&skb);
    if (tsp) {
        u64 ts = bpf_ktime_get_ns();
        struct proc_record_t record = {};
        record.delay = ts - *tsp;
        record.action = action;
        events.perf_submit(ctx, &record, sizeof(record));
        pkts.delete(&skb);
    }
}

// Called when packets are dropped by Open vSwitch.
int
kprobe__consume_skb(struct pt_regs *ctx, struct sk_buff *skb) {
    end_processing(ctx, skb, DROP);
    return 0;
}

// Called when packets are outputted by Open vSwitch.
int
kprobe__ovs_vport_send(struct pt_regs *ctx, struct vport *vport, struct sk_buff *skb) {
    end_processing(ctx, skb, OUTPUT);
    return 0;
}
"""

b = BPF(text=prog)

class Data(ct.Structure):
    _fields_ = [("delay", ct.c_ulonglong),
                ("action", ct.c_int)]
actions = ["drop", "output"]

print("%-18s %s" % ("DELAY(ns)", "ACTION"))

# Callback function to display information from kernel
def print_event(cpu, data, size):
    event = ct.cast(data, ct.POINTER(Data)).contents
    print("%-18d %s" % (event.delay, actions[event.action]))

b["events"].open_perf_buffer(print_event)
while True:
    b.kprobe_poll()

You'll need to install bcc to execute this script. Then, it's as simple as:

$ sudo python trace_processing_time.py
DELAY(ns)          ACTION
97385              drop
55630              drop
38768              drop
61113              drop
10382              output
14795              output

See the bcc documentation for details on how this script works. You will need to change it if you want to support more OpenFlow actions (only drop and output currently).