Re: [PATCH] MI: new timing command

Vladimir Prus
2006-12-30T12:09:49Z

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