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
