All four patches look good to me,
Acked-by: Alex Wang <al...@nicira.com>
On Wed, Apr 30, 2014 at 10:51 AM, Ben Pfaff <b...@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 <b...@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@openvswitch.org
> http://openvswitch.org/mailman/listinfo/dev
>
_______________________________________________
dev mailing list
dev@openvswitch.org
http://openvswitch.org/mailman/listinfo/dev
