From patchwork Wed Aug 31 01:47:35 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Daniele Di Proietto X-Patchwork-Id: 664345 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from archives.nicira.com (archives.nicira.com [96.126.127.54]) by ozlabs.org (Postfix) with ESMTP id 3sP7ZT28Wfz9s9c for ; Wed, 31 Aug 2016 11:48:17 +1000 (AEST) Received: from archives.nicira.com (localhost [127.0.0.1]) by archives.nicira.com (Postfix) with ESMTP id 3A8B7108CE; Tue, 30 Aug 2016 18:47:53 -0700 (PDT) X-Original-To: dev@openvswitch.org Delivered-To: dev@openvswitch.org Received: from mx1e4.cudamail.com (mx1.cudamail.com [69.90.118.67]) by archives.nicira.com (Postfix) with ESMTPS id 51A5D108BC for ; Tue, 30 Aug 2016 18:47:51 -0700 (PDT) Received: from bar5.cudamail.com (unknown [192.168.21.12]) by mx1e4.cudamail.com (Postfix) with ESMTPS id D56991E0452 for ; Tue, 30 Aug 2016 19:47:50 -0600 (MDT) X-ASG-Debug-ID: 1472608070-09eadd7e6101990001-byXFYA Received: from mx3-pf3.cudamail.com ([192.168.14.3]) by bar5.cudamail.com with ESMTP id klRDPdZvIftnf8l9 (version=TLSv1 cipher=DHE-RSA-AES256-SHA bits=256 verify=NO) for ; Tue, 30 Aug 2016 19:47:50 -0600 (MDT) X-Barracuda-Envelope-From: diproiettod@vmware.com X-Barracuda-RBL-Trusted-Forwarder: 192.168.14.3 Received: from unknown (HELO EX13-EDG-OU-001.vmware.com) (208.91.0.189) by mx3-pf3.cudamail.com with ESMTPS (AES256-SHA encrypted); 31 Aug 2016 01:47:50 -0000 Received-SPF: error (mx3-pf3.cudamail.com: error in processing during lookup of vmware.com: DNS problem) Received: from sc9-mailhost1.vmware.com (10.113.161.71) by EX13-EDG-OU-001.vmware.com (10.113.208.155) with Microsoft SMTP Server id 15.0.1156.6; Tue, 30 Aug 2016 18:47:25 -0700 Received: from sc9-mailhost2.vmware.com (htb-1n-eng-dhcp84.eng.vmware.com [10.33.74.84]) by sc9-mailhost1.vmware.com (Postfix) with ESMTP id B89AB18781; Tue, 30 Aug 2016 18:47:48 -0700 (PDT) X-CudaMail-Envelope-Sender: diproiettod@vmware.com From: Daniele Di Proietto To: X-CudaMail-Whitelist-To: dev@openvswitch.org X-CudaMail-MID: CM-V3-829062583 X-CudaMail-DTE: 083016 X-CudaMail-Originating-IP: 208.91.0.189 Date: Tue, 30 Aug 2016 18:47:35 -0700 X-ASG-Orig-Subj: [##CM-V3-829062583##][RFC v2 5/5] ofproto-dpif-upcall: Add instant revalidation. Message-ID: <20160831014735.54058-5-diproiettod@vmware.com> X-Mailer: git-send-email 2.9.3 In-Reply-To: <20160831014735.54058-1-diproiettod@vmware.com> References: <20160831014735.54058-1-diproiettod@vmware.com> MIME-Version: 1.0 Received-SPF: None (EX13-EDG-OU-001.vmware.com: diproiettod@vmware.com does not designate permitted sender hosts) X-Barracuda-Connect: UNKNOWN[192.168.14.3] X-Barracuda-Start-Time: 1472608070 X-Barracuda-Encrypted: DHE-RSA-AES256-SHA X-Barracuda-URL: https://web.cudamail.com:443/cgi-mod/mark.cgi X-ASG-Whitelist: Header =?UTF-8?B?eFwtY3VkYW1haWxcLXdoaXRlbGlzdFwtdG8=?= X-Virus-Scanned: by bsmtpd at cudamail.com X-Barracuda-BRTS-Status: 1 Subject: [ovs-dev] [RFC v2 5/5] ofproto-dpif-upcall: Add instant revalidation. X-BeenThere: dev@openvswitch.org X-Mailman-Version: 2.1.16 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: dev-bounces@openvswitch.org Sender: "dev" 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 --- 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(-) 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