diff mbox

[ovs-dev,RFC,v2,5/5] ofproto-dpif-upcall: Add instant revalidation.

Message ID 20160831014735.54058-5-diproiettod@vmware.com
State Deferred
Headers show

Commit Message

Daniele Di Proietto Aug. 31, 2016, 1:47 a.m. UTC 
Sometimes the ofproto layer creates a flow which is not liked by the
revalidation for various reasons.  This behavior, while not critical
might impact the performance.  This commit adds a facility to detect
this issue early and log a warning.

The detection is done by revalidating a flow as soon as it is installed.
Since this extra revalidation might be expensive it is disabled by
default.  It can be enabled using the undocumented unixctl:

`ovs-appctl upcall/instant-revalidation sample_rate`

where 'sample_rate' is a number between 0 and 100, meaning the
percentage of newly installed flows that are instantly revalidated.

We explicitly enable the feature in the unit and system tests (except
for three MPLS unit tests, which expose a problem that hasn't been fixed
yet);

Signed-off-by: Daniele Di Proietto <diproiettod@vmware.com>
---
While I've been using this to detect some bugs in the testsuite and in a
real deployment, I still consider this an RFC.
---
 ofproto/ofproto-dpif-upcall.c | 171 ++++++++++++++++++++++++++++++++++++++----
 tests/ofproto-dpif.at         |  15 ++++
 tests/ofproto-macros.at       |   2 +
 3 files changed, 174 insertions(+), 14 deletions(-)

Comments

Joe Stringer Sept. 21, 2016, 1:54 a.m. UTC | #1 
On 30 August 2016 at 18:47, Daniele Di Proietto <diproiettod@vmware.com> wrote:
> Sometimes the ofproto layer creates a flow which is not liked by the
> revalidation for various reasons.  This behavior, while not critical
> might impact the performance.  This commit adds a facility to detect
> this issue early and log a warning.
>
> The detection is done by revalidating a flow as soon as it is installed.
> Since this extra revalidation might be expensive it is disabled by
> default.  It can be enabled using the undocumented unixctl:
>
> `ovs-appctl upcall/instant-revalidation sample_rate`
>
> where 'sample_rate' is a number between 0 and 100, meaning the
> percentage of newly installed flows that are instantly revalidated.
>
> We explicitly enable the feature in the unit and system tests (except
> for three MPLS unit tests, which expose a problem that hasn't been fixed
> yet);
>
> Signed-off-by: Daniele Di Proietto <diproiettod@vmware.com>

This is great idea, and it's clearly showing itself to be useful for
finding real bugs.

I think that for the kernel datapath codepath, there's still cases
where the ukey exists in the upcall but wasn't installed -
(upcall->ukey && !upcall->ukey_persists). Is it intended to also run
in this case?

revalidate_ukey() is already kinda hard to track, and I feel like
adding an extra "instant_revalidation" bool complicates it further. I
took a stab at trying to refactor this code, which I hoped would allow
you to simplify your logic by just using the logic for translating a
ukey into a translated flow. I think the resulting revalidate_ukey__()
is pretty close to what you want here, but I would appreciate any
feedback on that:

http://openvswitch.org/pipermail/dev/2016-September/079778.html
diff mbox

Patch

diff --git a/ofproto/ofproto-dpif-upcall.c b/ofproto/ofproto-dpif-upcall.c
index e447308..264e2af 100644
--- a/ofproto/ofproto-dpif-upcall.c
+++ b/ofproto/ofproto-dpif-upcall.c
@@ -310,6 +310,9 @@  static void revalidate(struct revalidator *);
 static void revalidator_pause(struct revalidator *);
 static void revalidator_sweep(struct revalidator *);
 static void revalidator_purge(struct revalidator *);
+static void instant_revalidate_upcall(struct udpif *udpif,
+                                      struct upcall *upcall,
+                                      ovs_version_t old_version);
 static void upcall_unixctl_show(struct unixctl_conn *conn, int argc,
                                 const char *argv[], void *aux);
 static void upcall_unixctl_disable_megaflows(struct unixctl_conn *, int argc,
@@ -326,6 +329,9 @@  static void upcall_unixctl_dump_wait(struct unixctl_conn *conn, int argc,
                                      const char *argv[], void *aux);
 static void upcall_unixctl_purge(struct unixctl_conn *conn, int argc,
                                  const char *argv[], void *aux);
+static void upcall_unixctl_instant_revalidation(struct unixctl_conn *conn,
+                                                int argc, const char *argv[],
+                                                void *aux);
 
 static struct udpif_key *ukey_create_from_upcall(struct upcall *,
                                                  struct flow_wildcards *);
@@ -359,6 +365,7 @@  static dp_purge_callback dp_purge_cb;
 
 static atomic_bool enable_megaflows = ATOMIC_VAR_INIT(true);
 static atomic_bool enable_ufid = ATOMIC_VAR_INIT(true);
+static atomic_int instant_revalidation_rate = ATOMIC_VAR_INIT(0);
 
 void
 udpif_init(void)
@@ -381,6 +388,9 @@  udpif_init(void)
                                  upcall_unixctl_dump_wait, NULL);
         unixctl_command_register("revalidator/purge", "", 0, 0,
                                  upcall_unixctl_purge, NULL);
+        unixctl_command_register("upcall/instant-revalidation",
+                                 "sample_rate", 1, 1,
+                                 upcall_unixctl_instant_revalidation, NULL);
         ovsthread_once_done(&once);
     }
 }
@@ -728,6 +738,8 @@  udpif_upcall_handler(void *arg)
     return NULL;
 }
 
+static bool should_install_flow(struct udpif *udpif, struct upcall *upcall);
+
 static size_t
 recv_upcalls(struct handler *handler)
 {
@@ -745,6 +757,7 @@  recv_upcalls(struct handler *handler)
         struct dpif_upcall *dupcall = &dupcalls[n_upcalls];
         struct upcall *upcall = &upcalls[n_upcalls];
         struct flow *flow = &flows[n_upcalls];
+        ovs_version_t old_version;
         unsigned int mru;
         int error;
 
@@ -794,12 +807,15 @@  recv_upcalls(struct handler *handler)
         pkt_metadata_from_flow(&dupcall->packet.md, flow);
         flow_extract(&dupcall->packet, flow);
 
+        old_version = ofproto_dpif_get_tables_version(upcall->ofproto);
         error = process_upcall(udpif, upcall,
                                &upcall->odp_actions, &upcall->wc);
         if (error) {
             goto cleanup;
         }
 
+        instant_revalidate_upcall(udpif, upcall, old_version);
+
         n_upcalls++;
         continue;
 
@@ -1172,6 +1188,8 @@  upcall_cb(const struct dp_packet *packet, const struct flow *flow, ovs_u128 *ufi
     bool megaflow;
     int error;
 
+    ovs_version_t old_version;
+
     atomic_read_relaxed(&enable_megaflows, &megaflow);
 
     error = upcall_receive(&upcall, udpif->backer, packet, type, userdata,
@@ -1180,6 +1198,8 @@  upcall_cb(const struct dp_packet *packet, const struct flow *flow, ovs_u128 *ufi
         return error;
     }
 
+    old_version = ofproto_dpif_get_tables_version(upcall.ofproto);
+
     error = process_upcall(udpif, &upcall, actions, wc);
     if (error) {
         goto out;
@@ -1202,7 +1222,11 @@  upcall_cb(const struct dp_packet *packet, const struct flow *flow, ovs_u128 *ufi
     if (upcall.ukey && !ukey_install(udpif, upcall.ukey)) {
         VLOG_WARN_RL(&rl, "upcall_cb failure: ukey installation fails");
         error = ENOSPC;
+        goto out;
     }
+
+    instant_revalidate_upcall(udpif, &upcall, old_version);
+
 out:
     if (!error) {
         upcall.ukey_persists = true;
@@ -1778,10 +1802,11 @@  should_revalidate(const struct udpif *udpif, uint64_t packets,
  * and ensuring any references are eventually freed.
  */
 static enum reval_result
-revalidate_ukey(struct udpif *udpif, struct udpif_key *ukey,
-                const struct dpif_flow_stats *stats,
-                struct ofpbuf *odp_actions, uint64_t reval_seq,
-                struct recirc_refs *recircs)
+revalidate_ukey__(struct udpif *udpif, struct udpif_key *ukey,
+                  const struct dpif_flow_stats *stats,
+                  struct ofpbuf *odp_actions, uint64_t reval_seq,
+                  struct recirc_refs *recircs, bool instant_revalidation,
+                  struct ds *log)
     OVS_REQUIRES(ukey->mutex)
 {
     struct xlate_out xout, *xoutp;
@@ -1802,7 +1827,7 @@  revalidate_ukey(struct udpif *udpif, struct udpif_key *ukey,
     netflow = NULL;
 
     ofpbuf_clear(odp_actions);
-    need_revalidate = (ukey->reval_seq != reval_seq);
+    need_revalidate = instant_revalidation || (ukey->reval_seq != reval_seq);
     last_used = ukey->stats.used;
     push.used = stats->used;
     push.tcp_flags = stats->tcp_flags;
@@ -1815,17 +1840,22 @@  revalidate_ukey(struct udpif *udpif, struct udpif_key *ukey,
 
     if (need_revalidate && last_used
         && !should_revalidate(udpif, push.n_packets, last_used)) {
+        if (log) {
+            ds_put_cstr(log, "Revalidation too slow, evicting");
+        }
         goto exit;
     }
 
     /* We will push the stats, so update the ukey stats cache. */
-    ukey->stats = *stats;
+    if (!instant_revalidation) {
+        ukey->stats = *stats;
+    }
     if (!push.n_packets && !need_revalidate) {
         result = UKEY_KEEP;
         goto exit;
     }
 
-    if (ukey->xcache && !need_revalidate) {
+    if (!instant_revalidation && ukey->xcache && !need_revalidate) {
         xlate_push_stats(ukey->xcache, &push);
         result = UKEY_KEEP;
         goto exit;
@@ -1833,25 +1863,32 @@  revalidate_ukey(struct udpif *udpif, struct udpif_key *ukey,
 
     if (odp_flow_key_to_flow(ukey->key, ukey->key_len, &flow)
         == ODP_FIT_ERROR) {
+        if (log) {
+            ds_put_cstr(log, "ODP key fit error. Key: ");
+            odp_flow_key_format(ukey->key, ukey->key_len, log);
+        }
         goto exit;
     }
 
     error = xlate_lookup(udpif->backer, &flow, &ofproto, NULL, NULL, &netflow,
                          &ofp_in_port);
     if (error) {
+        if (log) {
+            ds_put_cstr(log, "Lookup error");
+        }
         goto exit;
     }
 
     if (need_revalidate) {
         xlate_cache_clear(ukey->xcache);
     }
-    if (!ukey->xcache) {
+    if (!instant_revalidation && !ukey->xcache) {
         ukey->xcache = xlate_cache_new();
     }
 
     xlate_in_init(&xin, ofproto, &flow, ofp_in_port, NULL, push.tcp_flags,
                   NULL, need_revalidate ? &wc : NULL, odp_actions);
-    if (push.n_packets) {
+    if (!instant_revalidation && push.n_packets) {
         xin.resubmit_stats = &push;
         xin.may_learn = true;
     }
@@ -1873,6 +1910,12 @@  revalidate_ukey(struct udpif *udpif, struct udpif_key *ukey,
     if (odp_flow_key_to_mask(ukey->mask, ukey->mask_len, ukey->key,
                              ukey->key_len, &dp_mask, &flow)
         == ODP_FIT_ERROR) {
+        if (log) {
+            ds_put_cstr(log, "ODP mask fit error. Flow: ");
+            odp_flow_format(ukey->key, ukey->key_len,
+                            ukey->mask, ukey->mask_len,
+                            NULL, log, true);
+        }
         goto exit;
     }
 
@@ -1882,32 +1925,111 @@  revalidate_ukey(struct udpif *udpif, struct udpif_key *ukey,
      * down.  Note that we do not know if the datapath has ignored any of the
      * wildcarded bits, so we may be overtly conservative here. */
     if (flow_wildcards_has_extra(&dp_mask, &wc)) {
+        if (log) {
+            struct match match;
+            ds_put_cstr(log, "Datapath mask is too generic:\n");
+
+            ds_put_cstr(log, "Flow with datapath mask: ");
+            match_init(&match, &flow, &dp_mask);
+            match_format(&match, log, OFP_DEFAULT_PRIORITY);
+
+            ds_put_cstr(log, "\nFlow with translation mask: ");
+            match_init(&match, &flow, &wc);
+            match_format(&match, log, OFP_DEFAULT_PRIORITY);
+        }
         goto exit;
     }
+    const struct ofpbuf *old_actions = ovsrcu_get(struct ofpbuf *,
+                                                  &ukey->actions);
 
-    if (!ofpbuf_equal(odp_actions,
-                      ovsrcu_get(struct ofpbuf *, &ukey->actions))) {
+    if (!ofpbuf_equal(odp_actions, old_actions)) {
         /* The datapath mask was OK, but the actions seem to have changed.
          * Let's modify it in place. */
         result = UKEY_MODIFY;
         /* Transfer recirc action ID references to the caller. */
-        recirc_refs_swap(recircs, &xoutp->recircs);
+        if (!instant_revalidation) {
+            recirc_refs_swap(recircs, &xoutp->recircs);
+        }
+        if (log) {
+            ds_put_cstr(log, "Modifying actions.\nNew: ");
+            format_odp_actions(log, odp_actions->data, odp_actions->size);
+            ds_put_cstr(log, "\nOld: ");
+            format_odp_actions(log, old_actions->data, old_actions->size);
+        }
         goto exit;
     }
 
     result = UKEY_KEEP;
 
 exit:
-    if (result != UKEY_DELETE) {
+    if (result != UKEY_DELETE && !instant_revalidation) {
         ukey->reval_seq = reval_seq;
     }
-    if (netflow && result == UKEY_DELETE) {
+    if (netflow && result == UKEY_DELETE && !instant_revalidation) {
         netflow_flow_clear(netflow, &flow);
     }
     xlate_out_uninit(xoutp);
     return result;
 }
 
+static enum reval_result
+revalidate_ukey(struct udpif *udpif, struct udpif_key *ukey,
+                const struct dpif_flow_stats *stats,
+                struct ofpbuf *odp_actions, uint64_t reval_seq,
+                struct recirc_refs *recircs)
+    OVS_REQUIRES(ukey->mutex)
+{
+    return revalidate_ukey__(udpif, ukey, stats, odp_actions, reval_seq,
+                             recircs, false, NULL);
+}
+
+/* Sometimes while translating an upcall('upcall'), due to subtle bugs in the
+ * xlate module or in odp conversion, we generate a ukey that would be deleted
+ * immediately by next revalidation.  This function can detect that by
+ * revalidating the ukey as soon as it's created and logging a warning message
+ * if revalidation fails.  It is useful only for debugging purposes.
+ *
+ * 'old_version' must be the version number of the ofproto tables before the
+ * upcall was processed.  If the version number changed in the meantime, the
+ * ukey can be legitimately deleted, so no check can be performed.
+ */
+static void instant_revalidate_upcall(struct udpif *udpif,
+                                      struct upcall *upcall,
+                                      ovs_version_t old_version)
+{
+    int sample = random_uint32() % 100;
+    int rate;
+
+    atomic_read_relaxed(&instant_revalidation_rate, &rate);
+
+    if (sample >= rate) {
+        return;
+    }
+
+    if (upcall->ukey && should_install_flow(udpif, upcall)
+        && old_version == ofproto_dpif_get_tables_version(upcall->ofproto)) {
+        struct dpif_flow_stats stats;
+        struct ofpbuf actions;
+        enum reval_result res;
+        struct ds log = DS_EMPTY_INITIALIZER;
+
+        ofpbuf_init(&actions, 16);
+
+        ovs_mutex_lock(&upcall->ukey->mutex);
+
+        stats = upcall->ukey->stats;
+        res = revalidate_ukey__(udpif, upcall->ukey, &stats, &actions, 0,
+                                &upcall->ukey->recircs, true, &log);
+
+        ovs_mutex_unlock(&upcall->ukey->mutex);
+        if (res != UKEY_KEEP) {
+            VLOG_WARN("Instant revalidation failed\n%s", ds_cstr(&log));
+        }
+        ds_destroy(&log);
+        ofpbuf_uninit(&actions);
+    }
+}
+
 static void
 delete_op_init__(struct udpif *udpif, struct ukey_op *op,
                  const struct dpif_flow *flow)
@@ -2497,3 +2619,24 @@  upcall_unixctl_purge(struct unixctl_conn *conn, int argc OVS_UNUSED,
     }
     unixctl_command_reply(conn, "");
 }
+
+static void
+upcall_unixctl_instant_revalidation(struct unixctl_conn *conn,
+                                    int argc OVS_UNUSED, const char *argv[],
+                                    void *aux OVS_UNUSED)
+{
+    int new_rate;
+
+    if (!str_to_int(argv[1], 10, &new_rate)
+        || new_rate < 0
+        || new_rate > 100) {
+        unixctl_command_reply_error(conn, "sample_rate must be between "
+                                          "0 and 100");
+        return;
+    };
+
+    atomic_store_relaxed(&instant_revalidation_rate, new_rate);
+    VLOG_INFO("Instant revalidation rate set to %d", new_rate);
+
+    unixctl_command_reply(conn, "");
+}
diff --git a/tests/ofproto-dpif.at b/tests/ofproto-dpif.at
index e047c1c..62f25ac 100644
--- a/tests/ofproto-dpif.at
+++ b/tests/ofproto-dpif.at
@@ -1581,6 +1581,10 @@  OVS_VSWITCHD_START([dnl
 ])
 on_exit 'kill `cat ovs-ofctl.pid`'
 
+dnl XXX Disable instant revalidation.  MPLS translation often generates matches
+dnl with wrong prerequisites.
+AT_CHECK([ovs-appctl upcall/instant-revalidation 0])
+
 AT_CAPTURE_FILE([ofctl_monitor.log])
 AT_DATA([flows.txt], [dnl
 cookie=0xa dl_src=40:44:44:44:44:42 actions=push_mpls:0x8847,load:10->OXM_OF_MPLS_LABEL[[]],load:3->OXM_OF_MPLS_TC[[]],controller
@@ -3328,6 +3332,10 @@  OVS_VSWITCHD_START([dnl
 ])
 on_exit 'kill `cat ovs-ofctl.pid`'
 
+dnl XXX Disable instant revalidation.  MPLS translation often generates matches
+dnl with wrong prerequisites.
+AT_CHECK([ovs-appctl upcall/instant-revalidation 0])
+
 AT_CAPTURE_FILE([ofctl_monitor.log])
 AT_DATA([flows.txt], [dnl
 cookie=0xa dl_src=40:44:44:44:54:50 actions=push_mpls:0x8847,load:10->OXM_OF_MPLS_LABEL[[]],push_vlan:0x8100,set_vlan_vid:99,set_vlan_pcp:1,controller
@@ -5912,6 +5920,11 @@  AT_CLEANUP
 AT_SETUP([ofproto-dpif - sFlow packet sampling - MPLS])
 AT_XFAIL_IF([test "$IS_WIN32" = "yes"])
 OVS_VSWITCHD_START
+
+dnl XXX Disable instant revalidation.  MPLS translation often generates matches
+dnl with wrong prerequisites.
+AT_CHECK([ovs-appctl upcall/instant-revalidation 0])
+
 AT_CHECK([ovs-appctl vlog/set dpif:dbg dpif_netdev:dbg])
 add_of_ports br0 1 2
 AT_DATA([flows.txt], [dnl
@@ -6837,6 +6850,8 @@  recirc_id(0),in_port(100),eth_type(0x0800),ipv4(src=192.168.0.1,frag=no), action
 
 AT_CHECK([grep -e '|nx_match|WARN|' ovs-vswitchd.log | sed "s/^.*|WARN|//"], [0], [dnl
 Failed to pop from an empty stack. On flow
+dnl The message is printed twice because of instant revalidation
+Failed to pop from an empty stack. On flow
 ])
 
 OVS_VSWITCHD_STOP(["/Failed to pop from an empty stack/d"])
diff --git a/tests/ofproto-macros.at b/tests/ofproto-macros.at
index 79dedf4..7af5370 100644
--- a/tests/ofproto-macros.at
+++ b/tests/ofproto-macros.at
@@ -98,6 +98,7 @@  sim_add () {
 
    # Start ovs-vswitchd
    as $1 start_daemon ovs-vswitchd --enable-dummy=system -vvconn -vofproto_dpif -vunixctl
+   as $1 ovs-appctl upcall/instant-revalidation 100
 }
 
 # "as $1" sets the OVS_*DIR environment variables to point to $ovs_base/$1.
@@ -323,6 +324,7 @@  m4_define([_OVS_VSWITCHD_START],
    AT_CHECK([ovs-vswitchd $1 --detach --no-chdir --pidfile --log-file -vvconn -vofproto_dpif -vunixctl], [0], [], [stderr])
    AT_CAPTURE_FILE([ovs-vswitchd.log])
    on_exit "kill `cat ovs-vswitchd.pid`"
+   AT_CHECK([ovs-appctl upcall/instant-revalidation 100])
    AT_CHECK([[sed < stderr '
 /ovs_numa|INFO|Discovered /d
 /vlog|INFO|opened log file/d