[03/10] Add printf debug to savevm

From: Juan Quintela <quintela@trasno.org>

Once there, print all sections that take more than 100ms to migrate.
buffered file runs a timer at that 100ms interval.

Signed-off-by: Juan Quintela <quintela@trasno.org>
Signed-off-by: Juan Quintela <quintela@redhat.com>
---
 savevm.c |   48 ++++++++++++++++++++++++++++++++++++++++++++++--
 1 files changed, 46 insertions(+), 2 deletions(-)

On 11/23/2010 05:03 PM, Juan Quintela wrote:
> From: Juan Quintela<quintela@trasno.org>
>
> Once there, print all sections that take more than 100ms to migrate.
> buffered file runs a timer at that 100ms interval.
>
> Signed-off-by: Juan Quintela<quintela@trasno.org>
> Signed-off-by: Juan Quintela<quintela@redhat.com>
> ---
>   savevm.c |   48 ++++++++++++++++++++++++++++++++++++++++++++++--
>   1 files changed, 46 insertions(+), 2 deletions(-)
>
> diff --git a/savevm.c b/savevm.c
> index 4e49765..ceed6de 100644
> --- a/savevm.c
> +++ b/savevm.c
> @@ -83,6 +83,24 @@
>   #include "migration.h"
>   #include "qemu_socket.h"
>   #include "qemu-queue.h"
> +#include "buffered_file.h"
> +
> +//#define DEBUG_SAVEVM
> +
> +#ifdef DEBUG_SAVEVM
> +#define DPRINTF(fmt, ...) \
> +    do { printf("savevm: " fmt, ## __VA_ARGS__); } while (0)
> +static int64_t start, stop;
> +#define START_SAVEVM_CLOCK()	do { start = qemu_get_clock(rt_clock); } while (0)
> +#define STOP_SAVEVM_CLOCK() \
> +	do { stop = qemu_get_clock(rt_clock) - start; \
> +	} while (0)
> +#else
> +#define DPRINTF(fmt, ...) \
> +    do { } while (0)
> +#define START_SAVEVM_CLOCK()  do { } while (0)
> +#define STOP_SAVEVM_CLOCK()   do { } while (0)
> +#endif
>
>   #define SELF_ANNOUNCE_ROUNDS 5
>
> @@ -1480,11 +1498,23 @@ int qemu_savevm_state_iterate(Monitor *mon, QEMUFile *f)
>           if (se->save_live_state == NULL)
>               continue;
>
> +        START_SAVEVM_CLOCK();
> +
>    

No magic macros like this please.  Maybe you want to add tracepoints?

>           /* Section type */
>           qemu_put_byte(f, QEMU_VM_SECTION_PART);
>           qemu_put_be32(f, se->section_id);
>
>           ret = se->save_live_state(mon, f, QEMU_VM_SECTION_PART, se->opaque);
> +        STOP_SAVEVM_CLOCK();
> +#ifdef DEBUG_SAVEVM
> +	if (stop>  buffered_file_interval) {
> +		/* buffered_file run a timer at 100ms */
> +		static int times_missing = 1;
> +		DPRINTF("save live iterate section id %u name %s took %ld milliseconds %u times\n",
> +			se->section_id,	se->idstr, stop, times_missing++);
> +	}
> +#endif
> +
>           if (!ret) {
>               /* Do not proceed to the next vmstate before this one reported
>                  completion of the current stage. This serializes the migration
> @@ -1516,13 +1546,18 @@ int qemu_savevm_state_complete(Monitor *mon, QEMUFile *f)
>           if (se->save_live_state == NULL)
>               continue;
>
> +        START_SAVEVM_CLOCK();
>           /* Section type */
>           qemu_put_byte(f, QEMU_VM_SECTION_END);
>           qemu_put_be32(f, se->section_id);
>
>           se->save_live_state(mon, f, QEMU_VM_SECTION_END, se->opaque);
> +        STOP_SAVEVM_CLOCK();
> +        DPRINTF("save live end section id %u name %s took %ld milliseconds\n",
> +		se->section_id, se->idstr, stop);
>       }
>
> +    START_SAVEVM_CLOCK();
>       QTAILQ_FOREACH(se,&savevm_handlers, entry) {
>           int len;
>
> @@ -1542,12 +1577,14 @@ int qemu_savevm_state_complete(Monitor *mon, QEMUFile *f)
>           qemu_put_be32(f, se->version_id);
>
>           r = vmstate_save(f, se);
> +        DPRINTF("save section id %u name %s\n", se->section_id, se->idstr);
>           if (r<  0) {
>               monitor_printf(mon, "cannot migrate with device '%s'\n", se->idstr);
>               return r;
>           }
>       }
> -
> +    STOP_SAVEVM_CLOCK();
> +    DPRINTF("save devices took %ld milliseconds\n", stop);
>       qemu_put_byte(f, QEMU_VM_EOF);
>
>       if (qemu_file_has_error(f))
> @@ -1746,8 +1783,11 @@ int qemu_loadvm_state(QEMUFile *f)
>               le->section_id = section_id;
>               le->version_id = version_id;
>               QLIST_INSERT_HEAD(&loadvm_handlers, le, entry);
> -
> +            START_SAVEVM_CLOCK();
>               ret = vmstate_load(f, le->se, le->version_id);
> +            STOP_SAVEVM_CLOCK();
> +            DPRINTF("load section id %u name %s took %ld milliseconds\n", le->section_id,
> +		    le->se->idstr, stop);
>               if (ret<  0) {
>                   fprintf(stderr, "qemu: warning: error while loading state for instance 0x%x of device '%s'\n",
>                           instance_id, idstr);
> @@ -1769,7 +1809,11 @@ int qemu_loadvm_state(QEMUFile *f)
>                   goto out;
>               }
>
> +            START_SAVEVM_CLOCK();
>               ret = vmstate_load(f, le->se, le->version_id);
> +            STOP_SAVEVM_CLOCK();
> +            DPRINTF("load section id %u name %s took %ld milliseconds\n", le->section_id,
> +		    le->se->idstr, stop);
>               if (ret<  0) {
>                   fprintf(stderr, "qemu: warning: error while loading state section id %d\n",
>                           section_id);
>    

Yeah, all of this should be done via tracing.  Maybe Stefan can make 
some suggestions.

Regards,

Anthony Liguori

On Mon, Nov 29, 2010 at 08:00:18PM -0600, Anthony Liguori wrote:
> Yeah, all of this should be done via tracing.  Maybe Stefan can make
> some suggestions.

Here is an example of how to record savevm timestamps using tracing.
Actually the timestamp is recorded automatically when a trace event
fires.

Add these to the trace-events file:
savevm_start(void) ""
savevm_stop(unsigned int section_id) "section_id %u"

Then use trace_savevm_start() instead of START_SAVEVM_CLOCK() and
trace_savevm_stop() instead of STOP_SAVEVM_CLOCK() in savevm.c.  Also
#include "trace.h".

All the macros and inline timestamp analysis can be removed from
savevm.c.

./configure --trace-backend=simple [...]
make

After running savevm look for the trace-<pid> file that QEMU produces in
its current working directory.  You can pretty-print it like this:
./simpletrace.py trace-events trace-<pid>

The second field in the simpletrace.py output is the time delta (in
microseconds) since the last trace event.  So you can easily see how
long start->stop took.

For more info see docs/tracing.txt.  You might prefer to use SystemTap
(./configure --trace-backend=dtrace) so you can write stap scripts to do
more powerful analysis.

Stefan

Stefan Hajnoczi <stefanha@linux.vnet.ibm.com> wrote:
> On Mon, Nov 29, 2010 at 08:00:18PM -0600, Anthony Liguori wrote:
>> Yeah, all of this should be done via tracing.  Maybe Stefan can make
>> some suggestions.
>
> Here is an example of how to record savevm timestamps using tracing.
> Actually the timestamp is recorded automatically when a trace event
> fires.
>
> Add these to the trace-events file:
> savevm_start(void) ""
> savevm_stop(unsigned int section_id) "section_id %u"
>
> Then use trace_savevm_start() instead of START_SAVEVM_CLOCK() and
> trace_savevm_stop() instead of STOP_SAVEVM_CLOCK() in savevm.c.  Also
> #include "trace.h".
>
> All the macros and inline timestamp analysis can be removed from
> savevm.c.
>
> ./configure --trace-backend=simple [...]
> make
>
> After running savevm look for the trace-<pid> file that QEMU produces in
> its current working directory.  You can pretty-print it like this:
> ./simpletrace.py trace-events trace-<pid>
>
> The second field in the simpletrace.py output is the time delta (in
> microseconds) since the last trace event.  So you can easily see how
> long start->stop took.
>
> For more info see docs/tracing.txt.  You might prefer to use SystemTap
> (./configure --trace-backend=dtrace) so you can write stap scripts to do
> more powerful analysis.

Thanks.

Searching for guru, I basically want to only print the values when the
difference is bigger that some values (number of calls is really big, I
need to learn how to script the analisys).

But clearly this "have to be" easier than change printf's and ifs and
rerun the test.

Later, Juan.

> Stefan

On Tue, Nov 30, 2010 at 11:40:36PM +0100, Juan Quintela wrote:
> Stefan Hajnoczi <stefanha@linux.vnet.ibm.com> wrote:
> > On Mon, Nov 29, 2010 at 08:00:18PM -0600, Anthony Liguori wrote:
> >> Yeah, all of this should be done via tracing.  Maybe Stefan can make
> >> some suggestions.
> >
> > Here is an example of how to record savevm timestamps using tracing.
> > Actually the timestamp is recorded automatically when a trace event
> > fires.
> >
> > Add these to the trace-events file:
> > savevm_start(void) ""
> > savevm_stop(unsigned int section_id) "section_id %u"
> >
> > Then use trace_savevm_start() instead of START_SAVEVM_CLOCK() and
> > trace_savevm_stop() instead of STOP_SAVEVM_CLOCK() in savevm.c.  Also
> > #include "trace.h".
> >
> > All the macros and inline timestamp analysis can be removed from
> > savevm.c.
> >
> > ./configure --trace-backend=simple [...]
> > make
> >
> > After running savevm look for the trace-<pid> file that QEMU produces in
> > its current working directory.  You can pretty-print it like this:
> > ./simpletrace.py trace-events trace-<pid>
> >
> > The second field in the simpletrace.py output is the time delta (in
> > microseconds) since the last trace event.  So you can easily see how
> > long start->stop took.
> >
> > For more info see docs/tracing.txt.  You might prefer to use SystemTap
> > (./configure --trace-backend=dtrace) so you can write stap scripts to do
> > more powerful analysis.
> 
> Thanks.
> 
> Searching for guru, I basically want to only print the values when the
> difference is bigger that some values (number of calls is really big, I
> need to learn how to script the analisys).

You can use awk(1) on the simpletrace.py output:
$1 ~ /savevm_stop/ {
	/* Print savevm_stop line when >100 ms duration */
	if ($2 > 100000) {
		printf("%s times_missing=%u\n", $0, times_missing++);
	}
}

Or you can use --trace-backend=dtrace and write SystemTap scripts:
http://sourceware.org/systemtap/SystemTap_Beginners_Guide/
http://sourceware.org/systemtap/langref/

Stefan