ofproto-dpif: Make sure one-packet flows have zero duration (again).

commit 6a0a5bbbc (ofproto-dpif: Make sure one-packet flows have zero
duration.) was supposed to fix failures in the "ofproto-dpif - NetFlow
flow expiration" test, but it didn't fix the whole problem.  That commit
eliminated one reason why a one-packet flow might be shown as having an
nonzero duration, but missed another.

The other reason was that the call to dpif_flow_stats_extract() could
obtain a time later than the time that a new facet was created.  (This
wasn't obvious because dpif_flow_stats_extract() obtained the time
internally instead of taking it from the caller.)  This commit fixes that
problem, by using the facet creation there too for the first packet in
a facet.

This problem has suddenly started showing up in a lot of builds.  I think
it's probably because of the recent change that makes x86-64 skip the timer
optimizations, so that the return value of time_msec() changes every 1 ms,
not just every 100 ms.

I've tested this by running the test in question in a loop for several
minutes, without any failures.

Signed-off-by: Ben Pfaff <blp@nicira.com>

diff --git a/ofproto/ofproto-dpif.c b/ofproto/ofproto-dpif.c
index 2fcb025..b83a50f 100644 (file)
--- a/ofproto/ofproto-dpif.c
+++ b/ofproto/ofproto-dpif.c
@@ -368,7 +368,8 @@ struct subfacet {
 
 static struct subfacet *subfacet_create(struct facet *, enum odp_key_fitness,
                                         const struct nlattr *key,
-                                        size_t key_len, ovs_be16 initial_tci);
+                                        size_t key_len, ovs_be16 initial_tci,
+                                        long long int now);
 static struct subfacet *subfacet_find(struct ofproto_dpif *,
                                       const struct nlattr *key, size_t key_len);
 static void subfacet_destroy(struct subfacet *);
@@ -2904,9 +2905,17 @@ handle_flow_miss_without_facet(struct flow_miss *miss,
 }
 
 /* Handles 'miss', which matches 'facet'.  May add any required datapath
- * operations to 'ops', incrementing '*n_ops' for each new op. */
+ * operations to 'ops', incrementing '*n_ops' for each new op.
+ *
+ * All of the packets in 'miss' are considered to have arrived at time 'now'.
+ * This is really important only for new facets: if we just called time_msec()
+ * here, then the new subfacet or its packets could look (occasionally) as
+ * though it was used some time after the facet was used.  That can make a
+ * one-packet flow look like it has a nonzero duration, which looks odd in
+ * e.g. NetFlow statistics. */
 static void
 handle_flow_miss_with_facet(struct flow_miss *miss, struct facet *facet,
+                            long long int now,
                             struct flow_miss_op *ops, size_t *n_ops)
 {
     struct ofproto_dpif *ofproto = ofproto_dpif_cast(facet->rule->up.ofproto);
@@ -2916,7 +2925,7 @@ handle_flow_miss_with_facet(struct flow_miss *miss, struct facet *facet,
 
     subfacet = subfacet_create(facet,
                                miss->key_fitness, miss->key, miss->key_len,
-                               miss->initial_tci);
+                               miss->initial_tci, now);
 
     LIST_FOR_EACH (packet, list_node, &miss->packets) {
         struct flow_miss_op *op = &ops[*n_ops];
@@ -2930,7 +2939,7 @@ handle_flow_miss_with_facet(struct flow_miss *miss, struct facet *facet,
             subfacet_make_actions(subfacet, packet, &odp_actions);
         }
 
-        dpif_flow_stats_extract(&facet->flow, packet, time_msec(), &stats);
+        dpif_flow_stats_extract(&facet->flow, packet, now, &stats);
         subfacet_update_stats(subfacet, &stats);
 
         if (subfacet->actions_len) {
@@ -2984,6 +2993,7 @@ handle_flow_miss(struct ofproto_dpif *ofproto, struct flow_miss *miss,
                  struct flow_miss_op *ops, size_t *n_ops)
 {
     struct facet *facet;
+    long long int now;
     uint32_t hash;
 
     /* The caller must ensure that miss->hmap_node.hash contains
@@ -3000,8 +3010,11 @@ handle_flow_miss(struct ofproto_dpif *ofproto, struct flow_miss *miss,
         }
 
         facet = facet_create(rule, &miss->flow, hash);
+        now = facet->used;
+    } else {
+        now = time_msec();
     }
-    handle_flow_miss_with_facet(miss, facet, ops, n_ops);
+    handle_flow_miss_with_facet(miss, facet, now, ops, n_ops);
 }
 
 /* Like odp_flow_key_to_flow(), this function converts the 'key_len' bytes of
@@ -4248,7 +4261,8 @@ subfacet_find__(struct ofproto_dpif *ofproto,
  * subfacet_make_actions(). */
 static struct subfacet *
 subfacet_create(struct facet *facet, enum odp_key_fitness key_fitness,
-                const struct nlattr *key, size_t key_len, ovs_be16 initial_tci)
+                const struct nlattr *key, size_t key_len,
+                ovs_be16 initial_tci, long long int now)
 {
     struct ofproto_dpif *ofproto = ofproto_dpif_cast(facet->rule->up.ofproto);
     uint32_t key_hash = odp_flow_key_hash(key, key_len);
@@ -4256,14 +4270,6 @@ subfacet_create(struct facet *facet, enum odp_key_fitness key_fitness,
 
     if (list_is_empty(&facet->subfacets)) {
         subfacet = &facet->one_subfacet;
-
-        /* This subfacet should conceptually be created, and have its first
-         * packet pass through, at the same time that its facet was created.
-         * If we called time_msec() here, then the subfacet could look
-         * (occasionally) as though it was used some time after the facet was
-         * used.  That can make a one-packet flow look like it has a nonzero
-         * duration, which looks odd in e.g. NetFlow statistics. */
-        subfacet->used = facet->used;
     } else {
         subfacet = subfacet_find__(ofproto, key, key_len, key_hash,
                                    &facet->flow);
@@ -4278,7 +4284,6 @@ subfacet_create(struct facet *facet, enum odp_key_fitness key_fitness,
         }
 
         subfacet = xmalloc(sizeof *subfacet);
-        subfacet->used = time_msec();
     }
 
     hmap_insert(&ofproto->subfacets, &subfacet->hmap_node, key_hash);
@@ -4292,6 +4297,7 @@ subfacet_create(struct facet *facet, enum odp_key_fitness key_fitness,
         subfacet->key = NULL;
         subfacet->key_len = 0;
     }
+    subfacet->used = now;
     subfacet->dp_packet_count = 0;
     subfacet->dp_byte_count = 0;
     subfacet->actions_len = 0;