Re: [PATCH] MI: new timing command

[Vladimir Prus <ghost at cs dot msu dot su>]

Nick Roberts wrote:

> Here's a patch for timing MI commands e.g.
> 
> (gdb)
> -enable-timings
> ^done
> (gdb)
> -break-insert main
> ^done,bkpt={number="1",type="breakpoint",disp="keep",enabled="y",addr="0x080484ed",func="main",file="myprog.c",
> fullname="/home/nickrob/myprog.c",line="73",times="0"},time={wallclock="0.05185",user="0.00800",system="0.00000"} 

Great. I think this is really important for optimizing performance of MI.

> It's based on Apple's code. ÂI also have a patch which works for asynchronous
> operation but there's probably not much point in submitting that now.
> 
> I hope to submit further patches from Apple's code. ÂNotably:
> 
> 1) -stack-list-locals --create-varobjs Â(hopefully though Vladimir will
> Â Â do this one).

It's rather close in my plans. 


> ===================================================================
> RCS file: /cvs/src/src/gdb/mi/mi-main.c,v
> retrieving revision 1.86
> diff -c -p -r1.86 mi-main.c
> *** mi-main.cÂÂÂ17 Nov 2006 19:30:41 -0000ÂÂÂÂÂÂ1.86
> --- mi-main.cÂÂÂ30 Dec 2006 08:42:29 -0000
> ***************
> *** 49,54 ****

Do you have a *strong* preference to context diff as opposed to unified?
If yes, I think I can try to cope with context diffs, but unified diffs
are much more readable.

> --- 49,55 ----
> Â 
> Â #include <ctype.h>
> Â #include <sys/time.h>
> + #include <sys/resource.h>
> Â 
> Â enum
> Â Â {
> *************** struct captured_mi_execute_command_args
> *** 81,86 ****
> --- 82,93 ----
> Â int mi_debug_p;
> Â struct ui_file *raw_stdout;
> Â 
> + /* This is used to pass the current command timestamp
> + Â Âdown to continuation routines. */

Two spaces after dot. No, I personally don't think this coding style
guideline makes any sense, but Dan will notice it anyway and you'll
have to change ;-)

More seriously, this comment only says what this variable is
used for, not what it is. For example, the comment might read:

        /* The timestamp of the moment when the current
            command started executing.  Used to ... */

Ah, and looking at the code this variable is used *only* so that
'run' and friend can output the timestamp despite the fact that
they don't emit '^done', so I think this is better
represented in the comment.

> + static struct mi_timestamp *current_command_ts;
> + 
> + static int do_timings = 0;
> + 
> Â /* The token of the last asynchronous command */
> Â static char *last_async_command;
> Â static char *previous_async_command;

> *************** mi_cmd_data_write_memory (char *command,
> *** 1024,1029 ****
> --- 1041,1070 ----
> Â Â return MI_CMD_DONE;
> Â }
> Â 
> + enum mi_cmd_result
> + mi_cmd_enable_timings (char *command, char **argv, int argc)
> + {
> + Â if (argc == 0)
> + Â Â do_timings = 1;
> + Â else if (argc == 1)
> + Â Â {
> + Â Â Â if (strcmp (argv[0], "yes") == 0)
> + ÂÂÂÂÂÂdo_timings = 1;
> + Â Â Â else if (strcmp (argv[0], "no") == 0)
> + ÂÂÂÂÂÂdo_timings = 0;
> + Â Â Â else
> + ÂÂÂÂÂÂgoto usage_error;

Something looks wrong with indentation above.

> + Â Â }
> + Â else
> + Â Â goto usage_error;
> + Â Â 
> + Â return MI_CMD_DONE;
> + 
> + Âusage_error:
> + Â error ("mi_cmd_enable_timings: Usage: %s {yes|no}", command);
> + Â return MI_CMD_ERROR;
> + }
> + 
> Â /* Execute a command within a safe environment.
> Â Â ÂReturn <0 for error; >=0 for ok.
> Â 
> *************** captured_mi_execute_command (struct ui_o
> *** 1038,1043 ****
> --- 1079,1086 ----
> Â Â Â (struct captured_mi_execute_command_args *) data;
> Â Â struct mi_parse *context = args->command;
> Â 
> + Â struct mi_timestamp cmd_finished;
> + 
> Â Â switch (context->op)
> Â Â Â {
> Â 
> *************** captured_mi_execute_command (struct ui_o
> *** 1052,1059 ****
> --- 1095,1109 ----
> Â Â Â Â Â Âindication of what action is required and then switch on
> Â Â Â Â Â Âthat. */
> Â Â Â Â args->action = EXECUTE_COMMAND_DISPLAY_PROMPT;
> + 
> + Â Â Â if (do_timings)
> + ÂÂÂÂÂÂcurrent_command_ts = context->cmd_start;

I wonder if it's better, instead of having global current_command_ts,
add new global

        struct mi_parse* current_context;

set it here to context:

        current_context = context;

And the user 'current_context' later. That seems to be a more
future-proof solution -- if mi_execute_async_cli_command will
later need something more from mi_parse structure, we won't
need to add yet another global variable.

> Â Â Â Â args->rc = mi_cmd_execute (context);
> Â 
> + Â Â Â if (do_timings)
> + Â Â Â Â Â timestamp (&cmd_finished);
> + 
> Â Â Â Â if (!target_can_async_p () || !target_executing)
> Â ÂÂÂÂÂÂ{
> Â ÂÂÂÂÂÂ Â/* print the result if there were no errors
> *************** captured_mi_execute_command (struct ui_o
> *** 1068,1073 ****
> --- 1118,1127 ----
> Â ÂÂÂÂÂÂ Â Â Âfputs_unfiltered ("^done", raw_stdout);
> Â ÂÂÂÂÂÂ Â Â Âmi_out_put (uiout, raw_stdout);
> Â ÂÂÂÂÂÂ Â Â Âmi_out_rewind (uiout);
> + ÂÂÂÂÂÂ Â Â Â/* Have to check cmd_start, since the command could be
> + ÂÂÂÂÂÂÂÂÂÂÂÂÂÂ "mi-enable-timings". */

Haven't you named the command 'enable-timings' without 'mi-'?

> + ÂÂÂÂÂÂ Â Â Âif (do_timings && context->cmd_start)
> + ÂÂÂÂÂÂÂÂÂÂÂÂÂÂ Âprint_diff (context->cmd_start, &cmd_finished);
> Â ÂÂÂÂÂÂ Â Â Âfputs_unfiltered ("\n", raw_stdout);
> Â ÂÂÂÂÂÂ Â Â}
> Â ÂÂÂÂÂÂ Âelse if (args->rc == MI_CMD_ERROR)
> *************** mi_execute_command (char *cmd, int from_
> *** 1163,1168 ****
> --- 1217,1230 ----
> Â Â if (command != NULL)
> Â Â Â {
> Â Â Â Â struct gdb_exception result;
> + 
> + Â Â Â if (do_timings)
> + ÂÂÂÂÂÂ{
> + ÂÂÂÂÂÂ Âcommand->cmd_start = (struct mi_timestamp *)
> + ÂÂÂÂÂÂ Â Âxmalloc (sizeof (struct mi_timestamp));
> + ÂÂÂÂÂÂ Âtimestamp (command->cmd_start);
> + ÂÂÂÂÂÂ}
> + 
> Â Â Â Â /* FIXME: cagney/1999-11-04: Can this use of catch_exceptions either
> Â Â Â Â Â Âbe pushed even further down or even eliminated? */
> Â Â Â Â args.command = command;
> *************** mi_execute_async_cli_command (char *mi, 
> *** 1350,1355 ****
> --- 1412,1419 ----
> Â Â Â Â fputs_unfiltered ("*stopped", raw_stdout);
> Â Â Â Â mi_out_put (uiout, raw_stdout);
> Â Â Â Â mi_out_rewind (uiout);
> + Â Â Â if (do_timings)
> + Â Â Â ÂÂÂÂÂÂÂÂprint_diff_now (current_command_ts);
> Â Â Â Â fputs_unfiltered ("\n", raw_stdout);
> Â Â Â Â return MI_CMD_QUIET;
> Â Â Â }
> *************** _initialize_mi_main (void)
> *** 1466,1468 ****
> --- 1530,1581 ----
> Â Â DEPRECATED_REGISTER_GDBARCH_SWAP (old_regs);
> Â Â deprecated_register_gdbarch_swap (NULL, 0, mi_setup_architecture_data);
> Â }
> + 
> + static void 
> + timestamp (struct mi_timestamp *tv)
> + Â {
> + Â Â gettimeofday (&tv->wallclock, NULL);
> + Â Â getrusage (RUSAGE_SELF, &tv->rusage);
> + Â }
> + 
> + static void 
> + print_diff_now (struct mi_timestamp *start)
> + Â {
> + Â Â struct mi_timestamp now;
> + Â Â timestamp (&now);
> + Â Â print_diff (start, &now);
> + Â }
> + 
> + static void 
> + print_diff (struct mi_timestamp *start, struct mi_timestamp *end)
> + Â {
> + Â Â fprintf_unfiltered
> + Â Â Â (raw_stdout,
> + Â Â Â Â",time={wallclock=\"%0.5f\",user=\"%0.5f\",system=\"%0.5f\"}", 
> + Â Â Â Âwallclock_diff (start, end) / 1000000.0, 
> + Â Â Â Âuser_diff (start, end) / 1000000.0, 
> + Â Â Â Âsystem_diff (start, end) / 1000000.0);
> + Â }
> + 
> + static long 
> + wallclock_diff (struct mi_timestamp *start, struct mi_timestamp *end)
> + Â {
> + Â Â return ((end->wallclock.tv_sec - start->wallclock.tv_sec) * 1000000) +
> + Â Â Â Â Â Â(end->wallclock.tv_usec - start->wallclock.tv_usec);
> + Â }
> + 
> + static long 
> + user_diff (struct mi_timestamp *start, struct mi_timestamp *end)
> + Â {
> + Â Â return 
> + Â Â Â((end->rusage.ru_utime.tv_sec - start->rusage.ru_utime.tv_sec) * 1000000) +
> + Â Â Â (end->rusage.ru_utime.tv_usec - start->rusage.ru_utime.tv_usec);
> + Â }
> + 
> + static long 
> + system_diff (struct mi_timestamp *start, struct mi_timestamp *end)
> + Â {
> + Â Â return 
> + Â Â Â((end->rusage.ru_stime.tv_sec - start->rusage.ru_stime.tv_sec) * 1000000) +
> + Â Â Â (end->rusage.ru_stime.tv_usec - start->rusage.ru_stime.tv_usec);
> + Â }

Perhaps the last three functions can be replaced with

static long
timeval_diff (struct timeval* start, start timeval *end)
{
        return (end->tv_sec - start->tv_sec) * 1000000 .....
}

That 'user_diff' seems rather low level on non-reusable.

> + /* Timestamps for current command and last asynchronous command */

Dot at the end of the sentence. The above sounds like this
structure hold two separate timestaps -- for current command
and the last async command. Maybe replacing "and" with "or" will help.

- Volodya