[ovs-dev] [PATCH v4] ofproto-dpif: Make ofproto/trace output easier to read.
Ben Pfaff
blp at ovn.org
Thu Jan 12 17:23:02 UTC 2017
On Mon, Jan 09, 2017 at 08:46:28PM -0800, Justin Pettit wrote:
> I think it would be helpful to have a comment describing this
> function. Also mentioning that the caller maintains ownership of
> 'text'.
There was a lot of missing comments and documentation. I added a bunch.
> I may be missing something, but is there anything that frees these
> "oftrace_node"s either here or ofproto-dpif-xlate.c?
No. Oops. I fixed this.
> > On Jan 5, 2017, at 5:04 PM, Ben Pfaff <blp at ovn.org> wrote:
>
> > static void
> > +oftrace_node_print_details(struct ds *output,
> > + const struct ovs_list *nodes, int level)
> > {
> > + const struct oftrace_node *sub;
> > + LIST_FOR_EACH (sub, node, nodes) {
> > + bool more = sub->node.next != nodes || sub->always_indent || oftrace_node_type_is_terminal(sub->type);
>
> This line is much longer than 80 characters.
'always_indent' wasn't useful anyhow. I removed this clause and split
the line.
> > + bool title = sub->type == OFT_BRIDGE;
> >
> > ...
> > + if (title) {
> > + ds_put_char(output, '\n');
> > + }
> > + ds_put_char_multiple(output, ' ', (level + more) * 4);
>
> It's clever, but, 'more' being a bool looks kind of weird to me seeing
> it used for math.
I spent a few minutes thinking of other ways to express this, but (level
+ (more ? 1 : 0)) isn't better, and using a separate statement with ++
doesn't seem better either.
After talking to you for a minute in-person, I decided to leave this as
is.
> > + switch (sub->type) {
> > + case OFT_DETAIL:
> > + ds_put_format(output, " -> %s\n", sub->name);
> > + break;
> > + case OFT_WARN:
> > + ds_put_format(output, " >> %s\n", sub->name);
> > + break;
> > + case OFT_ERROR:
> > + ds_put_format(output, " >>>> %s <<<<\n", sub->name);
> > + break;
> > + case OFT_BRIDGE:
> > + ds_put_format(output, "%s\n", sub->name);
> > + ds_put_char_multiple(output, ' ', (level + more) * 4);
> > + ds_put_char_multiple(output, '-', strlen(sub->name));
> > + ds_put_char(output, '\n');
> > + break;
> > + case OFT_TABLE:
> > + case OFT_THAW:
> > + case OFT_ACTION:
> > + ds_put_format(output, "%s\n", sub->name);
> > + break;
> > }
>
> The actions printing at a shallower depth than the rule looks a little
> odd to me. I suppose that helps if there are a lot of actions.
> Regardless, I'm sure I'll get used to it.
It only seems at first glance that it's indented shallower, but in fact
it comes out in a natural way because of the nesting, e.g.:
bridge("br0")
-------------
0. priority 0
resubmit(,1)
1. in_port=2,vlan_tci=0x0000, priority 99
mod_vlan_vid:20
resubmit(,2)
2. No match.
drop
> > diff --git a/ofproto/ofproto-dpif-xlate.c b/ofproto/ofproto-dpif-xlate.c
> > index 371ced4..f96468d 100644
> > --- a/ofproto/ofproto-dpif-xlate.c
> > +++ b/ofproto/ofproto-dpif-xlate.c
> > ...
> > +static struct ovs_list * OVS_PRINTF_FORMAT(3, 4)
> > +xlate_report(const struct xlate_ctx *ctx, enum oftrace_node_type type,
> > + const char *format, ...)
> > {
> > - if (OVS_UNLIKELY(ctx->xin->report_hook)) {
> > + struct ovs_list *subtrace = NULL;
> > + if (OVS_UNLIKELY(ctx->xin->trace)) {
> > va_list args;
> > -
> > va_start(args, format);
> > - ctx->xin->report_hook(ctx->xin, ctx->indentation, format, args);
> > + char *text = xvasprintf(format, args);
> > + subtrace = &oftrace_report(ctx->xin->trace, type, text)->subs;
>
> I think you need to free "text", since oftrace_report() makes a copy.
Thanks, fixed.
> > +/* This is like xlate_report() for errors that are serious enough that we
> > + * should log them even if we are not tracing. */
> > +static void OVS_PRINTF_FORMAT(2, 3)
> > +xlate_report_error(const struct xlate_ctx *ctx, const char *format, ...)
>
> The next two functions in the source file have comments pointing out
> that they're similar to xlate_report(), but xlate_report() doesn't
> have a comment describing it. It might be nice to do that.
I added better comments everywhere.
> The difference in behavior between xlate_report_actions() and
> xlate_report_action_set() seem to be more than just that one has to do
> with actions and the other with action sets. It might be nice to
> document the differences.
Including here.
> > + ctx->xin->trace = old_trace;
> > if (independent_mirrors) {
> > ctx->mirrors = old_mirrors;
> > }
>
> There are a few of these "old_trace" logic blocks, and I think the
> memory management and linked list processing may not be handled
> properly.
This works out OK in practice. Memory management is not a problem, once
I added some; it's just a tree, you free it from root down.
> > @@ -5603,12 +5823,9 @@ xlate_actions(struct xlate_in *xin, struct xlate_out *xout)
> > * was done before they were frozen and should not be redone. */
> > } else if (in_port && in_port->xbundle
> > && xbundle_mirror_out(xbridge, in_port->xbundle)) {
> > - if (ctx.xin->packet != NULL) {
> > - static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 5);
> > - VLOG_WARN_RL(&rl, "bridge %s: dropping packet received on port "
> > - "%s, which is reserved exclusively for mirroring",
> > - ctx.xbridge->name, in_port->xbundle->name);
> > - }
> > + xlate_report_error(&ctx, "dropping packet received on port "
> > + "%s, which is reserved exclusively for mirroring",
> > + in_port->xbundle->name);
>
> This used to only log when "ctx.xin->packet" was not null. Was this
> intentionally changed?
The idea here was that we should only log when a packet is being
translated, not when we're revalidating. This is a good idea in
general, and I forgot about it, so now I've modified
xlate_report_error() and xlate_report_debug() so that they only log if
ctx->xin->packet != NULL.
> > diff --git a/ofproto/ofproto-dpif-xlate.h b/ofproto/ofproto-dpif-xlate.h
> > index 51c05ac..fa2b130 100644
> > --- a/ofproto/ofproto-dpif-xlate.h
> > +++ b/ofproto/ofproto-dpif-xlate.h
> > @@ -83,27 +83,10 @@ struct xlate_in {
> > * timeouts.) */
> > uint16_t tcp_flags;
> >
> > - /* If nonnull, flow translation calls this function just before executing a
> > - * resubmit or OFPP_TABLE action. In addition, disables logging of traces
> > - * when the recursion depth is exceeded.
> > - *
> > - * 'rule' is the rule being submitted into. It will be null if the
> > - * resubmit or OFPP_TABLE action didn't find a matching rule.
> > - *
> > - * 'indentation' is the resubmit recursion depth at time of invocation,
> > - * suitable for indenting the output.
> > - *
> > - * This is normally null so the client has to set it manually after
> > - * calling xlate_in_init(). */
> > - void (*resubmit_hook)(struct xlate_in *, struct rule_dpif *rule,
> > - int indentation);
> > -
> > - /* If nonnull, flow translation calls this function to report some
> > - * significant decision, e.g. to explain why OFPP_NORMAL translation
> > - * dropped a packet. 'indentation' is the resubmit recursion depth at time
> > - * of invocation, suitable for indenting the output. */
> > - void (*report_hook)(struct xlate_in *, int indentation,
> > - const char *format, va_list args);
> > + /* If nonnull, this indicates that the translation is being traced. It
> > + * points to the list of oftrace nodes to which the translation should add
> > + * tracing information (with oftrace_node_append()). */
> > + struct ovs_list *trace;
>
> I don't believe there is a function called oftrace_node_append(). Did
> you mean oftrace_report()?
Thanks, fixed.
> Thanks for working on this. The output is much more readable now.
>
> Acked-by: Justin Pettit <jpettit at ovn.org>
Thanks. I folded in the following incremental and applied this to
master.
--8<--------------------------cut here-------------------------->8--
diff --git a/ofproto/ofproto-dpif-trace.c b/ofproto/ofproto-dpif-trace.c
index 017fbb1..b01a131 100644
--- a/ofproto/ofproto-dpif-trace.c
+++ b/ofproto/ofproto-dpif-trace.c
@@ -1,5 +1,5 @@
/*
- * Copyright (c) 2009, 2010, 2011, 2012, 2013, 2014, 2015, 2016 Nicira, Inc.
+ * Copyright (c) 2009, 2010, 2011, 2012, 2013, 2014, 2015, 2016, 2017 Nicira, Inc.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
@@ -27,7 +27,11 @@ static void ofproto_trace(struct ofproto_dpif *, struct flow *,
const struct dp_packet *packet,
const struct ofpact[], size_t ofpacts_len,
struct ds *);
+static void oftrace_node_destroy(struct oftrace_node *);
+/* Creates a new oftrace_node, populates it with the given 'type' and a copy of
+ * 'text', and appends it to list 'super'. The caller retains ownership of
+ * 'text'. */
struct oftrace_node *
oftrace_report(struct ovs_list *super, enum oftrace_node_type type,
const char *text)
@@ -35,8 +39,7 @@ oftrace_report(struct ovs_list *super, enum oftrace_node_type type,
struct oftrace_node *node = xmalloc(sizeof *node);
ovs_list_push_back(super, &node->node);
node->type = type;
- node->name = xstrdup(text);
- node->always_indent = false;
+ node->text = xstrdup(text);
ovs_list_init(&node->subs);
return node;
@@ -62,38 +65,61 @@ oftrace_node_type_is_terminal(enum oftrace_node_type type)
}
static void
+oftrace_node_list_destroy(struct ovs_list *nodes)
+{
+ if (nodes) {
+ struct oftrace_node *node, *next;
+ LIST_FOR_EACH_SAFE (node, next, node, nodes) {
+ ovs_list_remove(&node->node);
+ oftrace_node_destroy(node);
+ }
+ }
+}
+
+static void
+oftrace_node_destroy(struct oftrace_node *node)
+{
+ if (node) {
+ oftrace_node_list_destroy(&node->subs);
+ free(node->text);
+ free(node);
+ }
+}
+
+static void
oftrace_node_print_details(struct ds *output,
- const struct ovs_list *nodes, int level)
+ const struct ovs_list *nodes, int level)
{
const struct oftrace_node *sub;
LIST_FOR_EACH (sub, node, nodes) {
- bool more = sub->node.next != nodes || sub->always_indent || oftrace_node_type_is_terminal(sub->type);
- bool title = sub->type == OFT_BRIDGE;
-
- if (title) {
+ if (sub->type == OFT_BRIDGE) {
ds_put_char(output, '\n');
}
+
+ bool more = (sub->node.next != nodes
+ || oftrace_node_type_is_terminal(sub->type));
+
ds_put_char_multiple(output, ' ', (level + more) * 4);
switch (sub->type) {
case OFT_DETAIL:
- ds_put_format(output, " -> %s\n", sub->name);
+ ds_put_format(output, " -> %s\n", sub->text);
break;
case OFT_WARN:
- ds_put_format(output, " >> %s\n", sub->name);
+ ds_put_format(output, " >> %s\n", sub->text);
break;
case OFT_ERROR:
- ds_put_format(output, " >>>> %s <<<<\n", sub->name);
+ ds_put_format(output, " >>>> %s <<<<\n", sub->text);
break;
case OFT_BRIDGE:
- ds_put_format(output, "%s\n", sub->name);
+ ds_put_format(output, "%s\n", sub->text);
ds_put_char_multiple(output, ' ', (level + more) * 4);
- ds_put_char_multiple(output, '-', strlen(sub->name));
+ ds_put_char_multiple(output, '-', strlen(sub->text));
ds_put_char(output, '\n');
break;
case OFT_TABLE:
case OFT_THAW:
case OFT_ACTION:
- ds_put_format(output, "%s\n", sub->name);
+ ds_put_format(output, "%s\n", sub->text);
break;
}
@@ -463,6 +489,7 @@ ofproto_trace(struct ofproto_dpif *ofproto, struct flow *flow,
xlate_out_uninit(&xout);
ofpbuf_uninit(&odp_actions);
+ oftrace_node_list_destroy(&trace);
}
void
diff --git a/ofproto/ofproto-dpif-trace.h b/ofproto/ofproto-dpif-trace.h
index 04acca7..e3d3b39 100644
--- a/ofproto/ofproto-dpif-trace.h
+++ b/ofproto/ofproto-dpif-trace.h
@@ -1,4 +1,4 @@
-/* Copyright (c) 2016 Nicira, Inc.
+/* Copyright (c) 2016, 2017 Nicira, Inc.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
@@ -15,26 +15,43 @@
#ifndef OFPROTO_DPIF_TRACE_H
#define OFPROTO_DPIF_TRACE_H 1
+/* Tracing
+ * =======
+ *
+ * The Open vSwitch software datapath based switch implementation supports
+ * "tracing". A trace describes what happens to a particular kind of packet as
+ * it passes through the switch, including information on each table, flow, and
+ * action that would apply to the packet. The trace is internally represented
+ * as a tree that reflects control flow; for example, an OpenFlow switch
+ * top-level node (of type OFT_BRIDGE) has a child node for each table visited
+ * by a packet (of type OFT_TABLE), and each table node has a child node for
+ * each action (OFT_ACTION) executed in the table.
+ */
+
#include "openvswitch/compiler.h"
#include "openvswitch/list.h"
+/* Type of a node within a trace. */
enum oftrace_node_type {
+ /* Nodes that may have children (nonterminal nodes). */
OFT_BRIDGE, /* Packet travel through an OpenFlow switch. */
OFT_TABLE, /* Packet travel through a flow table. */
OFT_THAW, /* Thawing a frozen state. */
+
+ /* Nodes that never have children (terminal nodes). */
OFT_ACTION, /* An action. */
OFT_DETAIL, /* Some detail of an action. */
OFT_WARN, /* A worrisome situation. */
OFT_ERROR, /* An erroneous situation, worth logging. */
};
+/* A node within a trace. */
struct oftrace_node {
struct ovs_list node; /* In parent. */
+ struct ovs_list subs; /* List of "struct oftrace_node" children. */
enum oftrace_node_type type;
- const char *name;
- bool always_indent;
- struct ovs_list subs; /* List of "struct oftrace_node" children. */
+ char *text;
};
void ofproto_dpif_trace_init(void);
diff --git a/ofproto/ofproto-dpif-xlate.c b/ofproto/ofproto-dpif-xlate.c
index 7aba744..e02771e 100644
--- a/ofproto/ofproto-dpif-xlate.c
+++ b/ofproto/ofproto-dpif-xlate.c
@@ -548,7 +548,17 @@ static void xlate_xbundle_copy(struct xbridge *, struct xbundle *);
static void xlate_xport_copy(struct xbridge *, struct xbundle *,
struct xport *);
static void xlate_xcfg_free(struct xlate_cfg *);
-
+
+/* Tracing helpers. */
+
+/* If tracing is enabled in 'ctx', creates a new trace node and appends it to
+ * the list of nodes maintained in ctx->xin. The new node has type 'type' and
+ * its text is created from 'format' by treating it as a printf format string.
+ * Returns the list of nodes embedded within the new trace node; ordinarily,
+ * the calleer can ignore this, but it is useful if the caller needs to nest
+ * more trace nodes within the new node.
+ *
+ * If tracing is not enabled, does nothing and returns NULL. */
static struct ovs_list * OVS_PRINTF_FORMAT(3, 4)
xlate_report(const struct xlate_ctx *ctx, enum oftrace_node_type type,
const char *format, ...)
@@ -560,6 +570,7 @@ xlate_report(const struct xlate_ctx *ctx, enum oftrace_node_type type,
char *text = xvasprintf(format, args);
subtrace = &oftrace_report(ctx->xin->trace, type, text)->subs;
va_end(args);
+ free(text);
}
return subtrace;
}
@@ -570,7 +581,8 @@ static void OVS_PRINTF_FORMAT(2, 3)
xlate_report_error(const struct xlate_ctx *ctx, const char *format, ...)
{
static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 5);
- if (!OVS_UNLIKELY(ctx->xin->trace) && VLOG_DROP_WARN(&rl)) {
+ if (!OVS_UNLIKELY(ctx->xin->trace)
+ && (!ctx->xin->packet || VLOG_DROP_WARN(&rl))) {
return;
}
@@ -599,7 +611,8 @@ xlate_report_debug(const struct xlate_ctx *ctx, enum oftrace_node_type type,
const char *format, ...)
{
static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(30, 300);
- if (!OVS_UNLIKELY(ctx->xin->trace) && VLOG_DROP_DBG(&rl)) {
+ if (!OVS_UNLIKELY(ctx->xin->trace)
+ && (!ctx->xin->packet || VLOG_DROP_DBG(&rl))) {
return;
}
@@ -617,22 +630,31 @@ xlate_report_debug(const struct xlate_ctx *ctx, enum oftrace_node_type type,
ds_destroy(&s);
}
-static struct ovs_list *
+/* If tracing is enabled in 'ctx', appends a node of the given 'type' to the
+ * trace, whose text is 'title' followed by a formatted version of the
+ * 'ofpacts_len' OpenFlow actions in 'ofpacts'.
+ *
+ * If tracing is not enabled, does nothing. */
+static void
xlate_report_actions(const struct xlate_ctx *ctx, enum oftrace_node_type type,
const char *title,
const struct ofpact *ofpacts, size_t ofpacts_len)
{
- struct ovs_list *subtrace = NULL;
if (OVS_UNLIKELY(ctx->xin->trace)) {
struct ds s = DS_EMPTY_INITIALIZER;
ds_put_format(&s, "%s: ", title);
ofpacts_format(ofpacts, ofpacts_len, &s);
- subtrace = &oftrace_report(ctx->xin->trace, type, ds_cstr(&s))->subs;
+ oftrace_report(ctx->xin->trace, type, ds_cstr(&s));
ds_destroy(&s);
}
- return subtrace;
}
+/* If tracing is enabled in 'ctx', appends a node of type OFT_DETAIL to the
+ * trace, whose the message is a formatted version of the OpenFlow action set.
+ * 'verb' should be "was" or "is", depending on whether the action set reported
+ * is the new action set or the old one.
+ *
+ * If tracing is not enabled, does nothing. */
static void
xlate_report_action_set(const struct xlate_ctx *ctx, const char *verb)
{
@@ -653,6 +675,14 @@ xlate_report_action_set(const struct xlate_ctx *ctx, const char *verb)
}
}
+
+/* If tracing is enabled in 'ctx', appends a node representing 'rule' (in
+ * OpenFlow table 'table_id') to the trace and makes this node the parent for
+ * future trace nodes. The caller should save ctx->xin->trace before calling
+ * this function, then after tracing all of the activities under the table,
+ * restore its previous value.
+ *
+ * If tracing is not enabled, does nothing. */
static void
xlate_report_table(const struct xlate_ctx *ctx, struct rule_dpif *rule,
uint8_t table_id)
@@ -688,6 +718,10 @@ xlate_report_table(const struct xlate_ctx *ctx, struct rule_dpif *rule,
ds_destroy(&s);
}
+/* If tracing is enabled in 'ctx', adds an OFT_DETAIL trace node to 'ctx'
+ * reporting the value of subfield 'sf'.
+ *
+ * If tracing is not enabled, does nothing. */
static void
xlate_report_subfield(const struct xlate_ctx *ctx,
const struct mf_subfield *sf)
@@ -712,7 +746,7 @@ xlate_report_subfield(const struct xlate_ctx *ctx,
ds_destroy(&s);
}
}
-
+
static void
xlate_xbridge_init(struct xlate_cfg *xcfg, struct xbridge *xbridge)
{
diff --git a/ofproto/ofproto-dpif-xlate.h b/ofproto/ofproto-dpif-xlate.h
index fa2b130..5d00d6d 100644
--- a/ofproto/ofproto-dpif-xlate.h
+++ b/ofproto/ofproto-dpif-xlate.h
@@ -1,4 +1,4 @@
-/* Copyright (c) 2009, 2010, 2011, 2012, 2013, 2014, 2015, 2016 Nicira, Inc.
+/* Copyright (c) 2009, 2010, 2011, 2012, 2013, 2014, 2015, 2016, 2017 Nicira, Inc.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
@@ -83,9 +83,9 @@ struct xlate_in {
* timeouts.) */
uint16_t tcp_flags;
- /* If nonnull, this indicates that the translation is being traced. It
- * points to the list of oftrace nodes to which the translation should add
- * tracing information (with oftrace_node_append()). */
+ /* Set to nonnull to trace the translation. See ofproto-dpif-trace.h for
+ * more information. This points to the list of oftrace nodes to which the
+ * translation should add tracing information (with oftrace_report()). */
struct ovs_list *trace;
/* If nonnull, flow translation credits the specified statistics to each
More information about the dev
mailing list