From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 17141 invoked by alias); 30 Dec 2006 12:09:49 -0000 Received: (qmail 17131 invoked by uid 22791); 30 Dec 2006 12:09:47 -0000 X-Spam-Check-By: sourceware.org Received: from zigzag.lvk.cs.msu.su (HELO zigzag.lvk.cs.msu.su) (158.250.17.23) by sourceware.org (qpsmtpd/0.31) with ESMTP; Sat, 30 Dec 2006 12:09:43 +0000 Received: from Debian-exim by zigzag.lvk.cs.msu.su with spam-scanned (Exim 4.50) id 1H0d1q-0006wA-J5 for gdb-patches@sources.redhat.com; Sat, 30 Dec 2006 15:09:39 +0300 Received: from localhost ([127.0.0.1] helo=ip6-localhost) by zigzag.lvk.cs.msu.su with esmtp (Exim 4.50) id 1H0d1a-0006vS-Ec; Sat, 30 Dec 2006 15:09:18 +0300 From: Vladimir Prus Subject: Re: [PATCH] MI: new timing command To: Nick Roberts , gdb-patches@sources.redhat.com Date: Sat, 30 Dec 2006 12:09:00 -0000 References: <17814.10139.269708.848818@kahikatea.snap.net.nz> User-Agent: KNode/0.10.2 MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 8Bit Message-Id: Mailing-List: contact gdb-patches-help@sourceware.org; run by ezmlm Precedence: bulk List-Id: List-Subscribe: List-Archive: List-Post: List-Help: , Sender: gdb-patches-owner@sourceware.org X-SW-Source: 2006-12/txt/msg00356.txt.bz2 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 >   #include > + #include >   >   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