From patchwork Thu Mar 1 00:32:27 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: William Tu X-Patchwork-Id: 879506 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Authentication-Results: ozlabs.org; spf=pass (mailfrom) smtp.mailfrom=openvswitch.org (client-ip=140.211.169.12; helo=mail.linuxfoundation.org; envelope-from=ovs-dev-bounces@openvswitch.org; receiver=) Authentication-Results: ozlabs.org; dmarc=fail (p=none dis=none) header.from=gmail.com Authentication-Results: ozlabs.org; dkim=fail reason="signature verification failed" (2048-bit key; unprotected) header.d=gmail.com header.i=@gmail.com header.b="b2pa7Jlo"; dkim-atps=neutral Received: from mail.linuxfoundation.org (mail.linuxfoundation.org [140.211.169.12]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 3zsD184bBCz9s23 for ; Thu, 1 Mar 2018 11:33:00 +1100 (AEDT) Received: from mail.linux-foundation.org (localhost [127.0.0.1]) by mail.linuxfoundation.org (Postfix) with ESMTP id 5B014EF3; Thu, 1 Mar 2018 00:32:57 +0000 (UTC) X-Original-To: dev@openvswitch.org Delivered-To: ovs-dev@mail.linuxfoundation.org Received: from smtp1.linuxfoundation.org (smtp1.linux-foundation.org [172.17.192.35]) by mail.linuxfoundation.org (Postfix) with ESMTPS id EB8F2E94 for ; Thu, 1 Mar 2018 00:32:55 +0000 (UTC) X-Greylist: whitelisted by SQLgrey-1.7.6 Received: from mail-pl0-f67.google.com (mail-pl0-f67.google.com [209.85.160.67]) by smtp1.linuxfoundation.org (Postfix) with ESMTPS id 64B6F110 for ; Thu, 1 Mar 2018 00:32:55 +0000 (UTC) Received: by mail-pl0-f67.google.com with SMTP id v9-v6so2577685plp.12 for ; Wed, 28 Feb 2018 16:32:55 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:subject:date:message-id; bh=42U5sdY8fhVFLsFIA0EWuc1tze8F/xVAKJiYRGlYDOA=; b=b2pa7Jloh8XKvOe11g8eLCh1ivRWqMfolKXgbpjZPNhuLtU7jYl6b1GwB33isUVfLA QsIoX1im4+yCffvIPi+3+OkoTZKC7Ky2X8Uro+7PVgxdyDmj09Si0dE72fKpqSpgRmth VbSg7fSmcxnQx7D+b0HUuDzNKAZuruCtAxu1hQNzYD+4GpOjBwVsw6h5bXqruBK9BuGn EENOjwnAZ6GjkvAqeA8QzYiXC9FFy20p01saQBC7q5S6eDmyBJwyRHEsZcK6A2czSLsh a9prH+UIaFTBr6u1Y83j9vZXbsSM8NoqB0cc9W+JeHLq/i7km0C/e/DMzbVidFXreuhP uU7g== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:subject:date:message-id; bh=42U5sdY8fhVFLsFIA0EWuc1tze8F/xVAKJiYRGlYDOA=; b=oXZcG8TdVUJKNhz/UIM1HX4nAONj5FqqckIz1w3KnWaA95FJxUI2cnFcKKZOsXW7GT I2p/Mxfciis82gEV0nCU6lS+rOChw0GDYPC2ftQoFCTHRuPPWAu8icLNdeZE1BFHHYv1 TlZTCYb+KcUoi5rOqPT9IHvxB+yrVq8OcfzW+5q7zFpzJWzZU5mE6Ha7tCVNNHzRm3Td 14yhXS8OGogAKg01YWSRo7fA3IKrqk4aGLGKN0NB+wV0ForLy3KVFXMUxNHsYAJRMoiM gs1HpNzn1raohI1AXSaUycp5FyB40gP/vo+II+fK4i7iGgGBEZaHrayFCYg9OFqVytwO HwkQ== X-Gm-Message-State: APf1xPBHVNhChcT1BfeIfnTMVwTMOyegQKCwAQSRG1PE48P8TAZP7D8G BoaNgPLQNgEJx9bvPRcoPbevI7ht X-Google-Smtp-Source: AH8x227SeUpemocqj9GMGXXBohGO7uh9cPnu0ae/K4nB+GV7KcKkdJMxqPXOeU9pnYBtPLFPBCYrCg== X-Received: by 2002:a17:902:8f89:: with SMTP id z9-v6mr20138987plo.370.1519864374733; Wed, 28 Feb 2018 16:32:54 -0800 (PST) Received: from sc9-mailhost2.vmware.com ([66.170.99.2]) by smtp.gmail.com with ESMTPSA id r62sm6753529pfi.52.2018.02.28.16.32.53 for (version=TLS1_2 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Wed, 28 Feb 2018 16:32:54 -0800 (PST) From: William Tu To: dev@openvswitch.org Date: Wed, 28 Feb 2018 16:32:27 -0800 Message-Id: <1519864348-57607-1-git-send-email-u9012063@gmail.com> X-Mailer: git-send-email 2.7.4 X-Spam-Status: No, score=-1.7 required=5.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_ENVFROM_END_DIGIT,FREEMAIL_FROM, RCVD_IN_DNSWL_NONE autolearn=no version=3.3.1 X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on smtp1.linux-foundation.org Subject: [ovs-dev] [PATCHv3 1/2] xlate: auto ofproto trace when recursion too deep X-BeenThere: ovs-dev@openvswitch.org X-Mailman-Version: 2.1.12 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , MIME-Version: 1.0 Sender: ovs-dev-bounces@openvswitch.org Errors-To: ovs-dev-bounces@openvswitch.org Usually ofproto/trace is used to debug the flow translation error. When translation error such as recursion too deep or too many resubmit, the issue might happen momentary; flows causing the recursion expire when users try to debug it. This patch enables the ofproto trace automatically when recursion is too deep or too many resubmit, by invoking the translation again, and log the ofproto trace as warnings. Since the log will be huge, rate limit to one per minute. VMWare-BZ: #2054659 Signed-off-by: William Tu --- ofproto/ofproto-dpif-trace.c | 7 +------ ofproto/ofproto-dpif-trace.h | 6 ++++++ ofproto/ofproto-dpif-upcall.c | 22 +++++++++++++++++++++- tests/ofproto-dpif.at | 25 +++++++++++++++++++++++++ 4 files changed, 53 insertions(+), 7 deletions(-) diff --git a/ofproto/ofproto-dpif-trace.c b/ofproto/ofproto-dpif-trace.c index 4071cc0ffd65..7211eac8e1a5 100644 --- a/ofproto/ofproto-dpif-trace.c +++ b/ofproto/ofproto-dpif-trace.c @@ -23,11 +23,6 @@ #include "ofproto-dpif-xlate.h" #include "unixctl.h" -static void ofproto_trace(struct ofproto_dpif *, const struct flow *, - const struct dp_packet *packet, - const struct ofpact[], size_t ofpacts_len, - struct ovs_list *next_ct_states, - 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 @@ -661,7 +656,7 @@ ofproto_trace__(struct ofproto_dpif *ofproto, const struct flow *flow, * * If 'ofpacts' is nonnull then its 'ofpacts_len' bytes specify the actions to * trace, otherwise the actions are determined by a flow table lookup. */ -static void +void ofproto_trace(struct ofproto_dpif *ofproto, const struct flow *flow, const struct dp_packet *packet, const struct ofpact ofpacts[], size_t ofpacts_len, diff --git a/ofproto/ofproto-dpif-trace.h b/ofproto/ofproto-dpif-trace.h index 5e51771b19b0..ea6cb3fc01ac 100644 --- a/ofproto/ofproto-dpif-trace.h +++ b/ofproto/ofproto-dpif-trace.h @@ -28,6 +28,8 @@ * each action (OFT_ACTION) executed in the table. */ +#include "openvswitch/dynamic-string.h" +#include "ofproto/ofproto-dpif.h" #include "openvswitch/compiler.h" #include "openvswitch/list.h" #include "flow.h" @@ -79,6 +81,10 @@ struct oftrace_next_ct_state { }; void ofproto_dpif_trace_init(void); +void ofproto_trace(struct ofproto_dpif *ofproto, const struct flow *flow, + const struct dp_packet *packet, + const struct ofpact *, size_t ofpacts_len, + struct ovs_list *next_ct_states, struct ds *output); struct oftrace_node *oftrace_report(struct ovs_list *, enum oftrace_node_type, const char *text); diff --git a/ofproto/ofproto-dpif-upcall.c b/ofproto/ofproto-dpif-upcall.c index 526be7760e0a..9bba16873d2d 100644 --- a/ofproto/ofproto-dpif-upcall.c +++ b/ofproto/ofproto-dpif-upcall.c @@ -34,6 +34,7 @@ #include "ofproto-dpif-sflow.h" #include "ofproto-dpif-xlate.h" #include "ofproto-dpif-xlate-cache.h" +#include "ofproto-dpif-trace.h" #include "ovs-rcu.h" #include "packets.h" #include "openvswitch/poll-loop.h" @@ -1124,7 +1125,9 @@ upcall_xlate(struct udpif *udpif, struct upcall *upcall, struct ofpbuf *odp_actions, struct flow_wildcards *wc) { struct dpif_flow_stats stats; + enum xlate_error xerr; struct xlate_in xin; + struct ds output; stats.n_packets = 1; stats.n_bytes = dp_packet_size(upcall->packet); @@ -1159,7 +1162,24 @@ upcall_xlate(struct udpif *udpif, struct upcall *upcall, upcall->dump_seq = seq_read(udpif->dump_seq); upcall->reval_seq = seq_read(udpif->reval_seq); - xlate_actions(&xin, &upcall->xout); + xerr = xlate_actions(&xin, &upcall->xout); + + /* Translate again and log the ofproto trace for + * these two error types. */ + if (xerr == XLATE_RECURSION_TOO_DEEP || + xerr == XLATE_TOO_MANY_RESUBMITS) { + static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 5); + + /* This is a huge log, so be conservative. */ + if (!VLOG_DROP_WARN(&rl)) { + ds_init(&output); + ofproto_trace(upcall->ofproto, upcall->flow, + upcall->packet, NULL, 0, NULL, &output); + VLOG_WARN("%s", ds_cstr(&output)); + ds_destroy(&output); + } + } + if (wc) { /* Convert the input port wildcard from OFP to ODP format. There's no * real way to do this for arbitrary bitmasks since the numbering spaces diff --git a/tests/ofproto-dpif.at b/tests/ofproto-dpif.at index 600afdda8528..fd78c5d9b593 100644 --- a/tests/ofproto-dpif.at +++ b/tests/ofproto-dpif.at @@ -8473,6 +8473,31 @@ AT_CHECK([grep -c 'over max translation depth 64' stdout], OVS_VSWITCHD_STOP(["/resubmit actions recursed/d"]) AT_CLEANUP +dnl Without using ofproto/trace, make sure the +dnl ofproto trace is still logged +AT_SETUP([ofproto-dpif - backward resubmit without trace]) +OVS_VSWITCHD_START +(echo "table=0, actions=resubmit(,66)" + for i in `seq 2 66`; do + j=`expr $i - 1` + echo "table=$i, actions=resubmit(,$j)" + done + echo "table=1, actions=local") > flows +AT_CHECK([ovs-ofctl add-flows br0 flows]) + +AT_CHECK([ovs-appctl netdev-dummy/receive br0 'in_port(1),eth(src=50:54:00:00:00:09,dst=50:54:00:00:00:0a),eth_type(0x1234)'], [0], [stdout]) + +OVS_WAIT_UNTIL([grep 'over max translation' ovs-vswitchd.log]) + +dnl make sure the full ofproto trace dump is present +AT_CHECK([grep -c "^ *resubmit" ovs-vswitchd.log], + [0], [66 +]) + +OVS_VSWITCHD_STOP(["/over max translation depth/d +/ofproto_dpif_upcall/d"]) +AT_CLEANUP + AT_SETUP([ofproto-dpif - exponential resubmit chain]) OVS_VSWITCHD_START add_of_ports br0 1 From patchwork Thu Mar 1 00:32:28 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: William Tu X-Patchwork-Id: 879507 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Authentication-Results: ozlabs.org; spf=pass (mailfrom) smtp.mailfrom=openvswitch.org (client-ip=140.211.169.12; helo=mail.linuxfoundation.org; envelope-from=ovs-dev-bounces@openvswitch.org; receiver=) Authentication-Results: ozlabs.org; dmarc=fail (p=none dis=none) header.from=gmail.com Authentication-Results: ozlabs.org; dkim=fail reason="signature verification failed" (2048-bit key; unprotected) header.d=gmail.com header.i=@gmail.com header.b="AkNjXOWF"; dkim-atps=neutral Received: from mail.linuxfoundation.org (mail.linuxfoundation.org [140.211.169.12]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 3zsD1d4KSfz9s23 for ; Thu, 1 Mar 2018 11:33:25 +1100 (AEDT) Received: from mail.linux-foundation.org (localhost [127.0.0.1]) by mail.linuxfoundation.org (Postfix) with ESMTP id 7F7DAEB5; Thu, 1 Mar 2018 00:32:59 +0000 (UTC) X-Original-To: dev@openvswitch.org Delivered-To: ovs-dev@mail.linuxfoundation.org Received: from smtp1.linuxfoundation.org (smtp1.linux-foundation.org [172.17.192.35]) by mail.linuxfoundation.org (Postfix) with ESMTPS id 03F39EE8 for ; Thu, 1 Mar 2018 00:32:57 +0000 (UTC) X-Greylist: whitelisted by SQLgrey-1.7.6 Received: from mail-pf0-f193.google.com (mail-pf0-f193.google.com [209.85.192.193]) by smtp1.linuxfoundation.org (Postfix) with ESMTPS id A6B01E7 for ; Thu, 1 Mar 2018 00:32:56 +0000 (UTC) Received: by mail-pf0-f193.google.com with SMTP id z10so1713352pfh.13 for ; Wed, 28 Feb 2018 16:32:56 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:subject:date:message-id:in-reply-to:references; bh=uE3XwUz190sRoedVHWrCtelpLf0HIz6axFzaSvC0o1w=; b=AkNjXOWFbdTb3kjiRRf+TaD0XVpxGlC3a7JZhwXUTGiGEoSRn2U4O0Sc7lcZTh40j6 FiCq6BK3FsVYnSSdoRRDm/ljNHtivrhZ6o1HCIzOpr3tDHkN0TbXnIA7aTq7FWTeTyTs bDAr0KB38wrFq/hUbtZLs45pKLG3Z8e27Hkc9h5uVWS32Aj6yXWHNHErkPxs+990xeGD FptH17CJl7YNwNj27DExlcHx2IEtiuQrKMirfbjwr1AthMf+qm5VH22lGhrphAeCh/21 oKBpoKCsdUqfNevgNB+LVffMReSLa1bUBYVLNyzHkR0yYRlzHM5X0oNH5/O4ILdu2oH9 r7Lg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:subject:date:message-id:in-reply-to :references; bh=uE3XwUz190sRoedVHWrCtelpLf0HIz6axFzaSvC0o1w=; b=l5DEA1PNbe0kum9AqHseM7KR72i6+wsWjw4X6C03SVgJQOmLUXltF1ue0xmiIyh9Ue ynB9SuDMBN3hSCDN6WZ6C7yWnUXRiaylN6LSHxnkh3KmvzbY4eJCK5SvMoI6xtEvQZBJ lnBzvC3XsxdaIKX+X74tzaUDXXKWr9eAI4+IHA+waviMl5j47LntD1fvuRohkk3crzrF m3u6sCnm/QFpmjBaKdjb1NEp1ToX+NgLaHt4ZGNNyFRJQ9WSRlaY1flHjxo4hUYO6JsX fyf73x9ax6GKRe9iWzsm07g4GNoHpjcWeZKagyYac+wyScvrgGugQNgvys5j1Hl18l9w /LtA== X-Gm-Message-State: APf1xPCkkdDKdRkpT0v4u8jdrGXh3Iwp1eLcAg83D3bOFGJITlPrG9Ad T9dfZYH1igYVWF2n+fPpsonxP9ti X-Google-Smtp-Source: AH8x226r+DM9/n8MQNcAu0OhrCJ2JsLrNB5hFnnZSwDh5FDLQaHQnJnHMc2XtJVF7iDheXgxDbGVag== X-Received: by 10.98.150.212 with SMTP id s81mr19838205pfk.100.1519864376043; Wed, 28 Feb 2018 16:32:56 -0800 (PST) Received: from sc9-mailhost2.vmware.com ([66.170.99.2]) by smtp.gmail.com with ESMTPSA id r62sm6753529pfi.52.2018.02.28.16.32.54 for (version=TLS1_2 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Wed, 28 Feb 2018 16:32:55 -0800 (PST) From: William Tu To: dev@openvswitch.org Date: Wed, 28 Feb 2018 16:32:28 -0800 Message-Id: <1519864348-57607-2-git-send-email-u9012063@gmail.com> X-Mailer: git-send-email 2.7.4 In-Reply-To: <1519864348-57607-1-git-send-email-u9012063@gmail.com> References: <1519864348-57607-1-git-send-email-u9012063@gmail.com> X-Spam-Status: No, score=-1.7 required=5.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_ENVFROM_END_DIGIT,FREEMAIL_FROM, RCVD_IN_DNSWL_NONE autolearn=no version=3.3.1 X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on smtp1.linux-foundation.org Subject: [ovs-dev] [PATCHv3 2/2] xlate: add backward resubmit trace log. X-BeenThere: ovs-dev@openvswitch.org X-Mailman-Version: 2.1.12 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , MIME-Version: 1.0 Sender: ovs-dev-bounces@openvswitch.org Errors-To: ovs-dev-bounces@openvswitch.org When hitting max translation depth of 64, printing the full ofproto trace is huge and consumes too much log. The patch adds a short trace log, which prints the top 3 table id and its count of the 64 backward resubmits during the translation. VMWare-BZ: #2054659 Signed-off-by: William Tu Signed-off-by: William Tu Signed-off-by: Ben Pfaff --- ofproto/ofproto-dpif-xlate.c | 45 ++++++++++++++++++++++++++++++++++++++++++-- tests/ofproto-dpif.at | 3 +++ 2 files changed, 46 insertions(+), 2 deletions(-) diff --git a/ofproto/ofproto-dpif-xlate.c b/ofproto/ofproto-dpif-xlate.c index cc450a896948..f82fe6bf711f 100644 --- a/ofproto/ofproto-dpif-xlate.c +++ b/ofproto/ofproto-dpif-xlate.c @@ -237,6 +237,7 @@ struct xlate_ctx { */ int depth; /* Current resubmit nesting depth. */ int resubmits; /* Total number of resubmits. */ + uint8_t bw_resubmit[MAX_DEPTH]; /* Track backward resubmit table IDs. */ bool in_group; /* Currently translating ofgroup, if true. */ bool in_action_set; /* Currently translating action_set, if true. */ bool in_packet_out; /* Currently translating a packet_out msg, if @@ -3912,8 +3913,11 @@ xlate_recursively(struct xlate_ctx *ctx, struct rule_dpif *rule, rule_dpif_credit_stats(rule, ctx->xin->resubmit_stats); } - ctx->resubmits++; + if (deepens) { + ctx->bw_resubmit[ctx->depth] = ctx->table_id; + } + ctx->resubmits++; ctx->depth += deepens; ctx->rule = rule; ctx->rule_cookie = rule->up.flow_cookie; @@ -3925,11 +3929,48 @@ xlate_recursively(struct xlate_ctx *ctx, struct rule_dpif *rule, ctx->depth -= deepens; } +static int +compare_uint8(const void *a_, const void *b_) +{ + const uint8_t *a = a_; + const uint8_t *b = b_; + return *a > *b ? -1 : *a < *b; +} + +static struct ds +format_bw_resubmit(uint8_t *bw_resubmit) +{ + int i; + uint8_t oftable[256]; + struct ds output; + + ds_init(&output); + memset(oftable, 0x0, sizeof oftable); + + for (i = 0; i < MAX_DEPTH; i++) { + uint8_t tab_id = bw_resubmit[i]; + oftable[tab_id]++; + } + qsort(oftable, 256, sizeof(uint8_t), compare_uint8); + + /* find the largest */ + ds_put_format(&output, "(%d,%d),", 0, oftable[0]); + ds_put_format(&output, "(%d,%d),", 1, oftable[1]); + ds_put_format(&output, "(%d,%d)", 2, oftable[2]); + return output; +} + static bool xlate_resubmit_resource_check(struct xlate_ctx *ctx) { if (ctx->depth >= MAX_DEPTH) { - xlate_report_error(ctx, "over max translation depth %d", MAX_DEPTH); + struct ds output; + + output = format_bw_resubmit(ctx->bw_resubmit); + xlate_report_error(ctx, "over max translation depth %d, " + "top 3 (table_id,count): [%s]", + MAX_DEPTH, ds_cstr(&output)); + ds_destroy(&output); ctx->error = XLATE_RECURSION_TOO_DEEP; } else if (ctx->resubmits >= MAX_RESUBMITS) { xlate_report_error(ctx, "over %d resubmit actions", MAX_RESUBMITS); diff --git a/tests/ofproto-dpif.at b/tests/ofproto-dpif.at index fd78c5d9b593..3776eca75e99 100644 --- a/tests/ofproto-dpif.at +++ b/tests/ofproto-dpif.at @@ -8494,6 +8494,9 @@ AT_CHECK([grep -c "^ *resubmit" ovs-vswitchd.log], [0], [66 ]) +dnl make sure the short backward table trace is present +AT_CHECK([egrep "\(table_id,count\): \[[\(0,1\),\(1,1\),\(2,1\)\]]" ovs-vswitchd.log], [0], [stdout]) + OVS_VSWITCHD_STOP(["/over max translation depth/d /ofproto_dpif_upcall/d"]) AT_CLEANUP