Re: [PATCH] MI: new timing command

[Vladimir Prus <ghost@cs.msu.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