Skip to content

trace2: clean up formatting in perf target format #298

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
18 changes: 17 additions & 1 deletion quote.c
Original file line number Diff line number Diff line change
Expand Up @@ -84,12 +84,28 @@ void sq_quote_argv(struct strbuf *dst, const char **argv)
}
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

On the Git mailing list, Junio C Hamano wrote (reply to this):

"Jeff Hostetler via GitGitGadget" <[email protected]> writes:

> +/*
> + * Legacy function to append each argv value, quoted as necessasry,
> + * with whitespace before each value.  This results in a leading
> + * space in the result.
> + */
>  void sq_quote_argv_pretty(struct strbuf *dst, const char **argv)
> +{
> +	if (argv[0])
> +		strbuf_addch(dst, ' ');
> +	sq_append_quote_argv_pretty(dst, argv);

Micronit (not worth a reroll): if !argv[0], there is no need to call
append, either.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

On the Git mailing list, Jeff Hostetler wrote (reply to this):



On 8/9/2019 1:54 PM, Junio C Hamano wrote:
> "Jeff Hostetler via GitGitGadget" <[email protected]> writes:
> 
>> +/*
>> + * Legacy function to append each argv value, quoted as necessasry,
>> + * with whitespace before each value.  This results in a leading
>> + * space in the result.
>> + */
>>   void sq_quote_argv_pretty(struct strbuf *dst, const char **argv)
>> +{
>> +	if (argv[0])
>> +		strbuf_addch(dst, ' ');
>> +	sq_append_quote_argv_pretty(dst, argv);
> 
> Micronit (not worth a reroll): if !argv[0], there is no need to call
> append, either.
> 

good catch.  thanks!

}

/*
* Legacy function to append each argv value, quoted as necessasry,
* with whitespace before each value. This results in a leading
* space in the result.
*/
void sq_quote_argv_pretty(struct strbuf *dst, const char **argv)
{
if (argv[0])
strbuf_addch(dst, ' ');
sq_append_quote_argv_pretty(dst, argv);
}

/*
* Append each argv value, quoted as necessary, with whitespace between them.
*/
void sq_append_quote_argv_pretty(struct strbuf *dst, const char **argv)
{
int i;

for (i = 0; argv[i]; i++) {
strbuf_addch(dst, ' ');
if (i > 0)
strbuf_addch(dst, ' ');
sq_quote_buf_pretty(dst, argv[i]);
}
}
Expand Down
1 change: 1 addition & 0 deletions quote.h
Original file line number Diff line number Diff line change
Expand Up @@ -40,6 +40,7 @@ void sq_quotef(struct strbuf *, const char *fmt, ...);
*/
void sq_quote_buf_pretty(struct strbuf *, const char *src);
void sq_quote_argv_pretty(struct strbuf *, const char **argv);
void sq_append_quote_argv_pretty(struct strbuf *dst, const char **argv);

/* This unwraps what sq_quote() produces in place, but returns
* NULL if the input does not look like what sq_quote would have
Expand Down
4 changes: 2 additions & 2 deletions t/t0211-trace2-perf.sh
Original file line number Diff line number Diff line change
Expand Up @@ -130,11 +130,11 @@ test_expect_success 'perf stream, child processes' '
d0|main|version|||||$V
d0|main|start||_T_ABS_|||_EXE_ trace2 004child test-tool trace2 004child test-tool trace2 001return 0
d0|main|cmd_name|||||trace2 (trace2)
d0|main|child_start||_T_ABS_|||[ch0] class:? argv: test-tool trace2 004child test-tool trace2 001return 0
d0|main|child_start||_T_ABS_|||[ch0] class:? argv:[test-tool trace2 004child test-tool trace2 001return 0]
d1|main|version|||||$V
d1|main|start||_T_ABS_|||_EXE_ trace2 004child test-tool trace2 001return 0
d1|main|cmd_name|||||trace2 (trace2/trace2)
d1|main|child_start||_T_ABS_|||[ch0] class:? argv: test-tool trace2 001return 0
d1|main|child_start||_T_ABS_|||[ch0] class:? argv:[test-tool trace2 001return 0]
d2|main|version|||||$V
d2|main|start||_T_ABS_|||_EXE_ trace2 001return 0
d2|main|cmd_name|||||trace2 (trace2/trace2/trace2)
Expand Down
5 changes: 0 additions & 5 deletions trace2/tr2_tgt_event.c
Original file line number Diff line number Diff line change
Expand Up @@ -205,11 +205,6 @@ static void maybe_add_string_va(struct json_writer *jw, const char *field_name,
strbuf_release(&buf);
return;
}

if (fmt && *fmt) {
jw_object_string(jw, field_name, fmt);
return;
}
}

static void fn_error_va_fl(const char *file, int line, const char *fmt,
Expand Down
35 changes: 18 additions & 17 deletions trace2/tr2_tgt_normal.c
Original file line number Diff line number Diff line change
Expand Up @@ -87,7 +87,7 @@ static void fn_start_fl(const char *file, int line,
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addstr(&buf_payload, "start ");
sq_quote_argv_pretty(&buf_payload, argv);
sq_append_quote_argv_pretty(&buf_payload, argv);
normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}
Expand Down Expand Up @@ -135,20 +135,18 @@ static void maybe_append_string_va(struct strbuf *buf, const char *fmt,
va_end(copy_ap);
return;
}

if (fmt && *fmt) {
strbuf_addstr(buf, fmt);
return;
}
}

static void fn_error_va_fl(const char *file, int line, const char *fmt,
va_list ap)
{
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addstr(&buf_payload, "error ");
maybe_append_string_va(&buf_payload, fmt, ap);
strbuf_addstr(&buf_payload, "error");
if (fmt && *fmt) {
strbuf_addch(&buf_payload, ' ');
maybe_append_string_va(&buf_payload, fmt, ap);
}
normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}
Expand Down Expand Up @@ -188,8 +186,8 @@ static void fn_alias_fl(const char *file, int line, const char *alias,
{
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "alias %s ->", alias);
sq_quote_argv_pretty(&buf_payload, argv);
strbuf_addf(&buf_payload, "alias %s -> ", alias);
sq_append_quote_argv_pretty(&buf_payload, argv);
normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}
Expand All @@ -200,22 +198,23 @@ static void fn_child_start_fl(const char *file, int line,
{
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "child_start[%d] ", cmd->trace2_child_id);
strbuf_addf(&buf_payload, "child_start[%d]", cmd->trace2_child_id);

if (cmd->dir) {
strbuf_addstr(&buf_payload, " cd");
strbuf_addstr(&buf_payload, " cd ");
sq_quote_buf_pretty(&buf_payload, cmd->dir);
strbuf_addstr(&buf_payload, "; ");
strbuf_addstr(&buf_payload, ";");
}

/*
* TODO if (cmd->env) { Consider dumping changes to environment. }
* See trace_add_env() in run-command.c as used by original trace.c
*/

strbuf_addch(&buf_payload, ' ');
if (cmd->git_cmd)
strbuf_addstr(&buf_payload, "git");
sq_quote_argv_pretty(&buf_payload, cmd->argv);
strbuf_addstr(&buf_payload, "git ");
sq_append_quote_argv_pretty(&buf_payload, cmd->argv);

normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
Expand All @@ -240,9 +239,11 @@ static void fn_exec_fl(const char *file, int line, uint64_t us_elapsed_absolute,
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "exec[%d] ", exec_id);
if (exe)
if (exe) {
strbuf_addstr(&buf_payload, exe);
sq_quote_argv_pretty(&buf_payload, argv);
strbuf_addch(&buf_payload, ' ');
}
sq_append_quote_argv_pretty(&buf_payload, argv);
normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}
Expand Down
89 changes: 59 additions & 30 deletions trace2/tr2_tgt_perf.c
Original file line number Diff line number Diff line change
Expand Up @@ -21,10 +21,10 @@ static struct tr2_dst tr2dst_perf = { TR2_SYSENV_PERF, 0, 0, 0 };
*/
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

On the Git mailing list, Junio C Hamano wrote (reply to this):

"Jeff Hostetler via GitGitGadget" <[email protected]> writes:

> From: Jeff Hostetler <[email protected]>
>
> Trim leading/trailing whitespace from the command line
> printed in the "start" message in the perf target format.
>
> We use `sq_quote_argv_pretty()` to format the message
> and it adds a leading space to the output.  Trim that.

strbuf_trim() not just drops a single leading space, but removes
consecutive spaces from both ends.  But the first char after the SP
comes from the first arg, and it can never be a whitespace (as a
payload that begins with a whitespace will be quoted, so it will be
a single quote), and the last char in the buffer would also be
either a closing single quote (if the last argument ends with a
whitespace) or a non whitespace "safe" character, so it is safe to
use strbuf_trim() here.

I wonder if we want to lose the prepending of SP from
sq_quote_argv_pretty(), though:

 * run-command.c::trace_run_command() does rely on having SP there,
   so the caller needs adjusting if we did so.

 * trace.c::trace_argv_vprintf_fl() also needs SP there after the
   caller supplied format.

 * trace.c::print_command_performance_atexit() expects command_line
   begins with the extra SP left by the sq_quote_argv_pretty()
   called by the trace_command_performance(); the format string
   given to trace_performance_leave() there needs adjusting.


By the way, use of sq_quote_argv_pretty() in builtin/rebase.c on
opts->git_am_opts.argv done in run_specific_rebase() is dubious.
The argv array is made into a single string that safely uses sq,
appropriate to feed a shell.  But that string is passed as the
"value" parameter to add_var() helper that expects to receive a raw
value (hence it calls sq_quote_buf() on the value), resulting in a
string that is doubly quoted.  I am not sure if that was intended.

In any case, the patch itself obviously look correct.

> Signed-off-by: Jeff Hostetler <[email protected]>
> ---
>  trace2/tr2_tgt_perf.c | 1 +
>  1 file changed, 1 insertion(+)
>
> diff --git a/trace2/tr2_tgt_perf.c b/trace2/tr2_tgt_perf.c
> index 4a9d99218b..ed4e708f28 100644
> --- a/trace2/tr2_tgt_perf.c
> +++ b/trace2/tr2_tgt_perf.c
> @@ -185,6 +185,7 @@ static void fn_start_fl(const char *file, int line,
>  	struct strbuf buf_payload = STRBUF_INIT;
>  
>  	sq_quote_argv_pretty(&buf_payload, argv);
> +	strbuf_trim(&buf_payload);
>  
>  	perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
>  			 NULL, NULL, &buf_payload);

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

On the Git mailing list, Jeff Hostetler wrote (reply to this):



On 8/1/2019 5:34 PM, Junio C Hamano wrote:
> "Jeff Hostetler via GitGitGadget" <[email protected]> writes:
> 
>> From: Jeff Hostetler <[email protected]>
>>
>> Trim leading/trailing whitespace from the command line
>> printed in the "start" message in the perf target format.
>>
>> We use `sq_quote_argv_pretty()` to format the message
>> and it adds a leading space to the output.  Trim that.
> 
> strbuf_trim() not just drops a single leading space, but removes
> consecutive spaces from both ends.  But the first char after the SP
> comes from the first arg, and it can never be a whitespace (as a
> payload that begins with a whitespace will be quoted, so it will be
> a single quote), and the last char in the buffer would also be
> either a closing single quote (if the last argument ends with a
> whitespace) or a non whitespace "safe" character, so it is safe to
> use strbuf_trim() here.
> 
> I wonder if we want to lose the prepending of SP from
> sq_quote_argv_pretty(), though:

I was wondering about that too, but I didn't want to presume
to know what all of the callers wanted.  And didn't want to
slip in such a change last-minute.

I'll re-roll with a new sq_quote_ function that does not
include the leading whitespace and convert/normalize all
of my trace2/* uses to call it instead.  This eliminates
the Trace2 code from the larger conversation (and is a
little more efficient than the strbuf_trim()).

Jeff

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

On the Git mailing list, Junio C Hamano wrote (reply to this):

Jeff Hostetler <[email protected]> writes:

> On 8/1/2019 5:34 PM, Junio C Hamano wrote:
>> "Jeff Hostetler via GitGitGadget" <[email protected]> writes:
>>
>>> From: Jeff Hostetler <[email protected]>
>>>
>>> Trim leading/trailing whitespace from the command line
>>> printed in the "start" message in the perf target format.
>>>
>>> We use `sq_quote_argv_pretty()` to format the message
>>> and it adds a leading space to the output.  Trim that.
>>
>> strbuf_trim() not just drops a single leading space, but removes
>> consecutive spaces from both ends.  But the first char after the SP
>> comes from the first arg, and it can never be a whitespace (as a
>> payload that begins with a whitespace will be quoted, so it will be
>> a single quote), and the last char in the buffer would also be
>> either a closing single quote (if the last argument ends with a
>> whitespace) or a non whitespace "safe" character, so it is safe to
>> use strbuf_trim() here.
>>
>> I wonder if we want to lose the prepending of SP from
>> sq_quote_argv_pretty(), though:
>
> I was wondering about that too, but I didn't want to presume
> to know what all of the callers wanted.  And didn't want to
> slip in such a change last-minute.

I do not think this topic/discussion is a place to do so, either.
And compensating on the caller's side, like your patch did, is
perfectly fine.

I was more disturbed by potential double quoting in some codepaths
when I did a cursory audit of users of sq_quote_argv_pretty(), and
would think that would be of more importance, though.

static int tr2env_perf_be_brief;

#define TR2FMT_PERF_FL_WIDTH (50)
#define TR2FMT_PERF_FL_WIDTH (28)
#define TR2FMT_PERF_MAX_EVENT_NAME (12)
#define TR2FMT_PERF_REPO_WIDTH (4)
#define TR2FMT_PERF_CATEGORY_WIDTH (10)
#define TR2FMT_PERF_REPO_WIDTH (3)
#define TR2FMT_PERF_CATEGORY_WIDTH (12)

#define TR2_DOTS_BUFFER_SIZE (100)
#define TR2_INDENT (2)
Expand Down Expand Up @@ -79,17 +79,36 @@ static void perf_fmt_prepare(const char *event_name,

if (!tr2env_perf_be_brief) {
struct tr2_tbuf tb_now;
size_t fl_end_col;

tr2_tbuf_local_time(&tb_now);
strbuf_addstr(buf, tb_now.buf);
strbuf_addch(buf, ' ');

if (file && *file)
strbuf_addf(buf, "%s:%d ", file, line);
while (buf->len < TR2FMT_PERF_FL_WIDTH)
fl_end_col = buf->len + TR2FMT_PERF_FL_WIDTH;

if (file && *file) {
struct strbuf buf_fl = STRBUF_INIT;

strbuf_addf(&buf_fl, "%s:%d", file, line);

if (buf_fl.len <= TR2FMT_PERF_FL_WIDTH)
strbuf_addbuf(buf, &buf_fl);
else {
size_t avail = TR2FMT_PERF_FL_WIDTH - 3;
strbuf_addstr(buf, "...");
strbuf_add(buf,
&buf_fl.buf[buf_fl.len - avail],
avail);
}

strbuf_release(&buf_fl);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Instead of initializing, reallocating and then releasing that strbuf all the time, I would like to suggest this strategy instead:

strbuf_addf(buf, "%s:%d", file, line);
if (buf->len > TR2FMT_PERF_FL_WIDTH)
    /* shorten it to the maximum width, prefixing with ... */
    strbuf_splice(buf, len, buf->len - (TR2FMT_PERF_FL_WIDTH - 3), "...", 3);

}

while (buf->len < fl_end_col)
strbuf_addch(buf, ' ');
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe this instead? It will potentially avoid repeated re-allocations:

if (buf->len < fl_end_col)
    strbuf_addchars(&buf, ' ', fl_end_col - buf->len);


strbuf_addstr(buf, "| ");
strbuf_addstr(buf, " | ");
}

strbuf_addf(buf, "d%d | ", tr2_sid_depth());
Expand All @@ -102,7 +121,7 @@ static void perf_fmt_prepare(const char *event_name,
strbuf_addf(buf, "r%d ", repo->trace2_repo_id);
while (buf->len < len)
strbuf_addch(buf, ' ');
strbuf_addstr(buf, "| ");
strbuf_addstr(buf, " | ");

if (p_us_elapsed_absolute)
strbuf_addf(buf, "%9.6f | ",
Expand All @@ -116,8 +135,8 @@ static void perf_fmt_prepare(const char *event_name,
else
strbuf_addf(buf, "%9s | ", " ");

strbuf_addf(buf, "%-*s | ", TR2FMT_PERF_CATEGORY_WIDTH,
(category ? category : ""));
strbuf_addf(buf, "%-*.*s | ", TR2FMT_PERF_CATEGORY_WIDTH,
TR2FMT_PERF_CATEGORY_WIDTH, (category ? category : ""));
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Cute. I did not know that you could do that. But I guess the -* defines a left-aligned column of a certain minimum width, and the .* defines the "precision" (maximum length for strings), so you essentially fix-width this.

It might be more readable (and less puzzling to the casual reader) to disentangle this, though:

size_t len;
[...]
len = buf->len;
if (category) {
    size_t category_len = strlen(category);
    strbuf_add(buf, category, category_len < TR2FMT_PERF_CATEGORY_WIDTH ?
        category_len : TR2FMT_PERF_CATEGORY_WIDTH);
}
if (buf->len - len < TR2FMT_PERF_CATEGORY_WIDTH)
    strbuf_addchars(buf, ' ', TR2FMT_PERF_CATEGORY_WIDTH);
strbuf_addstr(buf, " | ");

At this point, though, it might make sense to add a fixed-width variant:

void strbuf_addstr_fixed_width(struct strbuf *buf, const char *string, size_t width, int pad_character)
{
    size_t offset = buf->len, len = strlen(string);

    strbuf_add(buf, string, len < width ? len : width);
    if (buf->len - offset < width)
        strbuf_addchars(buf, pad_character, width - (buf->len - offset));
}


if (ctx->nr_open_regions > 0) {
int len_indent = TR2_INDENT_LENGTH(ctx);
Expand Down Expand Up @@ -165,7 +184,7 @@ static void fn_start_fl(const char *file, int line,
const char *event_name = "start";
struct strbuf buf_payload = STRBUF_INIT;

sq_quote_argv_pretty(&buf_payload, argv);
sq_append_quote_argv_pretty(&buf_payload, argv);

perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
NULL, NULL, &buf_payload);
Expand Down Expand Up @@ -220,11 +239,6 @@ static void maybe_append_string_va(struct strbuf *buf, const char *fmt,
va_end(copy_ap);
return;
}

if (fmt && *fmt) {
strbuf_addstr(buf, fmt);
return;
}
}

static void fn_error_va_fl(const char *file, int line, const char *fmt,
Expand Down Expand Up @@ -285,8 +299,9 @@ static void fn_alias_fl(const char *file, int line, const char *alias,
const char *event_name = "alias";
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "alias:%s argv:", alias);
sq_quote_argv_pretty(&buf_payload, argv);
strbuf_addf(&buf_payload, "alias:%s argv:[", alias);
sq_append_quote_argv_pretty(&buf_payload, argv);
strbuf_addch(&buf_payload, ']');

perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
&buf_payload);
Expand Down Expand Up @@ -315,10 +330,14 @@ static void fn_child_start_fl(const char *file, int line,
sq_quote_buf_pretty(&buf_payload, cmd->dir);
}

strbuf_addstr(&buf_payload, " argv:");
if (cmd->git_cmd)
strbuf_addstr(&buf_payload, " git");
sq_quote_argv_pretty(&buf_payload, cmd->argv);
strbuf_addstr(&buf_payload, " argv:[");
if (cmd->git_cmd) {
strbuf_addstr(&buf_payload, "git");
if (cmd->argv[0])
strbuf_addch(&buf_payload, ' ');
}
sq_append_quote_argv_pretty(&buf_payload, cmd->argv);
strbuf_addch(&buf_payload, ']');

perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
NULL, NULL, &buf_payload);
Expand Down Expand Up @@ -369,10 +388,14 @@ static void fn_exec_fl(const char *file, int line, uint64_t us_elapsed_absolute,
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "id:%d ", exec_id);
strbuf_addstr(&buf_payload, "argv:");
if (exe)
strbuf_addf(&buf_payload, " %s", exe);
sq_quote_argv_pretty(&buf_payload, argv);
strbuf_addstr(&buf_payload, "argv:[");
if (exe) {
strbuf_addstr(&buf_payload, exe);
if (argv[0])
strbuf_addch(&buf_payload, ' ');
}
sq_append_quote_argv_pretty(&buf_payload, argv);
strbuf_addch(&buf_payload, ']');

perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
NULL, NULL, &buf_payload);
Expand Down Expand Up @@ -433,8 +456,11 @@ static void fn_region_enter_printf_va_fl(const char *file, int line,
struct strbuf buf_payload = STRBUF_INIT;

if (label)
strbuf_addf(&buf_payload, "label:%s ", label);
maybe_append_string_va(&buf_payload, fmt, ap);
strbuf_addf(&buf_payload, "label:%s", label);
if (fmt && *fmt) {
strbuf_addch(&buf_payload, ' ');
maybe_append_string_va(&buf_payload, fmt, ap);
}

perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute,
NULL, category, &buf_payload);
Expand All @@ -450,8 +476,11 @@ static void fn_region_leave_printf_va_fl(
struct strbuf buf_payload = STRBUF_INIT;

if (label)
strbuf_addf(&buf_payload, "label:%s ", label);
maybe_append_string_va(&buf_payload, fmt, ap);
strbuf_addf(&buf_payload, "label:%s", label);
if (fmt && *fmt) {
strbuf_addch(&buf_payload, ' ' );
maybe_append_string_va(&buf_payload, fmt, ap);
}

perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute,
&us_elapsed_region, category, &buf_payload);
Expand Down