Re: [PATCH v4] perf sched map: Add command-name, fuzzy-name options to filter the output map

[Namhyung Kim <namhyung@kernel.org>]

Hello,

On Tue, Jun 18, 2024 at 11:37:08PM +0530, Madadi Vineeth Reddy wrote:
> By default, perf sched map prints sched-in events for all the tasks
> which may not be required all the time as it prints lot of symbols
> and rows to the terminal.
> 
> With --command-name option, one could specify the specific command(s)
> for which the map has to be shown. This would help in analyzing the
> CPU usage patterns easier for that specific command(s). Since multiple
> PID's might have the same command name, using command-name filter
> would be more useful for debugging.
> 
> Multiple command names can be given with a comma separator without
> whitespace.
> 
> The --fuzzy-name option can be used if fuzzy name matching is required.
> For example, "taskname" can be matched to any string that contains
> "taskname" as its substring.

Can we split the changes into separate commit?

 1. add --command-name filter, but I think --task-name is better.
 2. add multiple name support using CSV
 3. add --fuzzy-name support

Although change 2 and 3 can be trivial, having them separately would be
better for reviewers.

> 
> For other tasks, instead of printing the symbol, ** is printed and
> the same . is used to represent idle. ** is used instead of symbol
> for other tasks because it helps in clear visualization of command(s)
> of interest and secondly the symbol itself doesn't mean anything
> because the sched-in of that symbol will not be printed(first sched-in
> contains pid and the corresponding symbol).

I feel like '**' might be getting too much attention in the output.  As
it's not interested, less characters like '-' could be used.

> 
> When using the --command-name option, the sched-out time is represented
> by a '+'. Since not all task sched-in events are printed, the sched-out
> time of the relevant commands might be lost. This representation ensures
> that the sched-out time of the interested commands is not overlooked.
> The sched-out values for non-current CPUs are skipped because the sched-out
> symbol would be irrelevant.

Well, I think it's also a sched-in of another task, we can use '*- '
instead of adding a new '+' sign for sched-out.

> 
> 6.10.0-rc1
> ==========
> *A0                     794225.687532 secs A0 => migration/0:18
>   *.                    794225.687544 secs .  => swapper:0
>    .  *B0               794225.687628 secs B0 => migration/1:21
>    .  *.                794225.687639 secs
>    .   .  *C0           794225.687704 secs C0 => migration/2:26
>    .   .  *.            794225.687715 secs
>   *D0  .   .            794225.687829 secs D0 => perf-exec:332914
>    D0  .   .  *.        794225.687926 secs
>    D0  .   .  *E0       794225.689369 secs E0 => schbench:332916
>    D0  .  *F0  E0       794225.689409 secs F0 => schbench:332917
> 
> 6.10.0-rc1 + patch (--command-name perf)
> =============
>    ** *A0  **  **       794226.581112 secs A0 => perf:332915
>       +A0               794226.581145 secs
>    ** *A0  **  **       794227.582150 secs
>       +A0               794227.582162 secs
>    ** *A0  .   .        794228.583167 secs
>       +A0               794228.583177 secs
>    ** *A0  **  **       794229.634027 secs
>       +A0               794229.634040 secs
>    ** *A0  .   **       794230.635045 secs
>       +A0               794230.635058 secs
>    **  **  ** *B0       794231.204272 secs B0 => perf:332912
>               +B0       794231.204352 secs

Something like:

     -  *A0  -   -
     -  *-   -   -
     -  *A0  -   -
     -  *-   -   -
  ...
     -   -   -  *B0
     -   -   -  *-

Thanks,
Namhyung

> 
> This helps in visualizing how a benchmark or a task is spread over
> the available cpus while also knowing which cpus are idle(.) and which
> are not(**). This will be more useful as number of CPUs increase.
> 
> Signed-off-by: Madadi Vineeth Reddy <vineethr@linux.ibm.com>
> Reviewed-and-tested-by: Athira Rajeev <atrajeev@linux.vnet.ibm.com>
> 
> ---
> Changes in v4:
> - Handle possible memory allocation failures. (Chen Yu)
> - Link to v3: https://lore.kernel.org/all/20240617125006.31654-1-vineethr@linux.ibm.com/
> 
> Changes in v3:
> - Print the sched-out timestamp as a row when using the --command-name
>   option. (Namhyung Kim)
> - Refactor the code.
> - Rebase against perf-tools-next commit eae7044b67a6 ("perf hist: Honor
>   symbol conf.skip_empty")
> - Link to v2: https://lore.kernel.org/lkml/20240608124915.33860-1-vineethr@linux.ibm.com/
> 
> Changes in v2:
> - Add support for giving multiple command-names in CSV. (Namhyung Kim)
> - Add fuzzy name matching option. (Chen Yu)
> - Add Reviewed-and-tested-by tag from Athira Rajeev.
> - Rebase against perf-tools-next commit d2307fd4f989 ("perf maps: Add/use
>   a sorted insert for fixup overlap and insert")
> - Link to v1: https://lore.kernel.org/lkml/20240417152521.80340-1-vineethr@linux.ibm.com/
> ---
>  tools/perf/Documentation/perf-sched.txt |  10 ++
>  tools/perf/builtin-sched.c              | 228 ++++++++++++++++++++----
>  2 files changed, 201 insertions(+), 37 deletions(-)
> 
> diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
> index a216d2991b19..28637d097ddb 100644
> --- a/tools/perf/Documentation/perf-sched.txt
> +++ b/tools/perf/Documentation/perf-sched.txt
> @@ -130,6 +130,16 @@ OPTIONS for 'perf sched map'
>  --color-pids::
>  	Highlight the given pids.
>  
> +--command-name::
> +	Map output only for the given command name(s). Separate the
> +	command names with a comma (without whitespace). The sched-out
> +	time is printed and is represented by '+' for the given command
> +	name(s).
> +	(** indicates other tasks while . is idle).
> +
> +--fuzzy-name::
> +	Given command name can be partially matched (fuzzy matching).
> +
>  OPTIONS for 'perf sched timehist'
>  ---------------------------------
>  -k::
> diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> index 8cdf18139a7e..fcafa77b814d 100644
> --- a/tools/perf/builtin-sched.c
> +++ b/tools/perf/builtin-sched.c
> @@ -156,6 +156,8 @@ struct perf_sched_map {
>  	const char		*color_pids_str;
>  	struct perf_cpu_map	*color_cpus;
>  	const char		*color_cpus_str;
> +	const char              *command;
> +	bool                    fuzzy;
>  	struct perf_cpu_map	*cpus;
>  	const char		*cpus_str;
>  };
> @@ -177,6 +179,7 @@ struct perf_sched {
>  	struct perf_cpu	 max_cpu;
>  	u32		 *curr_pid;
>  	struct thread	 **curr_thread;
> +	struct thread    **curr_out_thread;
>  	char		 next_shortname1;
>  	char		 next_shortname2;
>  	unsigned int	 replay_repeat;
> @@ -1538,23 +1541,148 @@ map__findnew_thread(struct perf_sched *sched, struct machine *machine, pid_t pid
>  	return thread;
>  }
>  
> +struct CommandList {
> +	char **command_list;
> +	int command_count;
> +};
> +
> +static void free_command_list(struct CommandList *cmd_list)
> +{
> +	if (cmd_list) {
> +		for (int i = 0; i < cmd_list->command_count; i++)
> +			free(cmd_list->command_list[i]);
> +		free(cmd_list->command_list);
> +		free(cmd_list);
> +	}
> +}
> +
> +
> +static struct CommandList *parse_commands(const char *commands)
> +{
> +	char *commands_copy = NULL;
> +	struct CommandList *cmd_list = NULL;
> +	char *token = NULL;
> +
> +	commands_copy = strdup(commands);
> +	if (commands_copy == NULL)
> +		return NULL;
> +
> +	cmd_list = malloc(sizeof(struct CommandList));
> +	if (cmd_list == NULL) {
> +		free(commands_copy);
> +		return NULL;
> +	}
> +
> +	cmd_list->command_count = 0;
> +	cmd_list->command_list = NULL;
> +
> +	token = strtok(commands_copy, ",");
> +	while (token != NULL) {
> +		cmd_list->command_list = realloc(cmd_list->command_list, sizeof(char *)
> +							*(cmd_list->command_count + 1));
> +		if (cmd_list->command_list == NULL) {
> +			free_command_list(cmd_list);
> +			free(commands_copy);
> +			return NULL;
> +		}
> +
> +		cmd_list->command_list[cmd_list->command_count] = strdup(token);
> +		if (cmd_list->command_list[cmd_list->command_count] == NULL) {
> +			free_command_list(cmd_list);
> +			free(commands_copy);
> +			return NULL;
> +		}
> +
> +		cmd_list->command_count++;
> +		token = strtok(NULL, ",");
> +	}
> +
> +	free(commands_copy);
> +	return cmd_list;
> +}
> +
> +static bool sched_match_task(const char *comm_str, struct CommandList *cmd_list, bool fuzzy_match)
> +{
> +	bool match_found = false;
> +
> +	for (int i = 0; i < cmd_list->command_count && !match_found; i++) {
> +		if (fuzzy_match)
> +			match_found = !!strstr(comm_str, cmd_list->command_list[i]);
> +		else
> +			match_found = !strcmp(comm_str, cmd_list->command_list[i]);
> +	}
> +
> +	return match_found;
> +}
> +
> +static void print_sched_map(struct perf_sched *sched, struct perf_cpu this_cpu, int cpus_nr,
> +								const char *color, bool sched_out)
> +{
> +	for (int i = 0; i < cpus_nr; i++) {
> +		struct perf_cpu cpu = {
> +		.cpu = sched->map.comp ? sched->map.comp_cpus[i].cpu : i,
> +		};
> +		struct thread *curr_thread = sched->curr_thread[cpu.cpu];
> +		struct thread *curr_out_thread = sched->curr_out_thread[cpu.cpu];
> +		struct thread_runtime *curr_tr;
> +		const char *pid_color = color;
> +		const char *cpu_color = color;
> +		char symbol = ' ';
> +		struct thread *thread_to_check = sched_out ? curr_out_thread : curr_thread;
> +
> +		if (thread_to_check && thread__has_color(thread_to_check))
> +			pid_color = COLOR_PIDS;
> +
> +		if (sched->map.color_cpus && perf_cpu_map__has(sched->map.color_cpus, cpu))
> +			cpu_color = COLOR_CPUS;
> +
> +		if (cpu.cpu == this_cpu.cpu) {
> +			if (sched_out)
> +				symbol = '+';
> +			else
> +				symbol = '*';
> +		}
> +
> +		color_fprintf(stdout, cpu.cpu != this_cpu.cpu ? color : cpu_color, "%c", symbol);
> +
> +		thread_to_check = sched_out ? sched->curr_out_thread[cpu.cpu] :
> +								sched->curr_thread[cpu.cpu];
> +
> +		if (thread_to_check) {
> +			curr_tr = thread__get_runtime(thread_to_check);
> +			if (curr_tr == NULL)
> +				return;
> +
> +			if (sched_out && cpu.cpu != this_cpu.cpu)
> +				color_fprintf(stdout, color, "   ");
> +			else
> +				color_fprintf(stdout, pid_color, "%2s ", curr_tr->shortname);
> +		} else
> +			color_fprintf(stdout, color, "   ");
> +	}
> +}
> +
>  static int map_switch_event(struct perf_sched *sched, struct evsel *evsel,
>  			    struct perf_sample *sample, struct machine *machine)
>  {
>  	const u32 next_pid = evsel__intval(evsel, sample, "next_pid");
> -	struct thread *sched_in;
> +	const u32 prev_pid = evsel__intval(evsel, sample, "prev_pid");
> +	struct thread *sched_in, *sched_out;
>  	struct thread_runtime *tr;
>  	int new_shortname;
>  	u64 timestamp0, timestamp = sample->time;
>  	s64 delta;
> -	int i;
>  	struct perf_cpu this_cpu = {
>  		.cpu = sample->cpu,
>  	};
>  	int cpus_nr;
> +	int proceed;
>  	bool new_cpu = false;
>  	const char *color = PERF_COLOR_NORMAL;
>  	char stimestamp[32];
> +	const char *str;
> +
> +	struct CommandList *cmd_list = NULL;
>  
>  	BUG_ON(this_cpu.cpu >= MAX_CPUS || this_cpu.cpu < 0);
>  
> @@ -1583,7 +1711,8 @@ static int map_switch_event(struct perf_sched *sched, struct evsel *evsel,
>  	}
>  
>  	sched_in = map__findnew_thread(sched, machine, -1, next_pid);
> -	if (sched_in == NULL)
> +	sched_out = map__findnew_thread(sched, machine, -1, prev_pid);
> +	if (sched_in == NULL || sched_out == NULL)
>  		return -1;
>  
>  	tr = thread__get_runtime(sched_in);
> @@ -1593,8 +1722,13 @@ static int map_switch_event(struct perf_sched *sched, struct evsel *evsel,
>  	}
>  
>  	sched->curr_thread[this_cpu.cpu] = thread__get(sched_in);
> +	sched->curr_out_thread[this_cpu.cpu] = thread__get(sched_out);
> +
> +	if (sched->map.command)
> +		cmd_list = parse_commands(sched->map.command);
>  
>  	new_shortname = 0;
> +	str = thread__comm_str(sched_in);
>  	if (!tr->shortname[0]) {
>  		if (!strcmp(thread__comm_str(sched_in), "swapper")) {
>  			/*
> @@ -1603,7 +1737,8 @@ static int map_switch_event(struct perf_sched *sched, struct evsel *evsel,
>  			 */
>  			tr->shortname[0] = '.';
>  			tr->shortname[1] = ' ';
> -		} else {
> +		} else if (!sched->map.command || sched_match_task(str, cmd_list,
> +								sched->map.fuzzy)) {
>  			tr->shortname[0] = sched->next_shortname1;
>  			tr->shortname[1] = sched->next_shortname2;
>  
> @@ -1616,6 +1751,9 @@ static int map_switch_event(struct perf_sched *sched, struct evsel *evsel,
>  				else
>  					sched->next_shortname2 = '0';
>  			}
> +		} else {
> +			tr->shortname[0] = '*';
> +			tr->shortname[1] = '*';
>  		}
>  		new_shortname = 1;
>  	}
> @@ -1623,42 +1761,27 @@ static int map_switch_event(struct perf_sched *sched, struct evsel *evsel,
>  	if (sched->map.cpus && !perf_cpu_map__has(sched->map.cpus, this_cpu))
>  		goto out;
>  
> -	printf("  ");
> -
> -	for (i = 0; i < cpus_nr; i++) {
> -		struct perf_cpu cpu = {
> -			.cpu = sched->map.comp ? sched->map.comp_cpus[i].cpu : i,
> -		};
> -		struct thread *curr_thread = sched->curr_thread[cpu.cpu];
> -		struct thread_runtime *curr_tr;
> -		const char *pid_color = color;
> -		const char *cpu_color = color;
> -
> -		if (curr_thread && thread__has_color(curr_thread))
> -			pid_color = COLOR_PIDS;
> -
> -		if (sched->map.cpus && !perf_cpu_map__has(sched->map.cpus, cpu))
> -			continue;
> -
> -		if (sched->map.color_cpus && perf_cpu_map__has(sched->map.color_cpus, cpu))
> -			cpu_color = COLOR_CPUS;
> -
> -		if (cpu.cpu != this_cpu.cpu)
> -			color_fprintf(stdout, color, " ");
> +	proceed = 0;
> +	str = thread__comm_str(sched_in);
> +	/*
> +	 * Check which of sched_in and sched_out matches the passed --command-line
> +	 * arguments and call the corresponding print_sched_map.
> +	 */
> +	if (sched->map.command && !sched_match_task(str, cmd_list, sched->map.fuzzy)) {
> +		if (!sched_match_task(thread__comm_str(sched_out), cmd_list, sched->map.fuzzy))
> +			goto out;
>  		else
> -			color_fprintf(stdout, cpu_color, "*");
> -
> -		if (sched->curr_thread[cpu.cpu]) {
> -			curr_tr = thread__get_runtime(sched->curr_thread[cpu.cpu]);
> -			if (curr_tr == NULL) {
> -				thread__put(sched_in);
> -				return -1;
> -			}
> -			color_fprintf(stdout, pid_color, "%2s ", curr_tr->shortname);
> -		} else
> -			color_fprintf(stdout, color, "   ");
> +			goto sched_out;
> +	} else {
> +		str = thread__comm_str(sched_out);
> +		if (!(sched->map.command && !sched_match_task(str, cmd_list, sched->map.fuzzy)))
> +			proceed = 1;
>  	}
>  
> +	printf("  ");
> +
> +	print_sched_map(sched, this_cpu, cpus_nr, color, false);
> +
>  	timestamp__scnprintf_usec(timestamp, stimestamp, sizeof(stimestamp));
>  	color_fprintf(stdout, color, "  %12s secs ", stimestamp);
>  	if (new_shortname || tr->comm_changed || (verbose > 0 && thread__tid(sched_in))) {
> @@ -1675,9 +1798,32 @@ static int map_switch_event(struct perf_sched *sched, struct evsel *evsel,
>  	if (sched->map.comp && new_cpu)
>  		color_fprintf(stdout, color, " (CPU %d)", this_cpu);
>  
> +	if (proceed != 1) {
> +		color_fprintf(stdout, color, "\n");
> +		goto out;
> +	}
> +
> +sched_out:
> +	if (sched->map.command) {
> +		tr = thread__get_runtime(sched->curr_out_thread[this_cpu.cpu]);
> +		if (strcmp(tr->shortname, "") == 0)
> +			goto out;
> +		if (proceed == 1)
> +			color_fprintf(stdout, color, "\n");
> +		printf("  ");
> +		print_sched_map(sched, this_cpu, cpus_nr, color, true);
> +		timestamp__scnprintf_usec(timestamp, stimestamp, sizeof(stimestamp));
> +		color_fprintf(stdout, color, "  %12s secs ", stimestamp);
> +	}
> +
>  	color_fprintf(stdout, color, "\n");
>  
>  out:
> +	if (sched->map.command) {
> +		free_command_list(cmd_list);
> +		thread__put(sched_out);
> +	}
> +
>  	thread__put(sched_in);
>  
>  	return 0;
> @@ -3307,6 +3453,10 @@ static int perf_sched__map(struct perf_sched *sched)
>  	if (!sched->curr_thread)
>  		return rc;
>  
> +	sched->curr_out_thread = calloc(MAX_CPUS, sizeof(*(sched->curr_out_thread)));
> +	if (!sched->curr_out_thread)
> +		return rc;
> +
>  	if (setup_cpus_switch_event(sched))
>  		goto out_free_curr_thread;
>  
> @@ -3560,6 +3710,10 @@ int cmd_sched(int argc, const char **argv)
>                      "highlight given CPUs in map"),
>  	OPT_STRING(0, "cpus", &sched.map.cpus_str, "cpus",
>                      "display given CPUs in map"),
> +	OPT_STRING(0, "command-name", &sched.map.command, "command",
> +		"map output only for the given command name(s)"),
> +	OPT_BOOLEAN(0, "fuzzy-name", &sched.map.fuzzy,
> +		"given command name can be partially matched (fuzzy matching)"),
>  	OPT_PARENT(sched_options)
>  	};
>  	const struct option timehist_options[] = {
> -- 
> 2.31.1
>