[Qemu-devel] [PATCH v2 0/4] block: Convert from DPRINTF() macro to trace event

[Qemu-devel] [PATCH v2 0/4] block: Convert from DPRINTF() macro to trace event

[Laurent Vivier]

Convert all the remaining uses of DPRINTF() in the directory block.

Compiled for all target but only tested with "make check"

v2: replace "sd_" prefix by "sheepdog_"
    remove the dot at the end of the text strings
    use %zu with size_t
    change an uint64_t to int64_t to match % PRIi64

Laurent Vivier (4):
  block/ssh: Convert from DPRINTF() macro to trace events
  block/curl: Convert from DPRINTF() macro to trace events
  block/file-posix: Convert from DPRINTF() macro to trace events
  block/sheepdog: Convert from DPRINTF() macro to trace events

 block/curl.c       | 29 ++++++++--------------------
 block/file-posix.c | 25 ++++++------------------
 block/sheepdog.c   | 47 +++++++++++++++++-----------------------------
 block/ssh.c        | 46 +++++++++++++++++----------------------------
 block/trace-events | 47 ++++++++++++++++++++++++++++++++++++++++++++++
 5 files changed, 95 insertions(+), 99 deletions(-)

-- 
2.19.2

[Qemu-devel] [PATCH v2 1/4] block/ssh: Convert from DPRINTF() macro to trace events

[Laurent Vivier]

Signed-off-by: Laurent Vivier <lvivier@redhat.com>
Reviewed-by: Richard W.M. Jones <rjones@redhat.com>
Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
---

Notes:
    v2: use %zu with size_t
        change an uint64_t to int64_t to match % PRIi64

 block/ssh.c        | 46 +++++++++++++++++-----------------------------
 block/trace-events | 17 +++++++++++++++++
 2 files changed, 34 insertions(+), 29 deletions(-)

diff --git a/block/ssh.c b/block/ssh.c
index 7fbc27abdf..bbc513e095 100644
--- a/block/ssh.c
+++ b/block/ssh.c
@@ -41,27 +41,17 @@
 #include "qapi/qmp/qstring.h"
 #include "qapi/qobject-input-visitor.h"
 #include "qapi/qobject-output-visitor.h"
+#include "trace.h"
 
-/* DEBUG_SSH=1 enables the DPRINTF (debugging printf) statements in
- * this block driver code.
- *
+/*
  * TRACE_LIBSSH2=<bitmask> enables tracing in libssh2 itself.  Note
  * that this requires that libssh2 was specially compiled with the
  * `./configure --enable-debug' option, so most likely you will have
  * to compile it yourself.  The meaning of <bitmask> is described
  * here: http://www.libssh2.org/libssh2_trace.html
  */
-#define DEBUG_SSH     0
 #define TRACE_LIBSSH2 0 /* or try: LIBSSH2_TRACE_SFTP */
 
-#define DPRINTF(fmt, ...)                           \
-    do {                                            \
-        if (DEBUG_SSH) {                            \
-            fprintf(stderr, "ssh: %-15s " fmt "\n", \
-                    __func__, ##__VA_ARGS__);       \
-        }                                           \
-    } while (0)
-
 typedef struct BDRVSSHState {
     /* Coroutine. */
     CoMutex lock;
@@ -336,7 +326,7 @@ static int check_host_key_knownhosts(BDRVSSHState *s,
     switch (r) {
     case LIBSSH2_KNOWNHOST_CHECK_MATCH:
         /* OK */
-        DPRINTF("host key OK: %s", found->key);
+        trace_ssh_check_host_key_knownhosts(found->key);
         break;
     case LIBSSH2_KNOWNHOST_CHECK_MISMATCH:
         ret = -EINVAL;
@@ -721,8 +711,7 @@ static int connect_to_ssh(BDRVSSHState *s, BlockdevOptionsSsh *opts,
     }
 
     /* Open the remote file. */
-    DPRINTF("opening file %s flags=0x%x creat_mode=0%o",
-            opts->path, ssh_flags, creat_mode);
+    trace_ssh_connect_to_ssh(opts->path, ssh_flags, creat_mode);
     s->sftp_handle = libssh2_sftp_open(s->sftp, opts->path, ssh_flags,
                                        creat_mode);
     if (!s->sftp_handle) {
@@ -890,7 +879,7 @@ static int coroutine_fn ssh_co_create_opts(const char *filename, QemuOpts *opts,
     /* Get desired file size. */
     ssh_opts->size = ROUND_UP(qemu_opt_get_size_del(opts, BLOCK_OPT_SIZE, 0),
                               BDRV_SECTOR_SIZE);
-    DPRINTF("total_size=%" PRIi64, ssh_opts->size);
+    trace_ssh_co_create_opts(ssh_opts->size);
 
     uri_options = qdict_new();
     ret = parse_uri(filename, uri_options, errp);
@@ -946,7 +935,7 @@ static void restart_coroutine(void *opaque)
     BDRVSSHState *s = bs->opaque;
     AioContext *ctx = bdrv_get_aio_context(bs);
 
-    DPRINTF("co=%p", restart->co);
+    trace_ssh_restart_coroutine(restart->co);
     aio_set_fd_handler(ctx, s->sock, false, NULL, NULL, NULL, NULL);
 
     aio_co_wake(restart->co);
@@ -974,13 +963,12 @@ static coroutine_fn void co_yield(BDRVSSHState *s, BlockDriverState *bs)
         wr_handler = restart_coroutine;
     }
 
-    DPRINTF("s->sock=%d rd_handler=%p wr_handler=%p", s->sock,
-            rd_handler, wr_handler);
+    trace_ssh_co_yield(s->sock, rd_handler, wr_handler);
 
     aio_set_fd_handler(bdrv_get_aio_context(bs), s->sock,
                        false, rd_handler, wr_handler, NULL, &restart);
     qemu_coroutine_yield();
-    DPRINTF("s->sock=%d - back", s->sock);
+    trace_ssh_co_yield_back(s->sock);
 }
 
 /* SFTP has a function `libssh2_sftp_seek64' which seeks to a position
@@ -1003,7 +991,7 @@ static void ssh_seek(BDRVSSHState *s, int64_t offset, int flags)
     bool force = (flags & SSH_SEEK_FORCE) != 0;
 
     if (force || op_read != s->offset_op_read || offset != s->offset) {
-        DPRINTF("seeking to offset=%" PRIi64, offset);
+        trace_ssh_seek(offset);
         libssh2_sftp_seek64(s->sftp_handle, offset);
         s->offset = offset;
         s->offset_op_read = op_read;
@@ -1019,7 +1007,7 @@ static coroutine_fn int ssh_read(BDRVSSHState *s, BlockDriverState *bs,
     char *buf, *end_of_vec;
     struct iovec *i;
 
-    DPRINTF("offset=%" PRIi64 " size=%zu", offset, size);
+    trace_ssh_read(offset, size);
 
     ssh_seek(s, offset, SSH_SEEK_READ);
 
@@ -1038,9 +1026,9 @@ static coroutine_fn int ssh_read(BDRVSSHState *s, BlockDriverState *bs,
      */
     for (got = 0; got < size; ) {
     again:
-        DPRINTF("sftp_read buf=%p size=%zu", buf, end_of_vec - buf);
+        trace_ssh_read_buf(buf, end_of_vec - buf);
         r = libssh2_sftp_read(s->sftp_handle, buf, end_of_vec - buf);
-        DPRINTF("sftp_read returned %zd", r);
+        trace_ssh_read_return(r);
 
         if (r == LIBSSH2_ERROR_EAGAIN || r == LIBSSH2_ERROR_TIMEOUT) {
             co_yield(s, bs);
@@ -1094,7 +1082,7 @@ static int ssh_write(BDRVSSHState *s, BlockDriverState *bs,
     char *buf, *end_of_vec;
     struct iovec *i;
 
-    DPRINTF("offset=%" PRIi64 " size=%zu", offset, size);
+    trace_ssh_write(offset, size);
 
     ssh_seek(s, offset, SSH_SEEK_WRITE);
 
@@ -1108,9 +1096,9 @@ static int ssh_write(BDRVSSHState *s, BlockDriverState *bs,
 
     for (written = 0; written < size; ) {
     again:
-        DPRINTF("sftp_write buf=%p size=%zu", buf, end_of_vec - buf);
+        trace_ssh_write_buf(buf, end_of_vec - buf);
         r = libssh2_sftp_write(s->sftp_handle, buf, end_of_vec - buf);
-        DPRINTF("sftp_write returned %zd", r);
+        trace_ssh_write_return(r);
 
         if (r == LIBSSH2_ERROR_EAGAIN || r == LIBSSH2_ERROR_TIMEOUT) {
             co_yield(s, bs);
@@ -1187,7 +1175,7 @@ static coroutine_fn int ssh_flush(BDRVSSHState *s, BlockDriverState *bs)
 {
     int r;
 
-    DPRINTF("fsync");
+    trace_ssh_flush();
  again:
     r = libssh2_sftp_fsync(s->sftp_handle);
     if (r == LIBSSH2_ERROR_EAGAIN || r == LIBSSH2_ERROR_TIMEOUT) {
@@ -1238,7 +1226,7 @@ static int64_t ssh_getlength(BlockDriverState *bs)
 
     /* Note we cannot make a libssh2 call here. */
     length = (int64_t) s->attrs.filesize;
-    DPRINTF("length=%" PRIi64, length);
+    trace_ssh_getlength(length);
 
     return length;
 }
diff --git a/block/trace-events b/block/trace-events
index 3e8c47bb24..e1dfd9713a 100644
--- a/block/trace-events
+++ b/block/trace-events
@@ -156,3 +156,20 @@ nvme_cmd_map_qiov_iov(void *s, int i, void *page, int pages) "s %p iov[%d] %p pa
 
 # block/iscsi.c
 iscsi_xcopy(void *src_lun, uint64_t src_off, void *dst_lun, uint64_t dst_off, uint64_t bytes, int ret) "src_lun %p offset %"PRIu64" dst_lun %p offset %"PRIu64" bytes %"PRIu64" ret %d"
+
+# block/ssh.c
+ssh_restart_coroutine(void *co) "co=%p"
+ssh_flush(void) "fsync"
+ssh_check_host_key_knownhosts(const char *key) "host key OK: %s"
+ssh_connect_to_ssh(char *path, int flags, int mode) "opening file %s flags=0x%x creat_mode=0%o"
+ssh_co_yield(int sock, void *rd_handler, void *wr_handler) "s->sock=%d rd_handler=%p wr_handler=%p"
+ssh_co_yield_back(int sock) "s->sock=%d - back"
+ssh_getlength(int64_t length) "length=%" PRIi64
+ssh_co_create_opts(uint64_t size) "total_size=%" PRIu64
+ssh_read(int64_t offset, size_t size) "offset=%" PRIi64 " size=%zu"
+ssh_read_buf(void *buf, size_t size) "sftp_read buf=%p size=%zu"
+ssh_read_return(size_t ret) "sftp_read returned %zu"
+ssh_write(int64_t offset, size_t size) "offset=%" PRIi64 " size=%zu"
+ssh_write_buf(void *buf, size_t size) "sftp_write buf=%p size=%zu"
+ssh_write_return(size_t ret) "sftp_write returned %zu"
+ssh_seek(int64_t offset) "seeking to offset=%" PRIi64
-- 
2.19.2

Re: [Qemu-devel] [PATCH v2 1/4] block/ssh: Convert from DPRINTF() macro to trace events

[Eric Blake]

On 12/13/18 10:27 AM, Laurent Vivier wrote:
> Signed-off-by: Laurent Vivier <lvivier@redhat.com>
> Reviewed-by: Richard W.M. Jones <rjones@redhat.com>
> Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
> ---
> 
> Notes:
>      v2: use %zu with size_t
>          change an uint64_t to int64_t to match % PRIi64

Why PRIi64?  It's identical to PRId64, but the sources show a strong 
preference for %d over %i:

$ git grep PRIi[0-9] | wc
      25     172    1885
$ git grep PRId[0-9] | wc
     415    3991   40345

$ git grep '%i' | wc
     231    1664   18269
$ git grep '%d' | wc
    5492   46211  498225

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org

Re: [Qemu-devel] [PATCH v2 1/4] block/ssh: Convert from DPRINTF() macro to trace events

[Laurent Vivier]

On 13/12/2018 17:34, Eric Blake wrote:
> On 12/13/18 10:27 AM, Laurent Vivier wrote:
>> Signed-off-by: Laurent Vivier <lvivier@redhat.com>
>> Reviewed-by: Richard W.M. Jones <rjones@redhat.com>
>> Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
>> ---
>>
>> Notes:
>>      v2: use %zu with size_t
>>          change an uint64_t to int64_t to match % PRIi64
> 
> Why PRIi64?  It's identical to PRId64, but the sources show a strong
> preference for %d over %i:
> 
> $ git grep PRIi[0-9] | wc
>      25     172    1885
> $ git grep PRId[0-9] | wc
>     415    3991   40345
> 
> $ git grep '%i' | wc
>     231    1664   18269
> $ git grep '%d' | wc
>    5492   46211  498225
> 

Yes, you're right but I have only moved the existing format string[1] to
trace-event:

diff --git a/block/ssh.c b/block/ssh.c
--- a/block/ssh.c
+++ b/block/ssh.c
@@ -1003,7 +991,7 @@ static void ssh_seek(BDRVSSHState *s, int64_t
offset, int flags)
     bool force = (flags & SSH_SEEK_FORCE) != 0;

     if (force || op_read != s->offset_op_read || offset != s->offset) {
-        DPRINTF("seeking to offset=%" PRIi64, offset);
+        trace_ssh_seek(offset);

diff --git a/block/trace-events b/block/trace-events
--- a/block/trace-events
+++ b/block/trace-events
...
+ssh_seek(int64_t offset) "seeking to offset=%" PRIi64

Thanks,
Laurent
[1] in fact, I have a coccinelle script to do that automatically.

Re: [Qemu-devel] [PATCH v2 1/4] block/ssh: Convert from DPRINTF() macro to trace events

[Max Reitz]

On 13.12.18 17:27, Laurent Vivier wrote:
> Signed-off-by: Laurent Vivier <lvivier@redhat.com>
> Reviewed-by: Richard W.M. Jones <rjones@redhat.com>
> Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
> ---
> 
> Notes:
>     v2: use %zu with size_t
>         change an uint64_t to int64_t to match % PRIi64
> 
>  block/ssh.c        | 46 +++++++++++++++++-----------------------------
>  block/trace-events | 17 +++++++++++++++++
>  2 files changed, 34 insertions(+), 29 deletions(-)
> 
> diff --git a/block/ssh.c b/block/ssh.c
> index 7fbc27abdf..bbc513e095 100644
> --- a/block/ssh.c
> +++ b/block/ssh.c

[...]

> @@ -1038,9 +1026,9 @@ static coroutine_fn int ssh_read(BDRVSSHState *s, BlockDriverState *bs,
>       */
>      for (got = 0; got < size; ) {
>      again:
> -        DPRINTF("sftp_read buf=%p size=%zu", buf, end_of_vec - buf);
> +        trace_ssh_read_buf(buf, end_of_vec - buf);
>          r = libssh2_sftp_read(s->sftp_handle, buf, end_of_vec - buf);
> -        DPRINTF("sftp_read returned %zd", r);
> +        trace_ssh_read_return(r);

(Here...

>  
>          if (r == LIBSSH2_ERROR_EAGAIN || r == LIBSSH2_ERROR_TIMEOUT) {
>              co_yield(s, bs);

[...]

> @@ -1108,9 +1096,9 @@ static int ssh_write(BDRVSSHState *s, BlockDriverState *bs,
>  
>      for (written = 0; written < size; ) {
>      again:
> -        DPRINTF("sftp_write buf=%p size=%zu", buf, end_of_vec - buf);
> +        trace_ssh_write_buf(buf, end_of_vec - buf);
>          r = libssh2_sftp_write(s->sftp_handle, buf, end_of_vec - buf);
> -        DPRINTF("sftp_write returned %zd", r);
> +        trace_ssh_write_return(r);

...and here r is of type ssize_t)

>  
>          if (r == LIBSSH2_ERROR_EAGAIN || r == LIBSSH2_ERROR_TIMEOUT) {
>              co_yield(s, bs);

[...]

> diff --git a/block/trace-events b/block/trace-events
> index 3e8c47bb24..e1dfd9713a 100644
> --- a/block/trace-events
> +++ b/block/trace-events
> @@ -156,3 +156,20 @@ nvme_cmd_map_qiov_iov(void *s, int i, void *page, int pages) "s %p iov[%d] %p pa
>  
>  # block/iscsi.c
>  iscsi_xcopy(void *src_lun, uint64_t src_off, void *dst_lun, uint64_t dst_off, uint64_t bytes, int ret) "src_lun %p offset %"PRIu64" dst_lun %p offset %"PRIu64" bytes %"PRIu64" ret %d"
> +
> +# block/ssh.c
> +ssh_restart_coroutine(void *co) "co=%p"
> +ssh_flush(void) "fsync"
> +ssh_check_host_key_knownhosts(const char *key) "host key OK: %s"
> +ssh_connect_to_ssh(char *path, int flags, int mode) "opening file %s flags=0x%x creat_mode=0%o"
> +ssh_co_yield(int sock, void *rd_handler, void *wr_handler) "s->sock=%d rd_handler=%p wr_handler=%p"
> +ssh_co_yield_back(int sock) "s->sock=%d - back"
> +ssh_getlength(int64_t length) "length=%" PRIi64
> +ssh_co_create_opts(uint64_t size) "total_size=%" PRIu64
> +ssh_read(int64_t offset, size_t size) "offset=%" PRIi64 " size=%zu"
> +ssh_read_buf(void *buf, size_t size) "sftp_read buf=%p size=%zu"
> +ssh_read_return(size_t ret) "sftp_read returned %zu"

Shouldn't this be ssize_t and %zi/%zd?

> +ssh_write(int64_t offset, size_t size) "offset=%" PRIi64 " size=%zu"
> +ssh_write_buf(void *buf, size_t size) "sftp_write buf=%p size=%zu"
> +ssh_write_return(size_t ret) "sftp_write returned %zu"

Same here.

Max

> +ssh_seek(int64_t offset) "seeking to offset=%" PRIi6

Re: [Qemu-devel] [PATCH v2 1/4] block/ssh: Convert from DPRINTF() macro to trace events

[Philippe Mathieu-Daudé]

On 1/14/19 12:15 PM, Max Reitz wrote:
> On 13.12.18 17:27, Laurent Vivier wrote:
>> Signed-off-by: Laurent Vivier <lvivier@redhat.com>
>> Reviewed-by: Richard W.M. Jones <rjones@redhat.com>
>> Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
>> ---
>>
>> Notes:
>>     v2: use %zu with size_t
>>         change an uint64_t to int64_t to match % PRIi64
>>
>>  block/ssh.c        | 46 +++++++++++++++++-----------------------------
>>  block/trace-events | 17 +++++++++++++++++
>>  2 files changed, 34 insertions(+), 29 deletions(-)
>>
>> diff --git a/block/ssh.c b/block/ssh.c
>> index 7fbc27abdf..bbc513e095 100644
>> --- a/block/ssh.c
>> +++ b/block/ssh.c
> 
> [...]
> 
>> @@ -1038,9 +1026,9 @@ static coroutine_fn int ssh_read(BDRVSSHState *s, BlockDriverState *bs,
>>       */
>>      for (got = 0; got < size; ) {
>>      again:
>> -        DPRINTF("sftp_read buf=%p size=%zu", buf, end_of_vec - buf);
>> +        trace_ssh_read_buf(buf, end_of_vec - buf);
>>          r = libssh2_sftp_read(s->sftp_handle, buf, end_of_vec - buf);
>> -        DPRINTF("sftp_read returned %zd", r);
>> +        trace_ssh_read_return(r);
> 
> (Here...
> 
>>  
>>          if (r == LIBSSH2_ERROR_EAGAIN || r == LIBSSH2_ERROR_TIMEOUT) {
>>              co_yield(s, bs);
> 
> [...]
> 
>> @@ -1108,9 +1096,9 @@ static int ssh_write(BDRVSSHState *s, BlockDriverState *bs,
>>  
>>      for (written = 0; written < size; ) {
>>      again:
>> -        DPRINTF("sftp_write buf=%p size=%zu", buf, end_of_vec - buf);
>> +        trace_ssh_write_buf(buf, end_of_vec - buf);
>>          r = libssh2_sftp_write(s->sftp_handle, buf, end_of_vec - buf);
>> -        DPRINTF("sftp_write returned %zd", r);
>> +        trace_ssh_write_return(r);
> 
> ...and here r is of type ssize_t)
> 
>>  
>>          if (r == LIBSSH2_ERROR_EAGAIN || r == LIBSSH2_ERROR_TIMEOUT) {
>>              co_yield(s, bs);
> 
> [...]
> 
>> diff --git a/block/trace-events b/block/trace-events
>> index 3e8c47bb24..e1dfd9713a 100644
>> --- a/block/trace-events
>> +++ b/block/trace-events
>> @@ -156,3 +156,20 @@ nvme_cmd_map_qiov_iov(void *s, int i, void *page, int pages) "s %p iov[%d] %p pa
>>  
>>  # block/iscsi.c
>>  iscsi_xcopy(void *src_lun, uint64_t src_off, void *dst_lun, uint64_t dst_off, uint64_t bytes, int ret) "src_lun %p offset %"PRIu64" dst_lun %p offset %"PRIu64" bytes %"PRIu64" ret %d"
>> +
>> +# block/ssh.c
>> +ssh_restart_coroutine(void *co) "co=%p"
>> +ssh_flush(void) "fsync"
>> +ssh_check_host_key_knownhosts(const char *key) "host key OK: %s"
>> +ssh_connect_to_ssh(char *path, int flags, int mode) "opening file %s flags=0x%x creat_mode=0%o"
>> +ssh_co_yield(int sock, void *rd_handler, void *wr_handler) "s->sock=%d rd_handler=%p wr_handler=%p"
>> +ssh_co_yield_back(int sock) "s->sock=%d - back"
>> +ssh_getlength(int64_t length) "length=%" PRIi64
>> +ssh_co_create_opts(uint64_t size) "total_size=%" PRIu64
>> +ssh_read(int64_t offset, size_t size) "offset=%" PRIi64 " size=%zu"
>> +ssh_read_buf(void *buf, size_t size) "sftp_read buf=%p size=%zu"
>> +ssh_read_return(size_t ret) "sftp_read returned %zu"
> 
> Shouldn't this be ssize_t and %zi/%zd?

Oops good catch.

The codebase uses %zd:

$ git grep '%zi'|wc -l
0
$ git grep '%zd'|wc -l
90

Can you directly fix this when applying?

Thanks,

Phil.

> 
>> +ssh_write(int64_t offset, size_t size) "offset=%" PRIi64 " size=%zu"
>> +ssh_write_buf(void *buf, size_t size) "sftp_write buf=%p size=%zu"
>> +ssh_write_return(size_t ret) "sftp_write returned %zu"
> 
> Same here.
> 
> Max
> 
>> +ssh_seek(int64_t offset) "seeking to offset=%" PRIi6
> 

[Qemu-devel] [PATCH v2 2/4] block/curl: Convert from DPRINTF() macro to trace events

[Laurent Vivier]

Signed-off-by: Laurent Vivier <lvivier@redhat.com>
Reviewed-by: Richard W.M. Jones <rjones@redhat.com>
Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
---

Notes:
    v2: use %zu with size_t

 block/curl.c       | 29 ++++++++---------------------
 block/trace-events |  9 +++++++++
 2 files changed, 17 insertions(+), 21 deletions(-)

diff --git a/block/curl.c b/block/curl.c
index db5d2bd8ef..b7ac265d3a 100644
--- a/block/curl.c
+++ b/block/curl.c
@@ -32,22 +32,10 @@
 #include "crypto/secret.h"
 #include <curl/curl.h>
 #include "qemu/cutils.h"
+#include "trace.h"
 
-// #define DEBUG_CURL
 // #define DEBUG_VERBOSE
 
-#ifdef DEBUG_CURL
-#define DEBUG_CURL_PRINT 1
-#else
-#define DEBUG_CURL_PRINT 0
-#endif
-#define DPRINTF(fmt, ...)                                            \
-    do {                                                             \
-        if (DEBUG_CURL_PRINT) {                                      \
-            fprintf(stderr, fmt, ## __VA_ARGS__);                    \
-        }                                                            \
-    } while (0)
-
 #if LIBCURL_VERSION_NUM >= 0x071000
 /* The multi interface timer callback was introduced in 7.16.0 */
 #define NEED_CURL_TIMER_CALLBACK
@@ -154,7 +142,7 @@ static int curl_timer_cb(CURLM *multi, long timeout_ms, void *opaque)
 {
     BDRVCURLState *s = opaque;
 
-    DPRINTF("CURL: timer callback timeout_ms %ld\n", timeout_ms);
+    trace_curl_timer_cb(timeout_ms);
     if (timeout_ms == -1) {
         timer_del(&s->timer);
     } else {
@@ -193,7 +181,7 @@ static int curl_sock_cb(CURL *curl, curl_socket_t fd, int action,
     }
     socket = NULL;
 
-    DPRINTF("CURL (AIO): Sock action %d on fd %d\n", action, (int)fd);
+    trace_curl_sock_cb(action, (int)fd);
     switch (action) {
         case CURL_POLL_IN:
             aio_set_fd_handler(s->aio_context, fd, false,
@@ -238,7 +226,7 @@ static size_t curl_read_cb(void *ptr, size_t size, size_t nmemb, void *opaque)
     size_t realsize = size * nmemb;
     int i;
 
-    DPRINTF("CURL: Just reading %zd bytes\n", realsize);
+    trace_curl_read_cb(realsize);
 
     if (!s || !s->orig_buf) {
         goto read_end;
@@ -777,7 +765,7 @@ static int curl_open(BlockDriverState *bs, QDict *options, int flags,
         }
     }
 
-    DPRINTF("CURL: Opening %s\n", file);
+    trace_curl_open(file);
     qemu_co_queue_init(&s->free_state_waitq);
     s->aio_context = bdrv_get_aio_context(bs);
     s->url = g_strdup(file);
@@ -830,7 +818,7 @@ static int curl_open(BlockDriverState *bs, QDict *options, int flags,
                 "Server does not support 'range' (byte ranges).");
         goto out;
     }
-    DPRINTF("CURL: Size = %" PRIu64 "\n", s->len);
+    trace_curl_open_size(s->len);
 
     qemu_mutex_lock(&s->mutex);
     curl_clean_state(state);
@@ -908,8 +896,7 @@ static void curl_setup_preadv(BlockDriverState *bs, CURLAIOCB *acb)
     state->acb[0] = acb;
 
     snprintf(state->range, 127, "%" PRIu64 "-%" PRIu64, start, end);
-    DPRINTF("CURL (AIO): Reading %" PRIu64 " at %" PRIu64 " (%s)\n",
-            acb->bytes, start, state->range);
+    trace_curl_setup_preadv(acb->bytes, start, state->range);
     curl_easy_setopt(state->curl, CURLOPT_RANGE, state->range);
 
     curl_multi_add_handle(s->multi, state->curl);
@@ -943,7 +930,7 @@ static void curl_close(BlockDriverState *bs)
 {
     BDRVCURLState *s = bs->opaque;
 
-    DPRINTF("CURL: Close\n");
+    trace_curl_close();
     curl_detach_aio_context(bs);
     qemu_mutex_destroy(&s->mutex);
 
diff --git a/block/trace-events b/block/trace-events
index e1dfd9713a..128ac2dd93 100644
--- a/block/trace-events
+++ b/block/trace-events
@@ -173,3 +173,12 @@ ssh_write(int64_t offset, size_t size) "offset=%" PRIi64 " size=%zu"
 ssh_write_buf(void *buf, size_t size) "sftp_write buf=%p size=%zu"
 ssh_write_return(size_t ret) "sftp_write returned %zu"
 ssh_seek(int64_t offset) "seeking to offset=%" PRIi64
+
+# block/curl.c
+curl_timer_cb(long timeout_ms) "timer callback timeout_ms %ld"
+curl_sock_cb(int action, int fd) "sock action %d on fd %d"
+curl_read_cb(size_t realsize) "just reading %zu bytes"
+curl_open(const char *file) "opening %s"
+curl_open_size(uint64_t size) "size = %" PRIu64
+curl_setup_preadv(uint64_t bytes, uint64_t start, const char *range) "reading %" PRIu64 " at %" PRIu64 " (%s)"
+curl_close(void) "close"
-- 
2.19.2

[Qemu-devel] [PATCH v2 3/4] block/file-posix: Convert from DPRINTF() macro to trace events

[Laurent Vivier]

Signed-off-by: Laurent Vivier <lvivier@redhat.com>
Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
---
 block/file-posix.c | 25 ++++++-------------------
 block/trace-events |  7 +++++++
 2 files changed, 13 insertions(+), 19 deletions(-)

diff --git a/block/file-posix.c b/block/file-posix.c
index 07bbdab953..cf90899a6e 100644
--- a/block/file-posix.c
+++ b/block/file-posix.c
@@ -102,19 +102,7 @@
 #include <xfs/xfs.h>
 #endif
 
-//#define DEBUG_BLOCK
-
-#ifdef DEBUG_BLOCK
-# define DEBUG_BLOCK_PRINT 1
-#else
-# define DEBUG_BLOCK_PRINT 0
-#endif
-#define DPRINTF(fmt, ...) \
-do { \
-    if (DEBUG_BLOCK_PRINT) { \
-        printf(fmt, ## __VA_ARGS__); \
-    } \
-} while (0)
+#include "trace.h"
 
 /* OS X does not have O_DSYNC */
 #ifndef O_DSYNC
@@ -1386,7 +1374,7 @@ static int xfs_write_zeroes(BDRVRawState *s, int64_t offset, uint64_t bytes)
 
     if (xfsctl(NULL, s->fd, XFS_IOC_ZERO_RANGE, &fl) < 0) {
         err = errno;
-        DPRINTF("cannot write zero range (%s)\n", strerror(errno));
+        trace_file_xfs_write_zeroes(strerror(errno));
         return -err;
     }
 
@@ -1405,7 +1393,7 @@ static int xfs_discard(BDRVRawState *s, int64_t offset, uint64_t bytes)
 
     if (xfsctl(NULL, s->fd, XFS_IOC_UNRESVSP64, &fl) < 0) {
         err = errno;
-        DPRINTF("cannot punch hole (%s)\n", strerror(errno));
+        trace_file_xfs_discard(strerror(errno));
         return -err;
     }
 
@@ -2798,7 +2786,7 @@ static char *FindEjectableOpticalMedia(io_iterator_t *mediaIterator)
 
         /* If a match was found, leave the loop */
         if (*mediaIterator != 0) {
-            DPRINTF("Matching using %s\n", matching_array[index]);
+            trace_file_FindEjectableOpticalMedia(matching_array[index]);
             mediaType = g_strdup(matching_array[index]);
             break;
         }
@@ -2858,7 +2846,7 @@ static bool setup_cdrom(char *bsd_path, Error **errp)
     if (partition_found == false) {
         error_setg(errp, "Failed to find a working partition on disc");
     } else {
-        DPRINTF("Using %s as optical disc\n", test_partition);
+        trace_file_setup_cdrom(test_partition);
         pstrcpy(bsd_path, MAXPATHLEN, test_partition);
     }
     return partition_found;
@@ -2953,8 +2941,7 @@ static bool hdev_is_sg(BlockDriverState *bs)
 
     ret = ioctl(s->fd, SG_GET_SCSI_ID, &scsiid);
     if (ret >= 0) {
-        DPRINTF("SG device found: type=%d, version=%d\n",
-            scsiid.scsi_type, sg_version);
+        trace_file_hdev_is_sg(scsiid.scsi_type, sg_version);
         return true;
     }
 
diff --git a/block/trace-events b/block/trace-events
index 128ac2dd93..06dbe65080 100644
--- a/block/trace-events
+++ b/block/trace-events
@@ -182,3 +182,10 @@ curl_open(const char *file) "opening %s"
 curl_open_size(uint64_t size) "size = %" PRIu64
 curl_setup_preadv(uint64_t bytes, uint64_t start, const char *range) "reading %" PRIu64 " at %" PRIu64 " (%s)"
 curl_close(void) "close"
+
+# block/file-posix.c
+file_xfs_write_zeroes(const char *error) "cannot write zero range (%s)"
+file_xfs_discard(const char* error) "cannot punch hole (%s)"
+file_FindEjectableOpticalMedia(const char *media) "Matching using %s"
+file_setup_cdrom(const char *partition) "Using %s as optical disc"
+file_hdev_is_sg(int type, int version) "SG device found: type=%d, version=%d"
-- 
2.19.2

[Qemu-devel] [PATCH v2 4/4] block/sheepdog: Convert from DPRINTF() macro to trace events

[Laurent Vivier]

Signed-off-by: Laurent Vivier <lvivier@redhat.com>
Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
---

Notes:
    v2: replace "sd_" prefix by "sheepdog_"
        remove the dot at the end of the text strings

 block/sheepdog.c   | 47 +++++++++++++++++-----------------------------
 block/trace-events | 14 ++++++++++++++
 2 files changed, 31 insertions(+), 30 deletions(-)

diff --git a/block/sheepdog.c b/block/sheepdog.c
index 0125df9d49..8b95cde01a 100644
--- a/block/sheepdog.c
+++ b/block/sheepdog.c
@@ -28,6 +28,7 @@
 #include "sysemu/block-backend.h"
 #include "qemu/bitops.h"
 #include "qemu/cutils.h"
+#include "trace.h"
 
 #define SD_PROTO_VER 0x01
 
@@ -299,19 +300,6 @@ static inline size_t count_data_objs(const struct SheepdogInode *inode)
                         (1UL << inode->block_size_shift));
 }
 
-#undef DPRINTF
-#ifdef DEBUG_SDOG
-#define DEBUG_SDOG_PRINT 1
-#else
-#define DEBUG_SDOG_PRINT 0
-#endif
-#define DPRINTF(fmt, args...)                                           \
-    do {                                                                \
-        if (DEBUG_SDOG_PRINT) {                                         \
-            fprintf(stderr, "%s %d: " fmt, __func__, __LINE__, ##args); \
-        }                                                               \
-    } while (0)
-
 typedef struct SheepdogAIOCB SheepdogAIOCB;
 typedef struct BDRVSheepdogState BDRVSheepdogState;
 
@@ -750,7 +738,7 @@ static coroutine_fn void reconnect_to_sdog(void *opaque)
         Error *local_err = NULL;
         s->fd = get_sheep_fd(s, &local_err);
         if (s->fd < 0) {
-            DPRINTF("Wait for connection to be established\n");
+            trace_sheepdog_reconnect_to_sdog();
             error_report_err(local_err);
             qemu_co_sleep_ns(QEMU_CLOCK_REALTIME, 1000000000ULL);
         }
@@ -847,7 +835,7 @@ static void coroutine_fn aio_read_response(void *opaque)
         break;
     case AIOCB_FLUSH_CACHE:
         if (rsp.result == SD_RES_INVALID_PARMS) {
-            DPRINTF("disable cache since the server doesn't support it\n");
+            trace_sheepdog_aio_read_response();
             s->cache_flags = SD_FLAG_CMD_DIRECT;
             rsp.result = SD_RES_SUCCESS;
         }
@@ -1639,7 +1627,7 @@ static int sd_open(BlockDriverState *bs, QDict *options, int flags,
     s->discard_supported = true;
 
     if (snap_id || tag[0]) {
-        DPRINTF("%" PRIx32 " snapshot inode was open.\n", vid);
+        trace_sheepdog_open(vid);
         s->is_snapshot = true;
     }
 
@@ -2252,7 +2240,7 @@ static void sd_close(BlockDriverState *bs)
     unsigned int wlen, rlen = 0;
     int fd, ret;
 
-    DPRINTF("%s\n", s->name);
+    trace_sheepdog_close(s->name);
 
     fd = connect_to_sdog(s, &local_err);
     if (fd < 0) {
@@ -2429,7 +2417,7 @@ static int sd_create_branch(BDRVSheepdogState *s)
     char *buf;
     bool deleted;
 
-    DPRINTF("%" PRIx32 " is snapshot.\n", s->inode.vdi_id);
+    trace_sheepdog_create_branch_snapshot(s->inode.vdi_id);
 
     buf = g_malloc(SD_INODE_SIZE);
 
@@ -2445,7 +2433,7 @@ static int sd_create_branch(BDRVSheepdogState *s)
         goto out;
     }
 
-    DPRINTF("%" PRIx32 " is created.\n", vid);
+    trace_sheepdog_create_branch_created(vid);
 
     fd = connect_to_sdog(s, &local_err);
     if (fd < 0) {
@@ -2467,7 +2455,7 @@ static int sd_create_branch(BDRVSheepdogState *s)
 
     s->is_snapshot = false;
     ret = 0;
-    DPRINTF("%" PRIx32 " was newly created.\n", s->inode.vdi_id);
+    trace_sheepdog_create_branch_new(s->inode.vdi_id);
 
 out:
     g_free(buf);
@@ -2561,11 +2549,11 @@ static void coroutine_fn sd_co_rw_vector(SheepdogAIOCB *acb)
         }
 
         if (create) {
-            DPRINTF("update ino (%" PRIu32 ") %" PRIu64 " %" PRIu64 " %ld\n",
-                    inode->vdi_id, oid,
-                    vid_to_data_oid(inode->data_vdi_id[idx], idx), idx);
+            trace_sheepdog_co_rw_vector_update(inode->vdi_id, oid,
+                                  vid_to_data_oid(inode->data_vdi_id[idx], idx),
+                                  idx);
             oid = vid_to_data_oid(inode->vdi_id, idx);
-            DPRINTF("new oid %" PRIx64 "\n", oid);
+            trace_sheepdog_co_rw_vector_new(oid);
         }
 
         aio_req = alloc_aio_req(s, acb, oid, len, offset, flags, create,
@@ -2670,9 +2658,8 @@ static int sd_snapshot_create(BlockDriverState *bs, QEMUSnapshotInfo *sn_info)
     SheepdogInode *inode;
     unsigned int datalen;
 
-    DPRINTF("sn_info: name %s id_str %s s: name %s vm_state_size %" PRId64 " "
-            "is_snapshot %d\n", sn_info->name, sn_info->id_str,
-            s->name, sn_info->vm_state_size, s->is_snapshot);
+    trace_sheepdog_snapshot_create_info(sn_info->name, sn_info->id_str, s->name,
+                                        sn_info->vm_state_size, s->is_snapshot);
 
     if (s->is_snapshot) {
         error_report("You can't create a snapshot of a snapshot VDI, "
@@ -2681,7 +2668,7 @@ static int sd_snapshot_create(BlockDriverState *bs, QEMUSnapshotInfo *sn_info)
         return -EINVAL;
     }
 
-    DPRINTF("%s %s\n", sn_info->name, sn_info->id_str);
+    trace_sheepdog_snapshot_create(sn_info->name, sn_info->id_str);
 
     s->inode.vm_state_size = sn_info->vm_state_size;
     s->inode.vm_clock_nsec = sn_info->vm_clock_nsec;
@@ -2726,8 +2713,8 @@ static int sd_snapshot_create(BlockDriverState *bs, QEMUSnapshotInfo *sn_info)
     }
 
     memcpy(&s->inode, inode, datalen);
-    DPRINTF("s->inode: name %s snap_id %x oid %x\n",
-            s->inode.name, s->inode.snap_id, s->inode.vdi_id);
+    trace_sheepdog_snapshot_create_inode(s->inode.name, s->inode.snap_id,
+                                         s->inode.vdi_id);
 
 cleanup:
     g_free(inode);
diff --git a/block/trace-events b/block/trace-events
index 06dbe65080..358c0e3c11 100644
--- a/block/trace-events
+++ b/block/trace-events
@@ -189,3 +189,17 @@ file_xfs_discard(const char* error) "cannot punch hole (%s)"
 file_FindEjectableOpticalMedia(const char *media) "Matching using %s"
 file_setup_cdrom(const char *partition) "Using %s as optical disc"
 file_hdev_is_sg(int type, int version) "SG device found: type=%d, version=%d"
+
+# block/sheepdog.c
+sheepdog_reconnect_to_sdog(void) "Wait for connection to be established"
+sheepdog_aio_read_response(void) "disable cache since the server doesn't support it"
+sheepdog_open(uint32_t vid) "0x%" PRIx32 " snapshot inode was open"
+sheepdog_close(const char *name) "%s"
+sheepdog_create_branch_snapshot(uint32_t vdi) "0x%" PRIx32 " is snapshot"
+sheepdog_create_branch_created(uint32_t vdi) "0x%" PRIx32 " is created"
+sheepdog_create_branch_new(uint32_t vdi) "0x%" PRIx32 " was newly created"
+sheepdog_co_rw_vector_update(uint32_t vdi, uint64_t oid, uint64_t data, long idx) "update ino (%" PRIu32 ") %" PRIu64 " %" PRIu64 " %ld"
+sheepdog_co_rw_vector_new(uint64_t oid) "new oid 0x%" PRIx64
+sheepdog_snapshot_create_info(const char *sn_name, const char *id, const char *name, int64_t size, int is_snapshot) "sn_info: name %s id_str %s s: name %s vm_state_size %" PRId64 " " "is_snapshot %d"
+sheepdog_snapshot_create(const char *sn_name, const char *id) "%s %s"
+sheepdog_snapshot_create_inode(const char *name, uint32_t snap, uint32_t vdi) "s->inode: name %s snap_id 0x%x vdi 0x%x"
-- 
2.19.2

Re: [Qemu-devel] [PATCH v2 4/4] block/sheepdog: Convert from DPRINTF() macro to trace events

[Max Reitz]

On 13.12.18 17:27, Laurent Vivier wrote:
> Signed-off-by: Laurent Vivier <lvivier@redhat.com>
> Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
> ---
> 
> Notes:
>     v2: replace "sd_" prefix by "sheepdog_"
>         remove the dot at the end of the text strings
> 
>  block/sheepdog.c   | 47 +++++++++++++++++-----------------------------
>  block/trace-events | 14 ++++++++++++++
>  2 files changed, 31 insertions(+), 30 deletions(-)
> 
> diff --git a/block/sheepdog.c b/block/sheepdog.c
> index 0125df9d49..8b95cde01a 100644
> --- a/block/sheepdog.c
> +++ b/block/sheepdog.c

[...]

> diff --git a/block/trace-events b/block/trace-events
> index 06dbe65080..358c0e3c11 100644
> --- a/block/trace-events
> +++ b/block/trace-events
> @@ -189,3 +189,17 @@ file_xfs_discard(const char* error) "cannot punch hole (%s)"

[...]

> +sheepdog_snapshot_create_inode(const char *name, uint32_t snap, uint32_t vdi) "s->inode: name %s snap_id 0x%x vdi 0x%x"

Good point in giving @snap and @vdi the correct types, but then the
format string should follow suit. :-)

Max

Re: [Qemu-devel] [PATCH v2 0/4] block: Convert from DPRINTF() macro to trace event

[Max Reitz]

On 13.12.18 17:27, Laurent Vivier wrote:
> Convert all the remaining uses of DPRINTF() in the directory block.
> 
> Compiled for all target but only tested with "make check"
> 
> v2: replace "sd_" prefix by "sheepdog_"
>     remove the dot at the end of the text strings
>     use %zu with size_t
>     change an uint64_t to int64_t to match % PRIi64
> 
> Laurent Vivier (4):
>   block/ssh: Convert from DPRINTF() macro to trace events
>   block/curl: Convert from DPRINTF() macro to trace events
>   block/file-posix: Convert from DPRINTF() macro to trace events
>   block/sheepdog: Convert from DPRINTF() macro to trace events

Applied to my block branch, with three fixes (Philippe asked me to do
one, so what are two more O:-)):
- Patch 1: Fixed ssh_{read,write}_return's @ret sign
- Patch 3: Moved the pointer asterisk in file_xfs_discard from type to name
- Patch 4: Fixed sheepdog_snapshot_create_inode's format string to use
PRIx32 instead of %x for uint32_ts

(https://git.xanclic.moe/XanClic/qemu/commits/branch/block)

Thanks!

Max

Re: [Qemu-devel] [PATCH v2 0/4] block: Convert from DPRINTF() macro to trace event

[Philippe Mathieu-Daudé]

On 1/14/19 1:14 PM, Max Reitz wrote:
> On 13.12.18 17:27, Laurent Vivier wrote:
>> Convert all the remaining uses of DPRINTF() in the directory block.
>>
>> Compiled for all target but only tested with "make check"
>>
>> v2: replace "sd_" prefix by "sheepdog_"
>>     remove the dot at the end of the text strings
>>     use %zu with size_t
>>     change an uint64_t to int64_t to match % PRIi64
>>
>> Laurent Vivier (4):
>>   block/ssh: Convert from DPRINTF() macro to trace events
>>   block/curl: Convert from DPRINTF() macro to trace events
>>   block/file-posix: Convert from DPRINTF() macro to trace events
>>   block/sheepdog: Convert from DPRINTF() macro to trace events
> 
> Applied to my block branch, with three fixes (Philippe asked me to do
> one, so what are two more O:-)):
> - Patch 1: Fixed ssh_{read,write}_return's @ret sign
> - Patch 3: Moved the pointer asterisk in file_xfs_discard from type to name
> - Patch 4: Fixed sheepdog_snapshot_create_inode's format string to use
> PRIx32 instead of %x for uint32_ts

Thank you Max!

> 
> (https://git.xanclic.moe/XanClic/qemu/commits/branch/block)
> 
> Thanks!
> 
> Max
>