Re: [Qemu-devel] [PATCH] qemu-nbd: add statistics

[Kevin Wolf <kwolf@redhat.com>]

Hi Laurent,

Am 05.10.2010 21:15, schrieb Laurent Vivier:
> During qemu-nbd run, I/O statistics can be now displayed using
> the option '-a N' where N is the number of seconds between each
> collect.
> 
> The statistics diplayed are : I/O per second, kilobytes read per second,
> kilobytes written per second, and the maximum values for each of them.
> 
> Example:
> 
> ...
> 0 io/s, 0 R kB/s 0 W kB/s (29 io/s, 59 R kB/s, 0 W kB/s)
> 123 io/s, 247 R kB/s 0 W kB/s (123 io/s, 247 R kB/s, 0 W kB/s)
> 145 io/s, 290 R kB/s 0 W kB/s (145 io/s, 290 R kB/s, 0 W kB/s)
> 383 io/s, 767 R kB/s 0 W kB/s (383 io/s, 767 R kB/s, 0 W kB/s)
> 273 io/s, 547 R kB/s 0 W kB/s (383 io/s, 767 R kB/s, 0 W kB/s)
> 2221 io/s, 4443 R kB/s 0 W kB/s (2221 io/s, 4443 R kB/s, 0 W kB/s)
> 0 io/s, 0 R kB/s 0 W kB/s (2221 io/s, 4443 R kB/s, 0 W kB/s)
> 0 io/s, 0 R kB/s 0 W kB/s (2221 io/s, 4443 R kB/s, 0 W kB/s)
> ...
> 
> Signed-off-by: Laurent Vivier <laurent@vivier.eu>
> ---
>  nbd.c      |   10 ++++++++
>  nbd.h      |    4 +++
>  qemu-nbd.c |   68 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++-
>  3 files changed, 80 insertions(+), 2 deletions(-)
> 
> diff --git a/nbd.c b/nbd.c
> index 4bf2eb7..730c514 100644
> --- a/nbd.c
> +++ b/nbd.c
> @@ -65,6 +65,12 @@
>  
>  #define NBD_OPT_EXPORT_NAME	(1 << 0)
>  
> +/* for I/O statistics */
> +
> +uint64_t nbd_stats_io = 0;
> +uint64_t nbd_stats_read = 0;
> +uint64_t nbd_stats_written = 0;
> +
>  /* That's all folks */
>  
>  #define read_sync(fd, buffer, size) nbd_wr_sync(fd, buffer, size, true)
> @@ -687,6 +693,8 @@ int nbd_trip(BlockDriverState *bs, int csock, off_t size, uint64_t dev_offset,
>  	switch (request.type) {
>  	case NBD_CMD_READ:
>  		TRACE("Request type is READ");
> +		nbd_stats_io++;
> +		nbd_stats_read += request.len;
>  
>  		if (bdrv_read(bs, (request.from + dev_offset) / 512,
>  			      data + NBD_REPLY_SIZE,
> @@ -721,6 +729,8 @@ int nbd_trip(BlockDriverState *bs, int csock, off_t size, uint64_t dev_offset,
>  		break;
>  	case NBD_CMD_WRITE:
>  		TRACE("Request type is WRITE");
> +		nbd_stats_io++;
> +		nbd_stats_written += request.len;
>  
>  		TRACE("Reading %u byte(s)", request.len);
>  
> diff --git a/nbd.h b/nbd.h
> index fc3a594..2d9457b 100644
> --- a/nbd.h
> +++ b/nbd.h
> @@ -44,6 +44,10 @@ enum {
>  
>  #define NBD_DEFAULT_PORT	10809
>  
> +extern uint64_t nbd_stats_io;
> +extern uint64_t nbd_stats_read;
> +extern uint64_t nbd_stats_written;
> +
>  size_t nbd_wr_sync(int fd, void *buffer, size_t size, bool do_read);
>  int tcp_socket_outgoing(const char *address, uint16_t port);
>  int tcp_socket_incoming(const char *address, uint16_t port);
> diff --git a/qemu-nbd.c b/qemu-nbd.c
> index 99f1d22..7626c37 100644
> --- a/qemu-nbd.c
> +++ b/qemu-nbd.c
> @@ -37,6 +37,7 @@
>  #define NBD_BUFFER_SIZE (1024*1024)
>  
>  static int verbose;
> +static int delay = 0;

I'd prefer calling this nbd_stat_delay or something. delay is relatively
unspecific for a global variable.

>  static void usage(const char *name)
>  {
> @@ -44,6 +45,7 @@ static void usage(const char *name)
>  "Usage: %s [OPTIONS] FILE\n"
>  "QEMU Disk Network Block Device Server\n"
>  "\n"
> +"  -a, --stats=N        display statistics every N seconds\n"
>  "  -p, --port=PORT      port to listen on (default `%d')\n"
>  "  -o, --offset=OFFSET  offset into the image\n"
>  "  -b, --bind=IFACE     interface to bind to (default `0.0.0.0')\n"
> @@ -180,6 +182,49 @@ static void show_parts(const char *device)
>      }
>  }
>  
> +static void nbd_stats(void)
> +{
> +	static struct timespec prev;
> +	static int first = 1;
> +	static uint64_t max_read = 0, max_written = 0, max_io = 0;
> +	struct timespec current;
> +	long seconds;
> +	uint64_t current_read = 0, current_written = 0, current_io = 0;
> +
> +	clock_gettime(CLOCK_MONOTONIC, &current);

I think there was a discussion recently that clock_gettime doesn't exist
everywhere. Is there a specific reason why qemu_gettimeofday() isn't
good enough here?

> +	if (first) {
> +		first = 0;
> +		prev = current;
> +		return;
> +	}
> +
> +	seconds = (current.tv_sec - prev.tv_sec) * 1000 +
> +                  (current.tv_nsec - prev.tv_nsec) / 1000000;

Despite the name of the variable, this looks like milliseconds.

> +
> +	if (seconds < delay * 1000)
> +		return;
> +
> +	current_io = nbd_stats_io * 1000 / seconds;
> +	if (current_io > max_io)
> +		max_io = current_io;
> +	current_read = nbd_stats_read * 1000 / seconds / 1024;
> +	if (current_read > max_read)
> +		max_read = current_read;
> +	current_written = nbd_stats_written * 1000 / seconds / 1024;
> +	if (current_written > max_written)
> +		max_written = current_written;
> +
> +	printf("%"PRIu64" io/s, %"PRIu64" R kB/s %"PRIu64" W kB/s "
> +               "(%"PRIu64" io/s, %"PRIu64" R kB/s, %"PRIu64" W kB/s)\n",

Maybe add a "max: " message in the brackets, so that users know what
this is supposed to mean?

> +		current_io, current_read, current_written,
> +		max_io, max_read, max_written);
> +
> +	nbd_stats_io = 0;
> +	nbd_stats_read = 0;
> +	nbd_stats_written = 0;
> +	prev = current;
> +}

Please use four spaces instead of tabs for indentation.

> +
>  int main(int argc, char **argv)
>  {
>      BlockDriverState *bs;
> @@ -195,11 +240,12 @@ int main(int argc, char **argv)
>      char *device = NULL;
>      char *socket = NULL;
>      char sockpath[128];
> -    const char *sopt = "hVb:o:p:rsnP:c:dvk:e:t";
> +    const char *sopt = "hVb:o:a:p:rsnP:c:dvk:e:t";
>      struct option lopt[] = {
>          { "help", 0, NULL, 'h' },
>          { "version", 0, NULL, 'V' },
>          { "bind", 1, NULL, 'b' },
> +        { "stats", 1, NULL, 'a' },
>          { "port", 1, NULL, 'p' },
>          { "socket", 1, NULL, 'k' },
>          { "offset", 1, NULL, 'o' },
> @@ -243,6 +289,15 @@ int main(int argc, char **argv)
>          case 'b':
>              bindto = optarg;
>              break;
> +        case 'a':
> +            delay = strtol(optarg, &end, 0);
> +            if (*end) {
> +                errx(EXIT_FAILURE, "Invalid statistics delay `%s'", optarg);
> +            }
> +            if (delay < 0) {
> +                errx(EXIT_FAILURE, "Statisctics delay must be positive `%s'", optarg);

Typo in the message ("Statisctics")

> +            }
> +            break;
>          case 'p':
>              li = strtol(optarg, &end, 0);
>              if (*end) {
> @@ -456,7 +511,16 @@ int main(int argc, char **argv)
>          for (i = 0; i < nb_fds; i++)
>              FD_SET(sharing_fds[i], &fds);
>  
> -        ret = select(max_fd + 1, &fds, NULL, NULL, NULL);
> +        if (delay) {
> +            struct timeval timeout;
> +
> +            nbd_stats();
> +            timeout.tv_sec = delay;
> +            timeout.tv_usec = 0;
> +            ret = select(max_fd + 1, &fds, NULL, NULL, &timeout);
> +        } else {
> +            ret = select(max_fd + 1, &fds, NULL, NULL, NULL);
> +        }

With some bad luck we can end up with almost 2*delay between two outputs
(request is processed with seconds = 1000 * delay - epsilon and then we
wait another delay seconds). I'm not sure if we really care, though.

Kevin