Re: [ovs-dev] About a race condition between handle_upcalls and revalidate

Paul Blakey Mon, 20 Mar 2017 09:19:53 -0700


On 19/03/2017 16:28, Paul Blakey wrote:

Hi all,


While using out patches for HW offload we've noticed we get a ovs
assertion at transition ukey, which tries to
transition the ukey state from EVICTED back to OPERATIONAL.
With furthur investigation it seem that this can happen without our HW
offload patches as there might be a race between handle_upcalls and
revalidate.

The procedure is as such:

handle_upcalls receives a new upcall and creates a new ukey, its state
is VISIBLE, it then it installs a flow (FLOW_PUT) to the datapat and
upon success wants to set the ukey state to OPERATIONAL (line 1408). for
that the handler running handle_upcalls wants to reaquirce the ukey
lock, but in the meantime revalidators dump (line 2261) the already
inserted flow and want to delete this flow (line 2328, say because of
openflow db changes, or aging). The revalidator deletes the flow and
moves the ukey from
VISIBLE -> OPERATIONAL (line 2320) -> EVICTING (line 2220) -> EVICTED
(line 2134)

finally handler succesfuly acquires the flow and now set the state to
OPERERTIONAL which will cause the assert in transition_ukey.

Line numbers in question are from ofproto/ofproto-dpif-upcall.c

I can provide a test the could show this happening, basicly adding a
sleep before (writing it now).

Thanks,
Paul Blakey.


New test patch below,
To reproduce run this bash script:
########## START OF SCRIPT ###############################
#setup: veth0 <-> veth1 <-> OVS <->  veth2@ns0 <-> veth3@ns0
#       VM1_IP                                      VM2_IP

VM1_IP=77.77.77.7
VM2_IP=77.77.77.8

echo "deleting bridges (if ovs is running)"
ovs-vsctl list-br | xargs -r -l ovs-vsctl del-br

echo "deleting namespace"
ip netns del ns0 &> /dev/null
ip netns add ns0

echo "setup veth0-3"
ip link del veth0 &> /dev/null
ip link del veth1 &> /dev/null
ip link del veth2 &> /dev/null
ip link del veth3 &> /dev/null
ip link add veth0 type veth peer name veth1
ip link add veth2 type veth peer name veth3

echo "setup remote vm(veth3) $VM2_IP in namespace"
ip link set veth3 netns ns0
ip netns exec ns0 ifconfig veth3 $VM2_IP/24 up

echo "setup local vm(veth0) $VM1_IP"

ifconfig veth0 $VM1_IP/24 up
ifconfig veth1 up
ifconfig veth2 up

echo "restart ovs and delete bridges (if ovs wasn't running)"
systemctl restart openvswitch
sleep 2
ovs-vsctl list-br | xargs -r -l ovs-vsctl del-br

ovs-vsctl set Open_vSwitch . other_config:max-idle=250
ovs-vsctl set Open_vSwitch . other_config:n-handler-threads=1
ovs-vsctl set Open_vSwitch . other_config:n-revalidator-threads=5

echo "setup ovs with veth"
ovs-vsctl add-br brv-1
ovs-vsctl add-port brv-1 veth1
ovs-vsctl add-port brv-1 veth2

echo "pinging remote VM $VM2_IP"
ping $VM2_IP -i 2

##################END OF BASH SCRIPT################

and follow ovs-vswitchd.log
Here is the ovs-vswitchd.log I get:

2017-03-20T16:01:27.864Z|00007|ofproto_dpif_upcall(revalidator36)|INFO|sleeping
2017-03-20T16:01:27.864Z|00013|ofproto_dpif_upcall(revalidator35)|INFO|sleeping



##################END OF LOG ################



From df02c4f769566ce6a8ebb8f228c9f3262c618395 Mon Sep 17 00:00:00 2001
From: Paul Blakey <pa...@mellanox.com>
Date: Sun, 19 Mar 2017 17:00:30 +0200
Subject: [PATCH] test

Change-Id: Iac752eb5fab3ff49da30a35bab3bee12673e1e28
---

ofproto/ofproto-dpif-upcall.c | 55+++++++++++++++++++++++++++++++++----------

 1 file changed, 43 insertions(+), 12 deletions(-)

diff --git a/ofproto/ofproto-dpif-upcall.c b/ofproto/ofproto-dpif-upcall.c
index 660383f..3291219 100644
--- a/ofproto/ofproto-dpif-upcall.c
+++ b/ofproto/ofproto-dpif-upcall.c
@@ -45,6 +45,8 @@
 #define UPCALL_MAX_BATCH 64
 #define REVALIDATE_MAX_BATCH 50

+int global_temp = 0;
+
 VLOG_DEFINE_THIS_MODULE(ofproto_dpif_upcall);

 COVERAGE_DEFINE(dumped_duplicate_flow);

@@ -350,7 +352,7 @@ static void ukey_get_actions(struct udpif_key *,const struct nlattr **actions,

 static bool ukey_install__(struct udpif *, struct udpif_key *ukey)
     OVS_TRY_LOCK(true, ukey->mutex);
 static bool ukey_install(struct udpif *udpif, struct udpif_key *ukey);
-static void transition_ukey(struct udpif_key *ukey, enum ukey_state dst)

+static void transition_ukey(const char *func, int line, structudpif_key *ukey, enum ukey_state dst)

     OVS_REQUIRES(ukey->mutex);
 static struct udpif_key *ukey_lookup(struct udpif *udpif,
                                      const ovs_u128 *ufid,

@@ -1399,15 +1401,30 @@ handle_upcalls(struct udpif *udpif, structupcall *upcalls,

     dpif_operate(udpif->dpif, opsp, n_opsp);
     for (i = 0; i < n_ops; i++) {
         struct udpif_key *ukey = ops[i].ukey;
+        static int count = 0;
+        const int sleep_time = 5;
+        const int sleep_every_n_flows = 20;

         if (ukey) {
+            count++;
+            VLOG_INFO("put count: %d", count);
+            if ((count % sleep_every_n_flows) == 0) {
+                global_temp = 1;
+                for (int z = 0; z < sleep_time; z++) {

+ VLOG_INFO("%s %d sleeping %d/%d sec, ukey state:%d", __func__, __LINE__, z+1, sleep_time, ukey->state);

+                    xsleep(1);
+                }
+            }
+
             ovs_mutex_lock(&ukey->mutex);
             if (ops[i].dop.error) {
-                transition_ukey(ukey, UKEY_EVICTED);
+                transition_ukey(__func__, __LINE__, ukey, UKEY_EVICTED);
             } else {
-                transition_ukey(ukey, UKEY_OPERATIONAL);

+ transition_ukey(__func__, __LINE__, ukey,UKEY_OPERATIONAL);

             }
             ovs_mutex_unlock(&ukey->mutex);
+
+            global_temp = 0;
         }
     }
 }

@@ -1605,8 +1622,8 @@ try_ukey_replace(struct umap *umap, structudpif_key *old_ukey,

             cmap_replace(&umap->cmap, &old_ukey->cmap_node,
                          &new_ukey->cmap_node, new_ukey->hash);
             ovsrcu_postpone(ukey_delete__, old_ukey);
-            transition_ukey(old_ukey, UKEY_DELETED);
-            transition_ukey(new_ukey, UKEY_VISIBLE);
+            transition_ukey(__func__, __LINE__, old_ukey, UKEY_DELETED);
+            transition_ukey(__func__, __LINE__, new_ukey, UKEY_VISIBLE);
             replaced = true;
         }
         ovs_mutex_unlock(&old_ukey->mutex);

@@ -1659,7 +1676,7 @@ ukey_install__(struct udpif *udpif, structudpif_key *new_ukey)

     } else {
         ovs_mutex_lock(&new_ukey->mutex);
         cmap_insert(&umap->cmap, &new_ukey->cmap_node, new_ukey->hash);
-        transition_ukey(new_ukey, UKEY_VISIBLE);
+        transition_ukey(__func__, __LINE__, new_ukey, UKEY_VISIBLE);
         locked = true;
     }
     ovs_mutex_unlock(&umap->mutex);

@@ -1667,10 +1684,18 @@ ukey_install__(struct udpif *udpif, structudpif_key *new_ukey)

     return locked;
 }

+char *state_to_str[] = { "CREATED", "VISIBLE", "OPERATIONAL","EVICTING", "EVICTED", "DELETED" };

+
 static void
-transition_ukey(struct udpif_key *ukey, enum ukey_state dst)

+transition_ukey(const char *func, int line, struct udpif_key *ukey,enum ukey_state dst)

     OVS_REQUIRES(ukey->mutex)
 {
+    struct ds ds2 = DS_EMPTY_INITIALIZER;
+
+    odp_format_ufid(&ukey->ufid, &ds2);

+ VLOG_INFO("%s %d state transition for ukey %s: %s -> %s", func,line, ds_cstr(&ds2), state_to_str[ukey->state], state_to_str[dst]);

+    ds_destroy(&ds2);
+
     ovs_assert(dst >= ukey->state);
     if (ukey->state == dst && dst == UKEY_OPERATIONAL) {
         return;
@@ -1797,7 +1822,7 @@ ukey_delete(struct umap *umap, struct udpif_key *ukey)
     if (ukey->state < UKEY_DELETED) {
         cmap_remove(&umap->cmap, &ukey->cmap_node, ukey->hash);
         ovsrcu_postpone(ukey_delete__, ukey);
-        transition_ukey(ukey, UKEY_DELETED);
+        transition_ukey(__func__, __LINE__, ukey, UKEY_DELETED);
     }
     ovs_mutex_unlock(&ukey->mutex);
 }

@@ -2131,7 +2156,7 @@ push_dp_ops(struct udpif *udpif, struct ukey_op*ops, size_t n_ops)


         if (op->ukey) {
             ovs_mutex_lock(&op->ukey->mutex);
-            transition_ukey(op->ukey, UKEY_EVICTED);
+            transition_ukey(__func__, __LINE__, op->ukey, UKEY_EVICTED);
             push->used = MAX(stats->used, op->ukey->stats.used);

push->tcp_flags = stats->tcp_flags |op->ukey->stats.tcp_flags;push->n_packets = stats->n_packets -op->ukey->stats.n_packets;@@ -2217,7 +2242,7 @@ reval_op_init(struct ukey_op *op, enumreval_result result,

 {
     if (result == UKEY_DELETE) {
         delete_op_init(udpif, op, ukey);
-        transition_ukey(ukey, UKEY_EVICTING);
+        transition_ukey(__func__, __LINE__, ukey, UKEY_EVICTING);
     } else if (result == UKEY_MODIFY) {
         /* Store the new recircs. */
         recirc_refs_swap(&ukey->recircs, recircs);
@@ -2317,7 +2342,7 @@ revalidate(struct revalidator *revalidator)
             }

             /* The flow is now confirmed to be in the datapath. */
-            transition_ukey(ukey, UKEY_OPERATIONAL);
+            transition_ukey(__func__, __LINE__, ukey, UKEY_OPERATIONAL);

             if (!used) {
                 used = ukey->created;

@@ -2417,6 +2442,12 @@ revalidator_sweep__(struct revalidator*revalidator, bool purge)

             ovs_mutex_unlock(&ukey->mutex);

             if (ukey_state == UKEY_EVICTED) {
+
+                while (global_temp) {
+                    VLOG_INFO("sleeping\n");
+                    xsleep(5);
+                }
+

/* The common flow deletion case involves deletion ofthe flow

                  * during the dump phase and ukey deletion here. */
                 ovs_mutex_lock(&umap->mutex);
@@ -2471,7 +2502,7 @@ dp_purge_cb(void *aux, unsigned pmd_id)
         CMAP_FOR_EACH(ukey, cmap_node, &umap->cmap) {
             if (ukey->pmd_id == pmd_id) {
                 delete_op_init(udpif, &ops[n_ops++], ukey);
-                transition_ukey(ukey, UKEY_EVICTING);
+                transition_ukey(__func__, __LINE__, ukey, UKEY_EVICTING);

                 if (n_ops == REVALIDATE_MAX_BATCH) {
                     push_ukey_ops(udpif, umap, ops, n_ops);
--
1.8.4.3




_______________________________________________
dev mailing list
d...@openvswitch.org
https://mail.openvswitch.org/mailman/listinfo/ovs-dev

Re: [ovs-dev] About a race condition between handle_upcalls and revalidate

Reply via email to