From nobody Mon Jun 8 04:19:59 2026 Received: from mail-dl1-f74.google.com (mail-dl1-f74.google.com [74.125.82.74]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id 01E113B1004 for ; Tue, 2 Jun 2026 07:31:58 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=74.125.82.74 ARC-Seal: i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1780385523; cv=none; b=Ql3PjVD26Lo/6Dq+kemLbuz1xcCfGHvsb0TlmT7IcB+4mCYVwkhpIpb9sIseNnkh+AH1BDfbE34Dj/YJ0fJZ4LgVSIU6PCya6j6ylJutGs41uGt5xxggbcIO0IhnuUtDcOvyGIEpEYTcq/raUvw/ybFVHGnSDckfxKIX25rbCKc= ARC-Message-Signature: i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1780385523; c=relaxed/simple; bh=f9L/qRrqqD++w8Digb/0gNp2AyHhgbAGC5eB2NzZIz8=; h=Date:In-Reply-To:Mime-Version:References:Message-ID:Subject:From: To:Cc:Content-Type; b=L5+xZ30K/6P5Vg7y5OI8cYX3lHMg3oN3AP9T99gAhak8ZFIVm5VNtpiKGm5HqZZUtIs8U3wrq4pIVqLZKk0zq4JWdxiM15hRQU6fNXM6bdbP6vYyiBPEtFH1c8p/k3iUdwe/wiXYFEpfeqJCUDOzG8LO0FEupVvIAcXYAMZ5N8c= ARC-Authentication-Results: i=1; smtp.subspace.kernel.org; dmarc=pass (p=reject dis=none) header.from=google.com; spf=pass smtp.mailfrom=flex--irogers.bounces.google.com; dkim=pass (2048-bit key) header.d=google.com header.i=@google.com header.b=IoGyUfvD; arc=none smtp.client-ip=74.125.82.74 Authentication-Results: smtp.subspace.kernel.org; dmarc=pass (p=reject dis=none) header.from=google.com Authentication-Results: smtp.subspace.kernel.org; spf=pass smtp.mailfrom=flex--irogers.bounces.google.com Authentication-Results: smtp.subspace.kernel.org; dkim=pass (2048-bit key) header.d=google.com header.i=@google.com header.b="IoGyUfvD" Received: by mail-dl1-f74.google.com with SMTP id a92af1059eb24-135f2aa4742so8168519c88.1 for ; Tue, 02 Jun 2026 00:31:58 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=20251104; t=1780385518; x=1780990318; darn=vger.kernel.org; h=cc:to:from:subject:message-id:references:mime-version:in-reply-to :date:from:to:cc:subject:date:message-id:reply-to; bh=BvBpcMEtqM3lWQFo/6krjYvUl6F+36E0CefhPE9ZQq4=; b=IoGyUfvD3FtklpBKSvaDtlyOoFtboHxWuvxpahI95tTaM0SdIMjlFN9IXq8oWFmfHn 0r5swZ4Wb7Kz/AaSfUxpiCnxhEdoMrgJINjoXpwTV/D73fwXbe7c4EVLQ18boCnvwOA6 wS49n8cttFhAT8Aal7AdcA3WNOzUGzb3y1jZz57Rb+FiA4FlsiRGKwwruOPpSumeSJwB aBtrqDKhx3J0JVwSUGoDWEVlFuPSsc8l0vP3c34bRySwGUc6AVQm42Ys1jhj5ujSIEYj CrarLMrsfQzJV9OvtK6UZmTBCKWOngutughBZkg4OtZvyi3F5uCv7Oc2I4CyPPYEVcv/ JZDg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20251104; t=1780385518; x=1780990318; h=cc:to:from:subject:message-id:references:mime-version:in-reply-to :date:x-gm-message-state:from:to:cc:subject:date:message-id:reply-to; bh=BvBpcMEtqM3lWQFo/6krjYvUl6F+36E0CefhPE9ZQq4=; b=Ui3XVsKxjzGRZPgraip0ZHN9+6dLuqyZVPQ/i/ZuQG0yHwujc7jR6h5jy/FZR/mk+b ksb82GSu8a8ibobcxIb/F+/Gh8cSZm7SlSvhSgCNf9Yrs/bA8sZjVd529s4bP7SKYH2b cZRqckS9rfkZ8FRb7MkVXu7Z4EqI7txF+fnVxtKiCRDPBJsx4mbmniXLgUC4PM+dkTwx cd1SW9AUlHxKXlPTXURjPFmtY95OXs1HaDVWeIIvGbRMRHGAwBFi5LAVYdedygDcIk9/ Us7K9wd6etwu2D4nzam2H7ScXfD35DqsDji5DB5X94UE1a50m8eadvOItu5GzMycJBUN Udbw== X-Forwarded-Encrypted: i=1; AFNElJ8TChJqj1jHnwQOKvop1oO3upjn8sxyAKNEvVo3PilTCg0DN6XWNpk2z3m3MPEIw4IduO5i2p7hbYp0zRY=@vger.kernel.org X-Gm-Message-State: AOJu0YzcBUDIY2HeTbqoEj4UviS1SjatGqRCuUoaCf/km8IOew3GTR+6 Du8sZ2ORNXi0Y112sLpz0t44762DuXgQp4zE4NKAfCh4VDaORoxYq35ml+XyT6kxo0ExDG0lH8g tRFgzYyDUUw== X-Received: from dlbrh24.prod.google.com ([2002:a05:7022:f318:b0:137:edc5:fe3f]) (user=irogers job=prod-delivery.src-stubby-dispatcher) by 2002:a05:7022:307:b0:136:959a:abe9 with SMTP id a92af1059eb24-137d3f1850amr5708379c88.5.1780385517671; Tue, 02 Jun 2026 00:31:57 -0700 (PDT) Date: Tue, 2 Jun 2026 00:31:24 -0700 In-Reply-To: <20260602073132.2653307-1-irogers@google.com> Precedence: bulk X-Mailing-List: linux-kernel@vger.kernel.org List-Id: List-Subscribe: List-Unsubscribe: Mime-Version: 1.0 References: <20260601061401.1541457-1-irogers@google.com> <20260602073132.2653307-1-irogers@google.com> X-Mailer: git-send-email 2.54.0.929.g9b7fa37559-goog Message-ID: <20260602073132.2653307-10-irogers@google.com> Subject: [PATCH v7] perf test: Show snippet failure output for verbose=1 From: Ian Rogers To: irogers@google.com, acme@kernel.org, namhyung@kernel.org Cc: adrian.hunter@intel.com, alexander.shishkin@linux.intel.com, james.clark@linaro.org, jolsa@kernel.org, linux-kernel@vger.kernel.org, linux-perf-users@vger.kernel.org, mingo@redhat.com, peterz@infradead.org Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset="utf-8" Currently, when running tests in verbose mode (-v), if a test case fails, the entire raw standard error buffer is dumped to stderr via fprintf(stderr, "%s", child->err_output.buf). For tests that generate massive amounts of debugging or logging output before dying, this results in multi-page terminal dumps where highly critical diagnostic keywords (error, fail, segv) are easily lost. Implement a smart, bounded snippet string processor to improve failure triaging: 1. Introduce a configurable quota limit static unsigned int failure_snippet_lines =3D 10; accessible via a new command-line option --failure-snippet-lines . 2. Parse the raw error buffer dynamically into lines and run a three-pass extraction algorithm: - Pass 0: Always select the very first line of the log as an initial outline marker. - Pass 1: Scan forward from the top of the log to pick up to N lines that contain case-insensitive failure keywords (error, fail, segv, abort) to isolate the root cause. Automatically pull in the immediate subsequent line as highly-prioritized context. Allow adjacent matching lines to overlap without dropping context by evaluating keywords for all lines (e.g. when "Failed to report" is followed by "Error:"). - Pass 2: If quota remains, scan backward from the absolute tail of the log to capture trailing crash or abort context. 3. Output the selected lines in their original chronological order, inserting a clear ... separator between non-contiguous line jumps. 4. Wrap matched failure keywords dynamically in bold red (PERF_COLOR_RED) to immediately draw the eye to failures. 5. Invoke the smart processor purely when verbose =3D=3D 1 && ret =3D=3D TEST_FAIL in both finish_test and finish_tests_parallel, leaving raw full-output dumping completely untouched when running highly verbose (-vv). Assisted-by: Gemini-CLI:Google Gemini 3 Signed-off-by: Ian Rogers --- tools/perf/tests/builtin-test.c | 203 +++++++++++++++++++++++++++++++- 1 file changed, 200 insertions(+), 3 deletions(-) diff --git a/tools/perf/tests/builtin-test.c b/tools/perf/tests/builtin-tes= t.c index 0b33bc74826c..7480cec6cda6 100644 --- a/tools/perf/tests/builtin-test.c +++ b/tools/perf/tests/builtin-test.c @@ -48,6 +48,8 @@ static bool dont_fork; static bool sequential; /* Number of times each test is run. */ static unsigned int runs_per_test =3D 1; +/* Number of lines to include in failure snippet. */ +static unsigned int failure_snippet_lines =3D 10; const char *dso_to_test; const char *test_objdump_path =3D "objdump"; =20 @@ -344,7 +346,7 @@ static int run_test_child(struct child_process *process) for (size_t i =3D 0; i < ARRAY_SIZE(signals); i++) signal(signals[i], child_test_sig_handler); =20 - pr_debug("--- start ---\n"); + pr_debug("---- start ----\n"); pr_debug("test child forked, pid %d\n", getpid()); err =3D test_function(child->test, child->test_case_num)(child->test, chi= ld->test_case_num); pr_debug("---- end(%d) ----\n", err); @@ -400,6 +402,195 @@ static int print_test_result(struct test_suite *t, in= t curr_suite, int curr_test return 0; } =20 +static const char * const fail_keywords[] =3D { + "error", "fail", "segv", "abort", + "signal", "fatal", "panic", "corrupt", NULL +}; + +static const char *find_next_keyword(const char *str, size_t max_len, size= _t *kw_len) +{ + const char *best =3D NULL; + size_t best_len =3D 0; + int k; + + for (k =3D 0; fail_keywords[k]; k++) { + const char *s =3D str; + size_t len =3D strlen(fail_keywords[k]); + + while ((size_t)(s - str) + len <=3D max_len) { + size_t i; + + if (best && s >=3D best) + break; + + for (i =3D 0; i < len; i++) { + if (tolower(s[i]) !=3D fail_keywords[k][i]) + break; + } + if (i =3D=3D len) { + if (!best || s < best) { + best =3D s; + best_len =3D len; + } + break; + } + s++; + } + } + if (best) { + *kw_len =3D best_len; + return best; + } + return NULL; +} + +static void print_line_highlighted(FILE *fp, const char *line, size_t len) +{ + const char *s =3D line; + + while (len > 0) { + size_t kw_len =3D 0; + const char *match =3D find_next_keyword(s, len, &kw_len); + + if (!match) { + fwrite(s, 1, len, fp); + break; + } + if (match > s) + fwrite(s, 1, match - s, fp); + if (perf_use_color_default) + fprintf(fp, "%s", PERF_COLOR_RED); + fwrite(match, 1, kw_len, fp); + if (perf_use_color_default) + fprintf(fp, "%s", PERF_COLOR_RESET); + + len -=3D (match + kw_len) - s; + s =3D match + kw_len; + } +} + + +static void print_test_failure_snippet(FILE *fp, const char *buf) +{ + size_t num_lines =3D 0; + size_t max_lines =3D 128; + const char **lines =3D calloc(max_lines, sizeof(const char *)); + size_t *line_lens =3D calloc(max_lines, sizeof(size_t)); + const char *s =3D buf; + size_t i; + unsigned int picked_count =3D 0; + bool *pick; + int last_printed =3D -1; + + if (!lines || !line_lens) { + free(lines); free(line_lens); + fprintf(fp, "%s", buf); + return; + } + + while (*s) { + const char *eol =3D strchr(s, '\n'); + size_t len; + + if (eol) + len =3D eol - s + 1; + else + len =3D strlen(s); + + if (num_lines =3D=3D max_lines) { + const char **new_lines; + size_t *new_lens; + + max_lines *=3D 2; + new_lines =3D realloc(lines, max_lines * sizeof(const char *)); + if (!new_lines) { + free(lines); free(line_lens); + fprintf(fp, "%s", buf); + return; + } + lines =3D new_lines; + + new_lens =3D realloc(line_lens, max_lines * sizeof(size_t)); + if (!new_lens) { + free(lines); free(line_lens); + fprintf(fp, "%s", buf); + return; + } + line_lens =3D new_lens; + } + lines[num_lines] =3D s; + line_lens[num_lines] =3D len; + num_lines++; + s +=3D len; + } + + if (num_lines <=3D failure_snippet_lines) { + for (i =3D 0; i < num_lines; i++) + print_line_highlighted(fp, lines[i], line_lens[i]); + free(lines); free(line_lens); + return; + } + + pick =3D calloc(num_lines, sizeof(bool)); + if (!pick) { + for (i =3D 0; i < num_lines; i++) + print_line_highlighted(fp, lines[i], line_lens[i]); + free(lines); free(line_lens); + return; + } + + /* Pass 0: Always pick the very first line */ + if (num_lines > 0 && picked_count < failure_snippet_lines) { + pick[0] =3D true; + picked_count++; + } + + /* Pass 1: Pick lines with failure keywords from start (Highest Priority)= */ + for (i =3D 0; i < num_lines && picked_count < failure_snippet_lines; i++)= { + size_t dummy; + + if (find_next_keyword(lines[i], line_lens[i], &dummy)) { + if (!pick[i]) { + pick[i] =3D true; + picked_count++; + } + /* Prioritize getting the immediate next line for context */ + if (i + 1 < num_lines && !pick[i + 1] && + picked_count < failure_snippet_lines) { + pick[i + 1] =3D true; + picked_count++; + } + } + } + + /* Pass 2: Fill remaining quota from the end backwards */ + i =3D num_lines; + while (i > 0 && picked_count < failure_snippet_lines) { + i--; + if (!pick[i]) { + pick[i] =3D true; + picked_count++; + } + } + + for (i =3D 0; i < num_lines; i++) { + if (!pick[i]) + continue; + if (last_printed !=3D -1 && (int)i > last_printed + 1) { + if (perf_use_color_default) + fprintf(fp, "%s...%s\n", PERF_COLOR_BLUE, PERF_COLOR_RESET); + else + fprintf(fp, "...\n"); + } + print_line_highlighted(fp, lines[i], line_lens[i]); + last_printed =3D i; + } + + free(pick); + free(lines); + free(line_lens); +} + static void finish_test(struct child_test **child_tests, int running_test,= int child_test_num, int width) { @@ -518,8 +709,10 @@ static void finish_test(struct child_test **child_test= s, int running_test, int c strbuf_release(&err_output); err_output =3D merged; } - if (verbose > 1 || (verbose =3D=3D 1 && ret =3D=3D TEST_FAIL)) + if (verbose > 1) fprintf(stderr, "%s", err_output.buf); + else if (verbose =3D=3D 1 && ret =3D=3D TEST_FAIL) + print_test_failure_snippet(stderr, err_output.buf); =20 strbuf_release(&err_output); strbuf_release(&child_test->err_output); @@ -723,8 +916,10 @@ static int finish_tests_parallel(struct child_test **c= hild_tests, size_t num_tes } } =20 - if (verbose > 1 || (verbose =3D=3D 1 && child->result =3D=3D TEST_FAIL)) + if (verbose > 1) fprintf(stderr, "%s", child->err_output.buf); + else if (verbose =3D=3D 1 && child->result =3D=3D TEST_FAIL) + print_test_failure_snippet(stderr, child->err_output.buf); =20 print_test_result(child->test, child->suite_num, child->test_case_num, child->result, width, 0); @@ -1060,6 +1255,8 @@ int cmd_test(int argc, const char **argv) OPT_STRING(0, "dso", &dso_to_test, "dso", "dso to test"), OPT_STRING(0, "objdump", &test_objdump_path, "path", "objdump binary to use for disassembly and annotations"), + OPT_UINTEGER(0, "failure-snippet-lines", &failure_snippet_lines, + "Number of lines to include in failure snippet, default 10"), OPT_END() }; const char * const test_subcommands[] =3D { "list", NULL }; --=20 2.54.0.929.g9b7fa37559-goog