All of lore.kernel.org
 help / color / mirror / Atom feed
From: Ian Rogers <irogers@google.com>
To: Peter Zijlstra <peterz@infradead.org>,
	Ingo Molnar <mingo@redhat.com>,
	 Arnaldo Carvalho de Melo <acme@kernel.org>,
	Namhyung Kim <namhyung@kernel.org>,
	 Alexander Shishkin <alexander.shishkin@linux.intel.com>,
	Jiri Olsa <jolsa@kernel.org>,
	 Adrian Hunter <adrian.hunter@intel.com>,
	James Clark <james.clark@linaro.org>,
	 linux-kernel@vger.kernel.org, linux-perf-users@vger.kernel.org
Cc: Ian Rogers <irogers@google.com>
Subject: [PATCH v1 07/14] perf test: Show snippet failure output for verbose=1
Date: Wed, 13 May 2026 16:04:43 -0700	[thread overview]
Message-ID: <20260513230450.529380-8-irogers@google.com> (raw)
In-Reply-To: <20260513230450.529380-1-irogers@google.com>

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 = 10; accessible via a new command-line option
   --failure-snippet-lines <N>.
2. Parse the raw error buffer dynamically into lines and run a three-pass
   extraction algorithm:
   - Pass 0: Prioritize retaining outline marker lines containing dashes
     (----) to beautifully frame the start and end execution boundaries.
   - 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 == 1 && ret == TEST_FAIL
   in both finish_test and finish_tests_parallel, leaving raw full-output
   dumping completely untouched when running highly verbose (-vv).

Example output:
```
---- start ----
...
-- [ FAIL ] -- perf_probe :: test_adding_kernel :: listing added probe :: perf probe -l (output regexp parsing)
-- [ PASS ] -- perf_probe :: test_adding_kernel :: using added probe
...
-- [ FAIL ] -- perf_probe :: test_adding_kernel :: wildcard adding support (command exitcode + output regexp parsing)
Regexp not found: "somenonexistingrandomstuffwhichisalsoprettylongorevenlongertoexceed64"
...
-- [ FAIL ] -- perf_probe :: test_adding_kernel :: non-existing variable (output regexp parsing)
-- [ PASS ] -- perf_probe :: test_adding_kernel :: function with retval :: add
...
-- [ SKIP ] -- perf_probe :: test_basic :: help message :: testcase skipped
...
---- end(-1) ----
143: perftool-testsuite_probe                                        : FAILED!
```

Assisted-by: Gemini-CLI:Google Gemini 3
Signed-off-by: Ian Rogers <irogers@google.com>
---
 tools/perf/tests/builtin-test.c | 218 +++++++++++++++++++++++++++++++-
 1 file changed, 215 insertions(+), 3 deletions(-)

diff --git a/tools/perf/tests/builtin-test.c b/tools/perf/tests/builtin-test.c
index ad1b941731ca..45c1afb9ad33 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 = 1;
+/* Number of lines to include in failure snippet. */
+static unsigned int failure_snippet_lines = 10;
 const char *dso_to_test;
 const char *test_objdump_path = "objdump";
 
@@ -343,7 +345,7 @@ static int run_test_child(struct child_process *process)
 	for (size_t i = 0; i < ARRAY_SIZE(signals); i++)
 		signal(signals[i], child_test_sig_handler);
 
-	pr_debug("--- start ---\n");
+	pr_debug("---- start ----\n");
 	pr_debug("test child forked, pid %d\n", getpid());
 	err = test_function(child->test, child->test_case_num)(child->test, child->test_case_num);
 	pr_debug("---- end(%d) ----\n", err);
@@ -394,6 +396,210 @@ static int print_test_result(struct test_suite *t, int curr_suite, int curr_test
 	return 0;
 }
 
+static const char * const fail_keywords[] = {
+	"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 = NULL;
+	size_t best_len = 0;
+	int k;
+
+	for (k = 0; fail_keywords[k]; k++) {
+		const char *s = str;
+		size_t len = strlen(fail_keywords[k]);
+
+		while ((size_t)(s - str) + len <= max_len) {
+			size_t i;
+
+			for (i = 0; i < len; i++) {
+				if (tolower(s[i]) != fail_keywords[k][i])
+					break;
+			}
+			if (i == len) {
+				if (!best || s < best) {
+					best = s;
+					best_len = len;
+				}
+				break;
+			}
+			s++;
+		}
+	}
+	if (best) {
+		*kw_len = best_len;
+		return best;
+	}
+	return NULL;
+}
+
+static void print_line_highlighted(FILE *fp, const char *line, size_t len)
+{
+	const char *s = line;
+
+	while (len > 0) {
+		size_t kw_len = 0;
+		const char *match = 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 -= (match + kw_len) - s;
+		s = match + kw_len;
+	}
+}
+
+static bool line_contains(const char *line, size_t len, const char *tok)
+{
+	size_t tok_len = strlen(tok);
+	const char *s = line;
+
+	while ((size_t)(s - line) + tok_len <= len) {
+		if (memcmp(s, tok, tok_len) == 0)
+			return true;
+		s++;
+	}
+	return false;
+}
+
+static void print_test_failure_snippet(FILE *fp, const char *buf)
+{
+	size_t num_lines = 0;
+	size_t max_lines = 128;
+	const char **lines = calloc(max_lines, sizeof(const char *));
+	size_t *line_lens = calloc(max_lines, sizeof(size_t));
+	const char *s = buf;
+	size_t i;
+	unsigned int picked_count = 0;
+	bool *pick;
+	int last_printed = -1;
+
+	if (!lines || !line_lens) {
+		free(lines); free(line_lens);
+		fprintf(fp, "%s", buf);
+		return;
+	}
+
+	while (*s) {
+		const char *eol = strchr(s, '\n');
+		size_t len;
+
+		if (eol)
+			len = eol - s + 1;
+		else
+			len = strlen(s);
+
+		if (num_lines == max_lines) {
+			const char **new_lines;
+			size_t *new_lens;
+
+			max_lines *= 2;
+			new_lines = realloc(lines, max_lines * sizeof(const char *));
+			if (!new_lines) {
+				free(lines); free(line_lens);
+				fprintf(fp, "%s", buf);
+				return;
+			}
+			lines = new_lines;
+
+			new_lens = realloc(line_lens, max_lines * sizeof(size_t));
+			if (!new_lens) {
+				free(lines); free(line_lens);
+				fprintf(fp, "%s", buf);
+				return;
+			}
+			line_lens = new_lens;
+		}
+		lines[num_lines] = s;
+		line_lens[num_lines] = len;
+		num_lines++;
+		s += len;
+	}
+
+	if (num_lines <= failure_snippet_lines) {
+		for (i = 0; i < num_lines; i++)
+			print_line_highlighted(fp, lines[i], line_lens[i]);
+		free(lines); free(line_lens);
+		return;
+	}
+
+	pick = calloc(num_lines, sizeof(bool));
+	if (!pick) {
+		for (i = 0; i < num_lines; i++)
+			print_line_highlighted(fp, lines[i], line_lens[i]);
+		free(lines); free(line_lens);
+		return;
+	}
+
+	/* Pass 0: Unconditionally pick marker lines */
+	for (i = 0; i < num_lines; i++) {
+		if (line_contains(lines[i], line_lens[i], "----")) {
+			pick[i] = true;
+			if (picked_count < failure_snippet_lines)
+				picked_count++;
+		}
+	}
+
+	/* Pass 1: Pick lines with failure keywords from start */
+	for (i = 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] = true;
+				picked_count++;
+			}
+			/* Prioritize getting the next line for context */
+			if (i + 1 < num_lines && !pick[i + 1] &&
+			    picked_count < failure_snippet_lines) {
+				pick[i + 1] = true;
+				picked_count++;
+			}
+		}
+	}
+
+	/* Pass 2: Fill remaining quota from the end backwards */
+	if (picked_count < failure_snippet_lines) {
+		size_t j = num_lines;
+
+		while (j > 0 && picked_count < failure_snippet_lines) {
+			j--;
+			if (!pick[j]) {
+				pick[j] = true;
+				picked_count++;
+			}
+		}
+	}
+
+	for (i = 0; i < num_lines; i++) {
+		if (!pick[i])
+			continue;
+		if (last_printed != -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 = 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)
 {
@@ -501,8 +707,10 @@ static void finish_test(struct child_test **child_tests, int running_test, int c
 	}
 	/* Clean up child process. */
 	ret = finish_command(&child_test->process);
-	if (verbose > 1 || (verbose == 1 && ret == TEST_FAIL))
+	if (verbose > 1)
 		fprintf(stderr, "%s", err_output.buf);
+	else if (verbose == 1 && ret == TEST_FAIL)
+		print_test_failure_snippet(stderr, err_output.buf);
 
 	strbuf_release(&err_output);
 	print_test_result(t, curr_suite, curr_test_case, ret, width, /*running=*/0);
@@ -675,8 +883,10 @@ static int finish_tests_parallel(struct child_test **child_tests, size_t num_tes
 				}
 			}
 
-			if (verbose > 1 || (verbose == 1 && child->result == TEST_FAIL))
+			if (verbose > 1)
 				fprintf(stderr, "%s", child->err_output.buf);
+			else if (verbose == 1 && child->result == TEST_FAIL)
+				print_test_failure_snippet(stderr, child->err_output.buf);
 
 			print_test_result(child->test, child->suite_num, child->test_case_num,
 					  child->result, width, 0);
@@ -1004,6 +1214,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[] = { "list", NULL };
-- 
2.54.0.563.g4f69b47b94-goog


  parent reply	other threads:[~2026-05-13 23:05 UTC|newest]

Thread overview: 22+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2026-05-13 23:04 [PATCH v1 00/14] perf test: Harness improvements Ian Rogers
2026-05-13 23:04 ` [PATCH v1 01/14] perf jevents.py: Make generated C code more kernel style Ian Rogers
2026-05-13 23:04 ` [PATCH v1 02/14] perf pmu-events: Add API to get metric table name and iterate tables Ian Rogers
2026-05-14 11:42   ` sashiko-bot
2026-05-13 23:04 ` [PATCH v1 03/14] perf test: Drain pipe after child finishes to avoid losing output Ian Rogers
2026-05-13 23:04 ` [PATCH v1 04/14] perf test: Support dynamic test suites with setup callback and private data Ian Rogers
2026-05-14 12:10   ` sashiko-bot
2026-05-13 23:04 ` [PATCH v1 05/14] perf test pmu-events: A sub-test per metric table Ian Rogers
2026-05-13 23:04 ` [PATCH v1 06/14] perf test: Refactor parallel poll loop to drain all pipes simultaneously Ian Rogers
2026-05-14 14:27   ` sashiko-bot
2026-05-13 23:04 ` Ian Rogers [this message]
2026-05-14 15:50   ` [PATCH v1 07/14] perf test: Show snippet failure output for verbose=1 sashiko-bot
2026-05-13 23:04 ` [PATCH v1 08/14] perf test: Add summary reporting Ian Rogers
2026-05-14 16:10   ` sashiko-bot
2026-05-13 23:04 ` [PATCH v1 09/14] perf test: Fix subtest status alignment for multi-digit indexes Ian Rogers
2026-05-13 23:04 ` [PATCH v1 10/14] perf test: Skip shebang and SPDX comments in shell test descriptions Ian Rogers
2026-05-13 23:04 ` [PATCH v1 11/14] perf test: Split monolithic 'util' test suite into sub-tests Ian Rogers
2026-05-13 23:04 ` [PATCH v1 12/14] perf test: Add -j/--junit option for JUnit XML test reports Ian Rogers
2026-05-14 17:48   ` sashiko-bot
2026-05-13 23:04 ` [PATCH v1 13/14] perf test: Add shell test to validate JUnit XML reporting output Ian Rogers
2026-05-13 23:04 ` [PATCH v1 14/14] perf test: Remove /usr/bin/cc dependency from Intel PT shell test Ian Rogers
2026-05-14 18:28   ` sashiko-bot

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=20260513230450.529380-8-irogers@google.com \
    --to=irogers@google.com \
    --cc=acme@kernel.org \
    --cc=adrian.hunter@intel.com \
    --cc=alexander.shishkin@linux.intel.com \
    --cc=james.clark@linaro.org \
    --cc=jolsa@kernel.org \
    --cc=linux-kernel@vger.kernel.org \
    --cc=linux-perf-users@vger.kernel.org \
    --cc=mingo@redhat.com \
    --cc=namhyung@kernel.org \
    --cc=peterz@infradead.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.