[RFC] Fix MI timings

[RFC] Fix MI timings

[Vladimir Prus]

I've noticed that -enable-timings produces broken output for all
commands that resume target. First, we output *stopped.
And them on a separate line we print the timing, like this:

	,time={wallclock="0.32046",user="0.32000",system="0.00000"} (gdb)

This happens because mi_on_normal_stop does print newline, and then
mi_execute_async_cli_command does timings separately. This patch:

1. Make mi_on_normal_stop emit the timing info
2. Stop mi_execute_async_cli_command from doing so
3. Makes captured_mi_execute_command report timing both to MI
and CLI code paths.

I'll commit this in a few days if there are no objections.

- Volodya

Re: [RFC] Fix MI timings

[Vladimir Prus]

[-- Attachment #1: Type: text/plain, Size: 733 bytes --]

On Tuesday 10 March 2009 00:10:05 Vladimir Prus wrote:
> I've noticed that -enable-timings produces broken output for all
> commands that resume target. First, we output *stopped.
> And them on a separate line we print the timing, like this:
>
> 	,time={wallclock="0.32046",user="0.32000",system="0.00000"} (gdb)
>
> This happens because mi_on_normal_stop does print newline, and then
> mi_execute_async_cli_command does timings separately. This patch:
>
> 1. Make mi_on_normal_stop emit the timing info
> 2. Stop mi_execute_async_cli_command from doing so
> 3. Makes captured_mi_execute_command report timing both to MI
> and CLI code paths.
>
> I'll commit this in a few days if there are no objections.

*This* patch.

- Volodya


[-- Attachment #2: timing.diff --]
[-- Type: text/x-patch, Size: 3487 bytes --]

diff --git a/gdb/mi/mi-interp.c b/gdb/mi/mi-interp.c
index 65c1b4f..5ab5036 100644
--- a/gdb/mi/mi-interp.c
+++ b/gdb/mi/mi-interp.c
@@ -362,6 +362,7 @@ mi_on_normal_stop (struct bpstats *bs, int print_frame)
   fputs_unfiltered ("*stopped", raw_stdout);
   mi_out_put (mi_uiout, raw_stdout);
   mi_out_rewind (mi_uiout);
+  print_timing_maybe ();
   fputs_unfiltered ("\n", raw_stdout);
   gdb_flush (raw_stdout);
 }
diff --git a/gdb/mi/mi-main.c b/gdb/mi/mi-main.c
index b905a9e..a41c135 100644
--- a/gdb/mi/mi-main.c
+++ b/gdb/mi/mi-main.c
@@ -97,6 +97,8 @@ static void timestamp (struct mi_timestamp *tv);
 
 static void print_diff_now (struct mi_timestamp *start);
 static void print_diff (struct mi_timestamp *start, struct mi_timestamp *end);
+void print_timing_maybe ();
+
 
 void
 mi_cmd_gdb_exit (char *command, char **argv, int argc)
@@ -1139,7 +1141,8 @@ captured_mi_execute_command (struct ui_out *uiout, void *data)
 {
   struct mi_parse *context = (struct mi_parse *) data;
 
-  struct mi_timestamp cmd_finished;
+  if (do_timings)
+    current_command_ts = context->cmd_start;
 
   running_result_record_printed = 0;
   switch (context->op)
@@ -1151,14 +1154,9 @@ captured_mi_execute_command (struct ui_out *uiout, void *data)
 	fprintf_unfiltered (raw_stdout, " token=`%s' command=`%s' args=`%s'\n",
 			    context->token, context->command, context->args);
 
-      if (do_timings)
-	current_command_ts = context->cmd_start;
 
       mi_cmd_execute (context);
 
-      if (do_timings)
-	timestamp (&cmd_finished);
-
       /* Print the result if there were no errors.
 
 	 Remember that on the way out of executing a command, you have
@@ -1174,10 +1172,7 @@ captured_mi_execute_command (struct ui_out *uiout, void *data)
 			    ? "^connected" : "^done", raw_stdout);
 	  mi_out_put (uiout, raw_stdout);
 	  mi_out_rewind (uiout);
-	  /* Have to check cmd_start, since the command could be
-	     -enable-timings.  */
-	  if (do_timings && context->cmd_start)
-	    print_diff (context->cmd_start, &cmd_finished);
+	  print_timing_maybe ();
 	  fputs_unfiltered ("\n", raw_stdout);
 	}
       else
@@ -1212,7 +1207,8 @@ captured_mi_execute_command (struct ui_out *uiout, void *data)
 		fputs_unfiltered ("^done", raw_stdout);
 		mi_out_put (uiout, raw_stdout);
 		mi_out_rewind (uiout);
-		fputs_unfiltered ("\n", raw_stdout);
+		print_timing_maybe ();
+		fputs_unfiltered ("\n", raw_stdout);		
 	      }
 	    else
 	      mi_out_rewind (uiout);
@@ -1447,8 +1443,6 @@ mi_execute_async_cli_command (char *cli_command, char **argv, int argc)
       /* Do this before doing any printing.  It would appear that some
          print code leaves garbage around in the buffer.  */
       do_cleanups (old_cleanups);
-      if (do_timings)
-      	print_diff_now (current_command_ts);
     }
 }
 
@@ -1567,6 +1561,15 @@ print_diff_now (struct mi_timestamp *start)
     print_diff (start, &now);
   }
 
+void
+print_timing_maybe ()
+{
+  // If the command is -enable-timing then do_timings may be
+  // true whilst current_command_ts is not initialized.
+  if (do_timings && current_command_ts)
+    print_diff_now (current_command_ts);
+}
+
 static long 
 timeval_diff (struct timeval start, struct timeval end)
   {
diff --git a/gdb/mi/mi-main.h b/gdb/mi/mi-main.h
index 977579e..6766d71 100644
--- a/gdb/mi/mi-main.h
+++ b/gdb/mi/mi-main.h
@@ -30,5 +30,7 @@ extern char *current_token;
 
 extern int running_result_record_printed;
 
+void print_timing_maybe ();
+
 #endif
 

Re: [RFC] Fix MI timings

[Daniel Jacobowitz]

On Tue, Mar 10, 2009 at 12:15:03AM +0300, Vladimir Prus wrote:
> *This* patch.

You must've been working on programs in some Other Real Language
lately... :-)

> @@ -97,6 +97,8 @@ static void timestamp (struct mi_timestamp *tv);
>  
>  static void print_diff_now (struct mi_timestamp *start);
>  static void print_diff (struct mi_timestamp *start, struct mi_timestamp *end);
> +void print_timing_maybe ();
> +
>  
>  void
>  mi_cmd_gdb_exit (char *command, char **argv, int argc)

Prototypes in .h files only please.

> @@ -1567,6 +1561,15 @@ print_diff_now (struct mi_timestamp *start)
>      print_diff (start, &now);
>    }
>  
> +void
> +print_timing_maybe ()

(void)

> +{
> +  // If the command is -enable-timing then do_timings may be
> +  // true whilst current_command_ts is not initialized.

/* */

> +void print_timing_maybe ();

(void)

Also, since this is public, please give it an "mi_" prefix.

I have nothing useful to say about the important part of the patch,
though.

-- 
Daniel Jacobowitz
CodeSourcery

Re: [RFC] Fix MI timings

[Vladimir Prus]

[-- Attachment #1: Type: text/plain, Size: 1184 bytes --]

On Tuesday 10 March 2009 00:22:30 Daniel Jacobowitz wrote:
> On Tue, Mar 10, 2009 at 12:15:03AM +0300, Vladimir Prus wrote:
> > *This* patch.
>
> You must've been working on programs in some Other Real Language
> lately... :-)

'Tis true.


>
> > @@ -97,6 +97,8 @@ static void timestamp (struct mi_timestamp *tv);
> >
> >  static void print_diff_now (struct mi_timestamp *start);
> >  static void print_diff (struct mi_timestamp *start, struct mi_timestamp
> > *end); +void print_timing_maybe ();
> > +
> >
> >  void
> >  mi_cmd_gdb_exit (char *command, char **argv, int argc)
>
> Prototypes in .h files only please.
>
> > @@ -1567,6 +1561,15 @@ print_diff_now (struct mi_timestamp *start)
> >      print_diff (start, &now);
> >    }
> >
> > +void
> > +print_timing_maybe ()
>
> (void)
>
> > +{
> > +  // If the command is -enable-timing then do_timings may be
> > +  // true whilst current_command_ts is not initialized.
>
> /* */
>
> > +void print_timing_maybe ();
>
> (void)
>
> Also, since this is public, please give it an "mi_" prefix.
>
> I have nothing useful to say about the important part of the patch,
> though.

OK :-) Here's a revised patch, just in case.

- Volodya




[-- Attachment #2: timing.diff --]
[-- Type: text/x-patch, Size: 3694 bytes --]

commit 060c708c273bbfc17a9e8b464acaf64f797f1352
Author: Vladimir Prus <vladimir@codesourcery.com>
Date:   Tue Mar 10 00:25:42 2009 +0300

    Fix MI timings.
    
    	* mi/mi-main.c (mi_print_timing_maybe): New.
    	(captured_mi_execute_command): Simplify. Output timings to
    	CLI commands, too.
    	(mi_execute_async_cli_command): Do not print timings.
    	* mi/mi-main.h (mi_print_timing_maybe): Declare.
    	* mi/mi-interp.c (mi_on_normal_stop): Call mi_print_timing_maybe.

diff --git a/gdb/mi/mi-interp.c b/gdb/mi/mi-interp.c
index 65c1b4f..131698b 100644
--- a/gdb/mi/mi-interp.c
+++ b/gdb/mi/mi-interp.c
@@ -362,6 +362,7 @@ mi_on_normal_stop (struct bpstats *bs, int print_frame)
   fputs_unfiltered ("*stopped", raw_stdout);
   mi_out_put (mi_uiout, raw_stdout);
   mi_out_rewind (mi_uiout);
+  mi_print_timing_maybe ();
   fputs_unfiltered ("\n", raw_stdout);
   gdb_flush (raw_stdout);
 }
diff --git a/gdb/mi/mi-main.c b/gdb/mi/mi-main.c
index b905a9e..2873b4d 100644
--- a/gdb/mi/mi-main.c
+++ b/gdb/mi/mi-main.c
@@ -1139,7 +1139,8 @@ captured_mi_execute_command (struct ui_out *uiout, void *data)
 {
   struct mi_parse *context = (struct mi_parse *) data;
 
-  struct mi_timestamp cmd_finished;
+  if (do_timings)
+    current_command_ts = context->cmd_start;
 
   running_result_record_printed = 0;
   switch (context->op)
@@ -1151,14 +1152,9 @@ captured_mi_execute_command (struct ui_out *uiout, void *data)
 	fprintf_unfiltered (raw_stdout, " token=`%s' command=`%s' args=`%s'\n",
 			    context->token, context->command, context->args);
 
-      if (do_timings)
-	current_command_ts = context->cmd_start;
 
       mi_cmd_execute (context);
 
-      if (do_timings)
-	timestamp (&cmd_finished);
-
       /* Print the result if there were no errors.
 
 	 Remember that on the way out of executing a command, you have
@@ -1174,10 +1170,7 @@ captured_mi_execute_command (struct ui_out *uiout, void *data)
 			    ? "^connected" : "^done", raw_stdout);
 	  mi_out_put (uiout, raw_stdout);
 	  mi_out_rewind (uiout);
-	  /* Have to check cmd_start, since the command could be
-	     -enable-timings.  */
-	  if (do_timings && context->cmd_start)
-	    print_diff (context->cmd_start, &cmd_finished);
+	  mi_print_timing_maybe ();
 	  fputs_unfiltered ("\n", raw_stdout);
 	}
       else
@@ -1212,7 +1205,8 @@ captured_mi_execute_command (struct ui_out *uiout, void *data)
 		fputs_unfiltered ("^done", raw_stdout);
 		mi_out_put (uiout, raw_stdout);
 		mi_out_rewind (uiout);
-		fputs_unfiltered ("\n", raw_stdout);
+		mi_print_timing_maybe ();
+		fputs_unfiltered ("\n", raw_stdout);		
 	      }
 	    else
 	      mi_out_rewind (uiout);
@@ -1447,8 +1441,6 @@ mi_execute_async_cli_command (char *cli_command, char **argv, int argc)
       /* Do this before doing any printing.  It would appear that some
          print code leaves garbage around in the buffer.  */
       do_cleanups (old_cleanups);
-      if (do_timings)
-      	print_diff_now (current_command_ts);
     }
 }
 
@@ -1567,6 +1559,15 @@ print_diff_now (struct mi_timestamp *start)
     print_diff (start, &now);
   }
 
+void
+mi_print_timing_maybe (void)
+{
+  /* If the command is -enable-timing then do_timings may be
+     true whilst current_command_ts is not initialized.  */
+  if (do_timings && current_command_ts)
+    print_diff_now (current_command_ts);
+}
+
 static long 
 timeval_diff (struct timeval start, struct timeval end)
   {
diff --git a/gdb/mi/mi-main.h b/gdb/mi/mi-main.h
index 977579e..1383177 100644
--- a/gdb/mi/mi-main.h
+++ b/gdb/mi/mi-main.h
@@ -30,5 +30,7 @@ extern char *current_token;
 
 extern int running_result_record_printed;
 
+void mi_print_timing_maybe ();
+
 #endif
 

Re: [RFC] Fix MI timings

[Pedro Alves]

On Monday 09 March 2009 21:32:25, Vladimir Prus wrote:
> +void mi_print_timing_maybe ();

                              ^ (void) here too, please.

Also, it's redundant, but the only other function declared
in the header marks it explicitly as "extern",  you may want
to do the same for consistency.

-- 
Pedro Alves

Re: [RFC] Fix MI timings

[Pedro Alves]

On Monday 09 March 2009 21:32:25, Vladimir Prus wrote:
> +void mi_print_timing_maybe ();

                              ^ (void) here too, please.

Also, it's redundant, but the only other function declared
in the header marks it explicitly as "extern",  you may want
to do the same for consistency.

-- 
Pedro Alves

Re: [RFC] Fix MI timings

[Pedro Alves]

On Monday 09 March 2009 21:36:34, Pedro Alves wrote:
> On Monday 09 March 2009 21:32:25, Vladimir Prus wrote:
> > +void mi_print_timing_maybe ();
> 
>                               ^ (void) here too, please.
> 
> Also, it's redundant, but the only other function declared
> in the header marks it explicitly as "extern",  you may want
> to do the same for consistency.
> 

I was touching this file and noticed this patch went it without
the '(void)'.  Evil as I am, I went ahead and checked in the
patch below.  Muahahaha!!1  :-)

-- 
Pedro Alves

2009-03-17  Pedro Alves  <pedro@codesourcery.com>

	* mi/mi-main.h (mi_print_timing_maybe): Add strict prototype,
	declare as extern.

---
 gdb/mi/mi-main.h |    4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

Index: src/gdb/mi/mi-main.h
===================================================================
--- src.orig/gdb/mi/mi-main.h	2009-03-17 05:05:10.000000000 +0000
+++ src/gdb/mi/mi-main.h	2009-03-17 05:05:42.000000000 +0000
@@ -26,11 +26,11 @@ extern void mi_load_progress (const char
 			      unsigned long total_sent,
 			      unsigned long grand_total);
 
+extern void mi_print_timing_maybe (void);
+
 extern char *current_token;
 
 extern int running_result_record_printed;
 
-void mi_print_timing_maybe ();
-
 #endif
 

Re: [RFC] Fix MI timings

[Vladimir Prus]

On Tuesday 17 March 2009 08:19:25 Pedro Alves wrote:
> On Monday 09 March 2009 21:36:34, Pedro Alves wrote:
> > On Monday 09 March 2009 21:32:25, Vladimir Prus wrote:
> > > +void mi_print_timing_maybe ();
> >
> >                               ^ (void) here too, please.
> >
> > Also, it's redundant, but the only other function declared
> > in the header marks it explicitly as "extern",  you may want
> > to do the same for consistency.
>
> I was touching this file and noticed this patch went it without
> the '(void)'.  

Guess what -- it was intentional -- based on IRC conversation where
you have said (abridged) "C compiler does not really care for that word".

> Evil as I am, I went ahead and checked in the
> patch below.  Muahahaha!!1  :-)

Okay. 

- Volodya

Re: [RFC] Fix MI timings

[Vladimir Prus]

On Tuesday 17 March 2009 10:12:56 Vladimir Prus wrote:
> On Tuesday 17 March 2009 08:19:25 Pedro Alves wrote:
> > On Monday 09 March 2009 21:36:34, Pedro Alves wrote:
> > > On Monday 09 March 2009 21:32:25, Vladimir Prus wrote:
> > > > +void mi_print_timing_maybe ();
> > >
> > >                               ^ (void) here too, please.
> > >
> > > Also, it's redundant, but the only other function declared
> > > in the header marks it explicitly as "extern",  you may want
> > > to do the same for consistency.
> >
> > I was touching this file and noticed this patch went it without
> > the '(void)'.
>
> Guess what -- it was intentional -- based on IRC conversation where
> you have said (abridged) "C compiler does not really care for that word".

Oh, it was "void" that was missing? I only meant to not add "extern" :-(

Thanks for catching,
Volodya

Re: [RFC] Fix MI timings

[Vladimir Prus]

On Tuesday 10 March 2009 00:32:25 Vladimir Prus wrote:

> > Also, since this is public, please give it an "mi_" prefix.
> >
> > I have nothing useful to say about the important part of the patch,
> > though.
>
> OK :-) Here's a revised patch, just in case.

I've checked it in.

- Volodya