[ovs-dev] [PATCH 4/4] ofproto: Log flow mod statistics per controller rather than per switch.

Ben Pfaff blp at nicira.com
Mon May 5 19:35:32 UTC 2014


Applied, thank you!

On Fri, May 02, 2014 at 04:25:03PM -0700, Alex Wang wrote:
> All four patches look good to me,
> 
> Acked-by: Alex Wang <alexw at nicira.com>
> 
> 
> On Wed, Apr 30, 2014 at 10:51 AM, Ben Pfaff <blp at nicira.com> wrote:
> 
> > I've had a number of requests for more specific logging of flow_mod
> > information.  It is useful for troubleshooting.
> >
> > Signed-off-by: Ben Pfaff <blp at nicira.com>
> > ---
> >  ofproto/connmgr.c          |   98
> > ++++++++++++++++++++++++++++++++++++++++++++
> >  ofproto/connmgr.h          |    3 ++
> >  ofproto/ofproto-provider.h |    6 ---
> >  ofproto/ofproto.c          |   68 +-----------------------------
> >  4 files changed, 102 insertions(+), 73 deletions(-)
> >
> > diff --git a/ofproto/connmgr.c b/ofproto/connmgr.c
> > index 9a5167d..0cf9e2d 100644
> > --- a/ofproto/connmgr.c
> > +++ b/ofproto/connmgr.c
> > @@ -22,6 +22,7 @@
> >  #include <stdlib.h>
> >
> >  #include "coverage.h"
> > +#include "dynamic-string.h"
> >  #include "fail-open.h"
> >  #include "in-band.h"
> >  #include "odp-util.h"
> > @@ -99,6 +100,12 @@ struct ofconn {
> >      uint32_t master_async_config[OAM_N_TYPES]; /* master, other */
> >      uint32_t slave_async_config[OAM_N_TYPES];  /* slave */
> >
> > +    /* Flow table operation logging. */
> > +    int n_add, n_delete, n_modify; /* Number of unreported ops of each
> > kind. */
> > +    long long int first_op, last_op; /* Range of times for unreported
> > ops. */
> > +    long long int next_op_report;    /* Time to report ops, or LLONG_MAX.
> > */
> > +    long long int op_backoff;        /* Earliest time to report ops
> > again. */
> > +
> >  /* Flow monitors (e.g. NXST_FLOW_MONITOR). */
> >
> >      /* Configuration.  Contains "struct ofmonitor"s. */
> > @@ -145,6 +152,8 @@ static void ofconn_run(struct ofconn *,
> >                                                 const struct ofpbuf
> > *ofp_msg));
> >  static void ofconn_wait(struct ofconn *, bool handling_openflow);
> >
> > +static void ofconn_log_flow_mods(struct ofconn *);
> > +
> >  static const char *ofconn_get_target(const struct ofconn *);
> >  static char *ofconn_make_name(const struct connmgr *, const char *target);
> >
> > @@ -1115,6 +1124,39 @@ ofconn_pktbuf_retrieve(struct ofconn *ofconn,
> > uint32_t id,
> >      return pktbuf_retrieve(ofconn->pktbuf, id, bufferp, in_port);
> >  }
> >
> > +/* Reports that a flow_mod operation of the type specified by 'command'
> > was
> > + * successfully executed by 'ofconn', so that the connmgr can log it. */
> > +void
> > +ofconn_report_flow_mod(struct ofconn *ofconn,
> > +                       enum ofp_flow_mod_command command)
> > +{
> > +    long long int now;
> > +
> > +    switch (command) {
> > +    case OFPFC_ADD:
> > +        ofconn->n_add++;
> > +        break;
> > +
> > +    case OFPFC_MODIFY:
> > +    case OFPFC_MODIFY_STRICT:
> > +        ofconn->n_modify++;
> > +        break;
> > +
> > +    case OFPFC_DELETE:
> > +    case OFPFC_DELETE_STRICT:
> > +        ofconn->n_delete++;
> > +        break;
> > +    }
> > +
> > +    now = time_msec();
> > +    if (ofconn->next_op_report == LLONG_MAX) {
> > +        ofconn->first_op = now;
> > +        ofconn->next_op_report = MAX(now + 10 * 1000, ofconn->op_backoff);
> > +        ofconn->op_backoff = ofconn->next_op_report + 60 * 1000;
> > +    }
> > +    ofconn->last_op = now;
> > +}
> > +
> >  /* Returns true if 'ofconn' has any pending opgroups. */
> >  bool
> >  ofconn_has_pending_opgroups(const struct ofconn *ofconn)
> > @@ -1177,6 +1219,8 @@ ofconn_flush(struct ofconn *ofconn)
> >      struct ofmonitor *monitor, *next_monitor;
> >      int i;
> >
> > +    ofconn_log_flow_mods(ofconn);
> > +
> >      ofconn->role = OFPCR12_ROLE_EQUAL;
> >      ofconn_set_protocol(ofconn, OFPUTIL_P_NONE);
> >      ofconn->packet_in_format = NXPIF_OPENFLOW10;
> > @@ -1244,6 +1288,11 @@ ofconn_flush(struct ofconn *ofconn)
> >                 sizeof ofconn->slave_async_config);
> >      }
> >
> > +    ofconn->n_add = ofconn->n_delete = ofconn->n_modify = 0;
> > +    ofconn->first_op = ofconn->last_op = LLONG_MIN;
> > +    ofconn->next_op_report = LLONG_MAX;
> > +    ofconn->op_backoff = LLONG_MIN;
> > +
> >      HMAP_FOR_EACH_SAFE (monitor, next_monitor, ofconn_node,
> >                          &ofconn->monitors) {
> >          ofmonitor_destroy(monitor);
> > @@ -1348,6 +1397,11 @@ ofconn_run(struct ofconn *ofconn,
> >          }
> >      }
> >
> > +
> > +    if (time_msec() >= ofconn->next_op_report) {
> > +        ofconn_log_flow_mods(ofconn);
> > +    }
> > +
> >      ovs_mutex_lock(&ofproto_mutex);
> >      if (!rconn_is_alive(ofconn->rconn)) {
> >          ofconn_destroy(ofconn);
> > @@ -1369,6 +1423,50 @@ ofconn_wait(struct ofconn *ofconn, bool
> > handling_openflow)
> >      if (handling_openflow && ofconn_may_recv(ofconn)) {
> >          rconn_recv_wait(ofconn->rconn);
> >      }
> > +    if (ofconn->next_op_report != LLONG_MAX) {
> > +        poll_timer_wait_until(ofconn->next_op_report);
> > +    }
> > +}
> > +
> > +static void
> > +ofconn_log_flow_mods(struct ofconn *ofconn)
> > +{
> > +    int n_flow_mods = ofconn->n_add + ofconn->n_delete + ofconn->n_modify;
> > +    if (n_flow_mods) {
> > +        long long int ago = (time_msec() - ofconn->first_op) / 1000;
> > +        long long int interval = (ofconn->last_op - ofconn->first_op) /
> > 1000;
> > +        struct ds s;
> > +
> > +        ds_init(&s);
> > +        ds_put_format(&s, "%d flow_mods ", n_flow_mods);
> > +        if (interval == ago) {
> > +            ds_put_format(&s, "in the last %lld s", ago);
> > +        } else if (interval) {
> > +            ds_put_format(&s, "in the %lld s starting %lld s ago",
> > +                          interval, ago);
> > +        } else {
> > +            ds_put_format(&s, "%lld s ago", ago);
> > +        }
> > +
> > +        ds_put_cstr(&s, " (");
> > +        if (ofconn->n_add) {
> > +            ds_put_format(&s, "%d adds, ", ofconn->n_add);
> > +        }
> > +        if (ofconn->n_delete) {
> > +            ds_put_format(&s, "%d deletes, ", ofconn->n_delete);
> > +        }
> > +        if (ofconn->n_modify) {
> > +            ds_put_format(&s, "%d modifications, ", ofconn->n_modify);
> > +        }
> > +        s.length -= 2;
> > +        ds_put_char(&s, ')');
> > +
> > +        VLOG_INFO("%s: %s", rconn_get_name(ofconn->rconn), ds_cstr(&s));
> > +        ds_destroy(&s);
> > +
> > +        ofconn->n_add = ofconn->n_delete = ofconn->n_modify = 0;
> > +    }
> > +    ofconn->next_op_report = LLONG_MAX;
> >  }
> >
> >  /* Returns true if 'ofconn' should receive asynchronous messages of the
> > given
> > diff --git a/ofproto/connmgr.h b/ofproto/connmgr.h
> > index c09c80f..036d125 100644
> > --- a/ofproto/connmgr.h
> > +++ b/ofproto/connmgr.h
> > @@ -159,6 +159,9 @@ enum ofperr ofconn_pktbuf_retrieve(struct ofconn *,
> > uint32_t id,
> >  bool ofconn_has_pending_opgroups(const struct ofconn *);
> >  void ofconn_add_opgroup(struct ofconn *, struct list *);
> >
> > +/* Logging flow_mod summaries. */
> > +void ofconn_report_flow_mod(struct ofconn *, enum ofp_flow_mod_command);
> > +
> >  /* Sending asynchronous messages. */
> >  bool connmgr_wants_packet_in_on_miss(struct connmgr *mgr);
> >  void connmgr_send_port_status(struct connmgr *, struct ofconn *source,
> > diff --git a/ofproto/ofproto-provider.h b/ofproto/ofproto-provider.h
> > index 8f4f41e..141adec 100644
> > --- a/ofproto/ofproto-provider.h
> > +++ b/ofproto/ofproto-provider.h
> > @@ -133,12 +133,6 @@ struct ofproto {
> >       * the flow table and reacquire the global lock. */
> >      struct guarded_list rule_executes; /* Contains "struct
> > rule_execute"s. */
> >
> > -    /* Flow table operation logging. */
> > -    int n_add, n_delete, n_modify; /* Number of unreported ops of each
> > kind. */
> > -    long long int first_op, last_op; /* Range of times for unreported
> > ops. */
> > -    long long int next_op_report;    /* Time to report ops, or LLONG_MAX.
> > */
> > -    long long int op_backoff;        /* Earliest time to report ops
> > again. */
> > -
> >      /* Linux VLAN device support (e.g. "eth0.10" for VLAN 10.)
> >       *
> >       * This is deprecated.  It is only for compatibility with broken
> > device
> > diff --git a/ofproto/ofproto.c b/ofproto/ofproto.c
> > index 3d788a6..7f5f792 100644
> > --- a/ofproto/ofproto.c
> > +++ b/ofproto/ofproto.c
> > @@ -529,10 +529,6 @@ ofproto_create(const char *datapath_name, const char
> > *datapath_type,
> >      ofproto->n_pending = 0;
> >      hmap_init(&ofproto->deletions);
> >      guarded_list_init(&ofproto->rule_executes);
> > -    ofproto->n_add = ofproto->n_delete = ofproto->n_modify = 0;
> > -    ofproto->first_op = ofproto->last_op = LLONG_MIN;
> > -    ofproto->next_op_report = LLONG_MAX;
> > -    ofproto->op_backoff = LLONG_MIN;
> >      ofproto->vlan_bitmap = NULL;
> >      ofproto->vlans_changed = false;
> >      ofproto->min_mtu = INT_MAX;
> > @@ -1561,43 +1557,6 @@ ofproto_run(struct ofproto *p)
> >          OVS_NOT_REACHED();
> >      }
> >
> > -    if (time_msec() >= p->next_op_report) {
> > -        long long int ago = (time_msec() - p->first_op) / 1000;
> > -        long long int interval = (p->last_op - p->first_op) / 1000;
> > -        struct ds s;
> > -
> > -        ds_init(&s);
> > -        ds_put_format(&s, "%d flow_mods ",
> > -                      p->n_add + p->n_delete + p->n_modify);
> > -        if (interval == ago) {
> > -            ds_put_format(&s, "in the last %lld s", ago);
> > -        } else if (interval) {
> > -            ds_put_format(&s, "in the %lld s starting %lld s ago",
> > -                          interval, ago);
> > -        } else {
> > -            ds_put_format(&s, "%lld s ago", ago);
> > -        }
> > -
> > -        ds_put_cstr(&s, " (");
> > -        if (p->n_add) {
> > -            ds_put_format(&s, "%d adds, ", p->n_add);
> > -        }
> > -        if (p->n_delete) {
> > -            ds_put_format(&s, "%d deletes, ", p->n_delete);
> > -        }
> > -        if (p->n_modify) {
> > -            ds_put_format(&s, "%d modifications, ", p->n_modify);
> > -        }
> > -        s.length -= 2;
> > -        ds_put_char(&s, ')');
> > -
> > -        VLOG_INFO("%s: %s", p->name, ds_cstr(&s));
> > -        ds_destroy(&s);
> > -
> > -        p->n_add = p->n_delete = p->n_modify = 0;
> > -        p->next_op_report = LLONG_MAX;
> > -    }
> > -
> >      return error;
> >  }
> >
> > @@ -4513,7 +4472,6 @@ handle_flow_mod(struct ofconn *ofconn, const struct
> > ofp_header *oh)
> >      uint64_t ofpacts_stub[1024 / 8];
> >      struct ofpbuf ofpacts;
> >      enum ofperr error;
> > -    long long int now;
> >
> >      error = reject_slave_controller(ofconn);
> >      if (error) {
> > @@ -4535,31 +4493,7 @@ handle_flow_mod(struct ofconn *ofconn, const struct
> > ofp_header *oh)
> >          goto exit_free_ofpacts;
> >      }
> >
> > -    /* Record the operation for logging a summary report. */
> > -    switch (fm.command) {
> > -    case OFPFC_ADD:
> > -        ofproto->n_add++;
> > -        break;
> > -
> > -    case OFPFC_MODIFY:
> > -    case OFPFC_MODIFY_STRICT:
> > -        ofproto->n_modify++;
> > -        break;
> > -
> > -    case OFPFC_DELETE:
> > -    case OFPFC_DELETE_STRICT:
> > -        ofproto->n_delete++;
> > -        break;
> > -    }
> > -
> > -    now = time_msec();
> > -    if (ofproto->next_op_report == LLONG_MAX) {
> > -        ofproto->first_op = now;
> > -        ofproto->next_op_report = MAX(now + 10 * 1000,
> > -                                      ofproto->op_backoff);
> > -        ofproto->op_backoff = ofproto->next_op_report + 60 * 1000;
> > -    }
> > -    ofproto->last_op = now;
> > +    ofconn_report_flow_mod(ofconn, fm.command);
> >
> >  exit_free_ofpacts:
> >      ofpbuf_uninit(&ofpacts);
> > --
> > 1.7.10.4
> >
> > _______________________________________________
> > dev mailing list
> > dev at openvswitch.org
> > http://openvswitch.org/mailman/listinfo/dev
> >



More information about the dev mailing list