Tracify migration/rdma.c

Turn all the D/DD/DDDPRINTFs into trace events
Turn most of the fprintf(stderr, into error_report

Signed-off-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
Signed-off-by: Amit Shah <amit.shah@redhat.com>
Signed-off-by: Juan Quintela <quintela@redhat.com>

1 files changed, 144 insertions, 189 deletions

diff --git a/migration/rdma.c b/migration/rdma.c
index b32dbdf..fc351ea 100644
--- a/migration/rdma.c
+++ b/migration/rdma.c
@@ -26,34 +26,7 @@
 #include <arpa/inet.h>
 #include <string.h>
 #include <rdma/rdma_cma.h>
-
-//#define DEBUG_RDMA
-//#define DEBUG_RDMA_VERBOSE
-//#define DEBUG_RDMA_REALLY_VERBOSE
-
-#ifdef DEBUG_RDMA
-#define DPRINTF(fmt, ...) \
-    do { printf("rdma: " fmt, ## __VA_ARGS__); } while (0)
-#else
-#define DPRINTF(fmt, ...) \
-    do { } while (0)
-#endif
-
-#ifdef DEBUG_RDMA_VERBOSE
-#define DDPRINTF(fmt, ...) \
-    do { printf("rdma: " fmt, ## __VA_ARGS__); } while (0)
-#else
-#define DDPRINTF(fmt, ...) \
-    do { } while (0)
-#endif
-
-#ifdef DEBUG_RDMA_REALLY_VERBOSE
-#define DDDPRINTF(fmt, ...) \
-    do { printf("rdma: " fmt, ## __VA_ARGS__); } while (0)
-#else
-#define DDDPRINTF(fmt, ...) \
-    do { } while (0)
-#endif
+#include "trace.h"
 
 /*
  * Print and error on both the Monitor and the Log file.
@@ -104,8 +77,8 @@ static uint32_t known_capabilities = RDMA_CAPABILITY_PIN_ALL;
     do { \
         if (rdma->error_state) { \
             if (!rdma->error_reported) { \
-                fprintf(stderr, "RDMA is in an error state waiting migration" \
-                                " to abort!\n"); \
+                error_report("RDMA is in an error state waiting migration" \
+                                " to abort!"); \
                 rdma->error_reported = 1; \
             } \
             return rdma->error_state; \
@@ -578,12 +551,13 @@ static int __qemu_rdma_add_block(RDMAContext *rdma, void *host_addr,
 
     g_hash_table_insert(rdma->blockmap, (void *) block_offset, block);
 
-    DDPRINTF("Added Block: %d, addr: %" PRIu64 ", offset: %" PRIu64
-           " length: %" PRIu64 " end: %" PRIu64 " bits %" PRIu64 " chunks %d\n",
-            local->nb_blocks, (uint64_t) block->local_host_addr, block->offset,
-            block->length, (uint64_t) (block->local_host_addr + block->length),
-                BITS_TO_LONGS(block->nb_chunks) *
-                    sizeof(unsigned long) * 8, block->nb_chunks);
+    trace___qemu_rdma_add_block(local->nb_blocks,
+                           (uint64_t) block->local_host_addr, block->offset,
+                           block->length,
+                           (uint64_t) (block->local_host_addr + block->length),
+                           BITS_TO_LONGS(block->nb_chunks) *
+                               sizeof(unsigned long) * 8,
+                           block->nb_chunks);
 
     local->nb_blocks++;
 
@@ -614,7 +588,7 @@ static int qemu_rdma_init_ram_blocks(RDMAContext *rdma)
     rdma->blockmap = g_hash_table_new(g_direct_hash, g_direct_equal);
     memset(local, 0, sizeof *local);
     qemu_ram_foreach_block(qemu_rdma_init_one_block, rdma);
-    DPRINTF("Allocated %d local ram block structures\n", local->nb_blocks);
+    trace_qemu_rdma_init_ram_blocks(local->nb_blocks);
     rdma->block = (RDMARemoteBlock *) g_malloc0(sizeof(RDMARemoteBlock) *
                         rdma->local_ram_blocks.nb_blocks);
     local->init = true;
@@ -683,12 +657,12 @@ static int __qemu_rdma_delete_block(RDMAContext *rdma, ram_addr_t block_offset)
         local->block = NULL;
     }
 
-    DDPRINTF("Deleted Block: %d, addr: %" PRIu64 ", offset: %" PRIu64
-           " length: %" PRIu64 " end: %" PRIu64 " bits %" PRIu64 " chunks %d\n",
-            local->nb_blocks, (uint64_t) block->local_host_addr, block->offset,
-            block->length, (uint64_t) (block->local_host_addr + block->length),
-                BITS_TO_LONGS(block->nb_chunks) *
-                    sizeof(unsigned long) * 8, block->nb_chunks);
+    trace___qemu_rdma_delete_block(local->nb_blocks,
+                           (uint64_t)block->local_host_addr,
+                           block->offset, block->length,
+                           (uint64_t)(block->local_host_addr + block->length),
+                           BITS_TO_LONGS(block->nb_chunks) *
+                               sizeof(unsigned long) * 8, block->nb_chunks);
 
     g_free(old);
 
@@ -713,7 +687,7 @@ static void qemu_rdma_dump_id(const char *who, struct ibv_context *verbs)
     struct ibv_port_attr port;
 
     if (ibv_query_port(verbs, 1, &port)) {
-        fprintf(stderr, "FAILED TO QUERY PORT INFORMATION!\n");
+        error_report("Failed to query port information");
         return;
     }
 
@@ -744,7 +718,7 @@ static void qemu_rdma_dump_gid(const char *who, struct rdma_cm_id *id)
     char dgid[33];
     inet_ntop(AF_INET6, &id->route.addr.addr.ibaddr.sgid, sgid, sizeof sgid);
     inet_ntop(AF_INET6, &id->route.addr.addr.ibaddr.dgid, dgid, sizeof dgid);
-    DPRINTF("%s Source GID: %s, Dest GID: %s\n", who, sgid, dgid);
+    trace_qemu_rdma_dump_gid(who, sgid, dgid);
 }
 
 /*
@@ -918,7 +892,7 @@ static int qemu_rdma_resolve_host(RDMAContext *rdma, Error **errp)
     for (e = res; e != NULL; e = e->ai_next) {
         inet_ntop(e->ai_family,
             &((struct sockaddr_in *) e->ai_dst_addr)->sin_addr, ip, sizeof ip);
-        DPRINTF("Trying %s => %s\n", rdma->host, ip);
+        trace_qemu_rdma_resolve_host_trying(rdma->host, ip);
 
         ret = rdma_resolve_addr(rdma->cm_id, NULL, e->ai_dst_addr,
                 RDMA_RESOLVE_TIMEOUT_MS);
@@ -997,14 +971,14 @@ static int qemu_rdma_alloc_pd_cq(RDMAContext *rdma)
     /* allocate pd */
     rdma->pd = ibv_alloc_pd(rdma->verbs);
     if (!rdma->pd) {
-        fprintf(stderr, "failed to allocate protection domain\n");
+        error_report("failed to allocate protection domain");
         return -1;
     }
 
     /* create completion channel */
     rdma->comp_channel = ibv_create_comp_channel(rdma->verbs);
     if (!rdma->comp_channel) {
-        fprintf(stderr, "failed to allocate completion channel\n");
+        error_report("failed to allocate completion channel");
         goto err_alloc_pd_cq;
     }
 
@@ -1015,7 +989,7 @@ static int qemu_rdma_alloc_pd_cq(RDMAContext *rdma)
     rdma->cq = ibv_create_cq(rdma->verbs, (RDMA_SIGNALED_SEND_MAX * 3),
             NULL, rdma->comp_channel, 0);
     if (!rdma->cq) {
-        fprintf(stderr, "failed to allocate completion queue\n");
+        error_report("failed to allocate completion queue");
         goto err_alloc_pd_cq;
     }
 
@@ -1160,8 +1134,7 @@ static int qemu_rdma_register_and_get_keys(RDMAContext *rdma,
     if (!block->pmr[chunk]) {
         uint64_t len = chunk_end - chunk_start;
 
-        DDPRINTF("Registering %" PRIu64 " bytes @ %p\n",
-                 len, chunk_start);
+        trace_qemu_rdma_register_and_get_keys(len, chunk_start);
 
         block->pmr[chunk] = ibv_reg_mr(rdma->pd,
                 chunk_start, len,
@@ -1204,7 +1177,7 @@ static int qemu_rdma_reg_control(RDMAContext *rdma, int idx)
         rdma->total_registrations++;
         return 0;
     }
-    fprintf(stderr, "qemu_rdma_reg_control failed!\n");
+    error_report("qemu_rdma_reg_control failed");
     return -1;
 }
 
@@ -1270,8 +1243,8 @@ static int qemu_rdma_unregister_waiting(RDMAContext *rdma)
                                    .repeat = 1,
                                  };
 
-        DDPRINTF("Processing unregister for chunk: %" PRIu64
-                 " at position %d\n", chunk, rdma->unregister_current);
+        trace_qemu_rdma_unregister_waiting_proc(chunk,
+                                                rdma->unregister_current);
 
         rdma->unregistrations[rdma->unregister_current] = 0;
         rdma->unregister_current++;
@@ -1291,11 +1264,11 @@ static int qemu_rdma_unregister_waiting(RDMAContext *rdma)
         clear_bit(chunk, block->unregister_bitmap);
 
         if (test_bit(chunk, block->transit_bitmap)) {
-            DDPRINTF("Cannot unregister inflight chunk: %" PRIu64 "\n", chunk);
+            trace_qemu_rdma_unregister_waiting_inflight(chunk);
             continue;
         }
 
-        DDPRINTF("Sending unregister for chunk: %" PRIu64 "\n", chunk);
+        trace_qemu_rdma_unregister_waiting_send(chunk);
 
         ret = ibv_dereg_mr(block->pmr[chunk]);
         block->pmr[chunk] = NULL;
@@ -1315,7 +1288,7 @@ static int qemu_rdma_unregister_waiting(RDMAContext *rdma)
             return ret;
         }
 
-        DDPRINTF("Unregister for chunk: %" PRIu64 " complete.\n", chunk);
+        trace_qemu_rdma_unregister_waiting_complete(chunk);
     }
 
     return 0;
@@ -1340,13 +1313,13 @@ static void qemu_rdma_signal_unregister(RDMAContext *rdma, uint64_t index,
                                         uint64_t chunk, uint64_t wr_id)
 {
     if (rdma->unregistrations[rdma->unregister_next] != 0) {
-        fprintf(stderr, "rdma migration: queue is full!\n");
+        error_report("rdma migration: queue is full");
     } else {
         RDMALocalBlock *block = &(rdma->local_ram_blocks.block[index]);
 
         if (!test_and_set_bit(chunk, block->unregister_bitmap)) {
-            DDPRINTF("Appending unregister chunk %" PRIu64
-                    " at position %d\n", chunk, rdma->unregister_next);
+            trace_qemu_rdma_signal_unregister_append(chunk,
+                                                     rdma->unregister_next);
 
             rdma->unregistrations[rdma->unregister_next++] =
                     qemu_rdma_make_wrid(wr_id, index, chunk);
@@ -1355,8 +1328,7 @@ static void qemu_rdma_signal_unregister(RDMAContext *rdma, uint64_t index,
                 rdma->unregister_next = 0;
             }
         } else {
-            DDPRINTF("Unregister chunk %" PRIu64 " already in queue.\n",
-                    chunk);
+            trace_qemu_rdma_signal_unregister_already(chunk);
         }
     }
 }
@@ -1381,7 +1353,7 @@ static uint64_t qemu_rdma_poll(RDMAContext *rdma, uint64_t *wr_id_out,
     }
 
     if (ret < 0) {
-        fprintf(stderr, "ibv_poll_cq return %d!\n", ret);
+        error_report("ibv_poll_cq return %d", ret);
         return ret;
     }
 
@@ -1397,8 +1369,7 @@ static uint64_t qemu_rdma_poll(RDMAContext *rdma, uint64_t *wr_id_out,
 
     if (rdma->control_ready_expected &&
         (wr_id >= RDMA_WRID_RECV_CONTROL)) {
-        DDDPRINTF("completion %s #%" PRId64 " received (%" PRId64 ")"
-                  " left %d\n", wrid_desc[RDMA_WRID_RECV_CONTROL],
+        trace_qemu_rdma_poll_recv(wrid_desc[RDMA_WRID_RECV_CONTROL],
                   wr_id - RDMA_WRID_RECV_CONTROL, wr_id, rdma->nb_sent);
         rdma->control_ready_expected = 0;
     }
@@ -1410,9 +1381,8 @@ static uint64_t qemu_rdma_poll(RDMAContext *rdma, uint64_t *wr_id_out,
             (wc.wr_id & RDMA_WRID_BLOCK_MASK) >> RDMA_WRID_BLOCK_SHIFT;
         RDMALocalBlock *block = &(rdma->local_ram_blocks.block[index]);
 
-        DDDPRINTF("completions %s (%" PRId64 ") left %d, "
-                 "block %" PRIu64 ", chunk: %" PRIu64 " %p %p\n",
-                 print_wrid(wr_id), wr_id, rdma->nb_sent, index, chunk,
+        trace_qemu_rdma_poll_write(print_wrid(wr_id), wr_id, rdma->nb_sent,
+                 index, chunk,
                  block->local_host_addr, (void *)block->remote_host_addr);
 
         clear_bit(chunk, block->transit_bitmap);
@@ -1433,8 +1403,7 @@ static uint64_t qemu_rdma_poll(RDMAContext *rdma, uint64_t *wr_id_out,
 #endif
         }
     } else {
-        DDDPRINTF("other completion %s (%" PRId64 ") received left %d\n",
-            print_wrid(wr_id), wr_id, rdma->nb_sent);
+        trace_qemu_rdma_poll_other(print_wrid(wr_id), wr_id, rdma->nb_sent);
     }
 
     *wr_id_out = wc.wr_id;
@@ -1482,9 +1451,8 @@ static int qemu_rdma_block_for_wrid(RDMAContext *rdma, int wrid_requested,
             break;
         }
         if (wr_id != wrid_requested) {
-            DDDPRINTF("A Wanted wrid %s (%d) but got %s (%" PRIu64 ")\n",
-                print_wrid(wrid_requested),
-                wrid_requested, print_wrid(wr_id), wr_id);
+            trace_qemu_rdma_block_for_wrid_miss(print_wrid(wrid_requested),
+                       wrid_requested, print_wrid(wr_id), wr_id);
         }
     }
 
@@ -1524,9 +1492,8 @@ static int qemu_rdma_block_for_wrid(RDMAContext *rdma, int wrid_requested,
                 break;
             }
             if (wr_id != wrid_requested) {
-                DDDPRINTF("B Wanted wrid %s (%d) but got %s (%" PRIu64 ")\n",
-                    print_wrid(wrid_requested), wrid_requested,
-                    print_wrid(wr_id), wr_id);
+                trace_qemu_rdma_block_for_wrid_miss(print_wrid(wrid_requested),
+                                   wrid_requested, print_wrid(wr_id), wr_id);
             }
         }
 
@@ -1571,7 +1538,7 @@ static int qemu_rdma_post_send_control(RDMAContext *rdma, uint8_t *buf,
                                    .num_sge = 1,
                                 };
 
-    DDDPRINTF("CONTROL: sending %s..\n", control_desc[head->type]);
+    trace_qemu_rdma_post_send_control(control_desc[head->type]);
 
     /*
      * We don't actually need to do a memcpy() in here if we used
@@ -1593,13 +1560,13 @@ static int qemu_rdma_post_send_control(RDMAContext *rdma, uint8_t *buf,
     ret = ibv_post_send(rdma->qp, &send_wr, &bad_wr);
 
     if (ret > 0) {
-        fprintf(stderr, "Failed to use post IB SEND for control!\n");
+        error_report("Failed to use post IB SEND for control");
         return -ret;
     }
 
     ret = qemu_rdma_block_for_wrid(rdma, RDMA_WRID_SEND_CONTROL, NULL);
     if (ret < 0) {
-        fprintf(stderr, "rdma migration: send polling control error!\n");
+        error_report("rdma migration: send polling control error");
     }
 
     return ret;
@@ -1643,32 +1610,31 @@ static int qemu_rdma_exchange_get_response(RDMAContext *rdma,
                                        &byte_len);
 
     if (ret < 0) {
-        fprintf(stderr, "rdma migration: recv polling control error!\n");
+        error_report("rdma migration: recv polling control error!");
         return ret;
     }
 
     network_to_control((void *) rdma->wr_data[idx].control);
     memcpy(head, rdma->wr_data[idx].control, sizeof(RDMAControlHeader));
 
-    DDDPRINTF("CONTROL: %s receiving...\n", control_desc[expecting]);
+    trace_qemu_rdma_exchange_get_response_start(control_desc[expecting]);
 
     if (expecting == RDMA_CONTROL_NONE) {
-        DDDPRINTF("Surprise: got %s (%d)\n",
-                  control_desc[head->type], head->type);
+        trace_qemu_rdma_exchange_get_response_none(control_desc[head->type],
+                                             head->type);
     } else if (head->type != expecting || head->type == RDMA_CONTROL_ERROR) {
-        fprintf(stderr, "Was expecting a %s (%d) control message"
-                ", but got: %s (%d), length: %d\n",
+        error_report("Was expecting a %s (%d) control message"
+                ", but got: %s (%d), length: %d",
                 control_desc[expecting], expecting,
                 control_desc[head->type], head->type, head->len);
         return -EIO;
     }
     if (head->len > RDMA_CONTROL_MAX_BUFFER - sizeof(*head)) {
-        fprintf(stderr, "too long length: %d\n", head->len);
+        error_report("too long length: %d\n", head->len);
         return -EINVAL;
     }
     if (sizeof(*head) + head->len != byte_len) {
-        fprintf(stderr, "Malformed length: %d byte_len %d\n",
-                head->len, byte_len);
+        error_report("Malformed length: %d byte_len %d", head->len, byte_len);
         return -EINVAL;
     }
 
@@ -1730,7 +1696,7 @@ static int qemu_rdma_exchange_send(RDMAContext *rdma, RDMAControlHeader *head,
     if (resp) {
         ret = qemu_rdma_post_recv_control(rdma, RDMA_WRID_DATA);
         if (ret) {
-            fprintf(stderr, "rdma migration: error posting"
+            error_report("rdma migration: error posting"
                     " extra control recv for anticipated result!");
             return ret;
         }
@@ -1741,7 +1707,7 @@ static int qemu_rdma_exchange_send(RDMAContext *rdma, RDMAControlHeader *head,
      */
     ret = qemu_rdma_post_recv_control(rdma, RDMA_WRID_READY);
     if (ret) {
-        fprintf(stderr, "rdma migration: error posting first control recv!");
+        error_report("rdma migration: error posting first control recv!");
         return ret;
     }
 
@@ -1751,7 +1717,7 @@ static int qemu_rdma_exchange_send(RDMAContext *rdma, RDMAControlHeader *head,
     ret = qemu_rdma_post_send_control(rdma, data, head);
 
     if (ret < 0) {
-        fprintf(stderr, "Failed to send control buffer!\n");
+        error_report("Failed to send control buffer!");
         return ret;
     }
 
@@ -1760,14 +1726,14 @@ static int qemu_rdma_exchange_send(RDMAContext *rdma, RDMAControlHeader *head,
      */
     if (resp) {
         if (callback) {
-            DDPRINTF("Issuing callback before receiving response...\n");
+            trace_qemu_rdma_exchange_send_issue_callback();
             ret = callback(rdma);
             if (ret < 0) {
                 return ret;
             }
         }
 
-        DDPRINTF("Waiting for response %s\n", control_desc[resp->type]);
+        trace_qemu_rdma_exchange_send_waiting(control_desc[resp->type]);
         ret = qemu_rdma_exchange_get_response(rdma, resp,
                                               resp->type, RDMA_WRID_DATA);
 
@@ -1779,7 +1745,7 @@ static int qemu_rdma_exchange_send(RDMAContext *rdma, RDMAControlHeader *head,
         if (resp_idx) {
             *resp_idx = RDMA_WRID_DATA;
         }
-        DDPRINTF("Response %s received.\n", control_desc[resp->type]);
+        trace_qemu_rdma_exchange_send_received(control_desc[resp->type]);
     }
 
     rdma->control_ready_expected = 1;
@@ -1807,7 +1773,7 @@ static int qemu_rdma_exchange_recv(RDMAContext *rdma, RDMAControlHeader *head,
     ret = qemu_rdma_post_send_control(rdma, NULL, &ready);
 
     if (ret < 0) {
-        fprintf(stderr, "Failed to send control buffer!\n");
+        error_report("Failed to send control buffer!");
         return ret;
     }
 
@@ -1828,7 +1794,7 @@ static int qemu_rdma_exchange_recv(RDMAContext *rdma, RDMAControlHeader *head,
      */
     ret = qemu_rdma_post_recv_control(rdma, RDMA_WRID_READY);
     if (ret) {
-        fprintf(stderr, "rdma migration: error posting second control recv!");
+        error_report("rdma migration: error posting second control recv!");
         return ret;
     }
 
@@ -1882,8 +1848,9 @@ retry:
         }
     }
 
-    DDPRINTF("Writing %" PRIu64 " chunks, (%" PRIu64 " MB)\n",
-        chunks + 1, (chunks + 1) * (1UL << RDMA_REG_CHUNK_SHIFT) / 1024 / 1024);
+    trace_qemu_rdma_write_one_top(chunks + 1,
+                                  (chunks + 1) *
+                                  (1UL << RDMA_REG_CHUNK_SHIFT) / 1024 / 1024);
 
     chunk_end = ram_chunk_end(block, chunk + chunks);
 
@@ -1895,17 +1862,15 @@ retry:
 
     while (test_bit(chunk, block->transit_bitmap)) {
         (void)count;
-        DDPRINTF("(%d) Not clobbering: block: %d chunk %" PRIu64
-                " current %" PRIu64 " len %" PRIu64 " %d %d\n",
-                count++, current_index, chunk,
+        trace_qemu_rdma_write_one_block(count++, current_index, chunk,
                 sge.addr, length, rdma->nb_sent, block->nb_chunks);
 
         ret = qemu_rdma_block_for_wrid(rdma, RDMA_WRID_RDMA_WRITE, NULL);
 
         if (ret < 0) {
-            fprintf(stderr, "Failed to Wait for previous write to complete "
+            error_report("Failed to Wait for previous write to complete "
                     "block %d chunk %" PRIu64
-                    " current %" PRIu64 " len %" PRIu64 " %d\n",
+                    " current %" PRIu64 " len %" PRIu64 " %d",
                     current_index, chunk, sge.addr, length, rdma->nb_sent);
             return ret;
         }
@@ -1932,10 +1897,8 @@ retry:
                 head.len = sizeof(comp);
                 head.type = RDMA_CONTROL_COMPRESS;
 
-                DDPRINTF("Entire chunk is zero, sending compress: %"
-                    PRIu64 " for %d "
-                    "bytes, index: %d, offset: %" PRId64 "...\n",
-                    chunk, sge.length, current_index, current_addr);
+                trace_qemu_rdma_write_one_zero(chunk, sge.length,
+                                               current_index, current_addr);
 
                 compress_to_network(&comp);
                 ret = qemu_rdma_exchange_send(rdma, &head,
@@ -1961,9 +1924,8 @@ retry:
             }
             reg.chunks = chunks;
 
-            DDPRINTF("Sending registration request chunk %" PRIu64 " for %d "
-                    "bytes, index: %d, offset: %" PRId64 "...\n",
-                    chunk, sge.length, current_index, current_addr);
+            trace_qemu_rdma_write_one_sendreg(chunk, sge.length, current_index,
+                                              current_addr);
 
             register_to_network(&reg);
             ret = qemu_rdma_exchange_send(rdma, &head, (uint8_t *) &reg,
@@ -1977,7 +1939,7 @@ retry:
                                                 (uint8_t *) sge.addr,
                                                 &sge.lkey, NULL, chunk,
                                                 chunk_start, chunk_end)) {
-                fprintf(stderr, "cannot get lkey!\n");
+                error_report("cannot get lkey");
                 return -EINVAL;
             }
 
@@ -1986,9 +1948,8 @@ retry:
 
             network_to_result(reg_result);
 
-            DDPRINTF("Received registration result:"
-                    " my key: %x their key %x, chunk %" PRIu64 "\n",
-                    block->remote_keys[chunk], reg_result->rkey, chunk);
+            trace_qemu_rdma_write_one_recvregres(block->remote_keys[chunk],
+                                                 reg_result->rkey, chunk);
 
             block->remote_keys[chunk] = reg_result->rkey;
             block->remote_host_addr = reg_result->host_addr;
@@ -1998,7 +1959,7 @@ retry:
                                                 (uint8_t *)sge.addr,
                                                 &sge.lkey, NULL, chunk,
                                                 chunk_start, chunk_end)) {
-                fprintf(stderr, "cannot get lkey!\n");
+                error_report("cannot get lkey!");
                 return -EINVAL;
             }
         }
@@ -2010,7 +1971,7 @@ retry:
         if (qemu_rdma_register_and_get_keys(rdma, block, (uint8_t *)sge.addr,
                                                      &sge.lkey, NULL, chunk,
                                                      chunk_start, chunk_end)) {
-            fprintf(stderr, "cannot get lkey!\n");
+            error_report("cannot get lkey!");
             return -EINVAL;
         }
     }
@@ -2031,10 +1992,8 @@ retry:
     send_wr.wr.rdma.remote_addr = block->remote_host_addr +
                                 (current_addr - block->offset);
 
-    DDDPRINTF("Posting chunk: %" PRIu64 ", addr: %lx"
-              " remote: %lx, bytes %" PRIu32 "\n",
-              chunk, sge.addr, send_wr.wr.rdma.remote_addr,
-              sge.length);
+    trace_qemu_rdma_write_one_post(chunk, sge.addr, send_wr.wr.rdma.remote_addr,
+                                   sge.length);
 
     /*
      * ibv_post_send() does not return negative error numbers,
@@ -2043,11 +2002,11 @@ retry:
     ret = ibv_post_send(rdma->qp, &send_wr, &bad_wr);
 
     if (ret == ENOMEM) {
-        DDPRINTF("send queue is full. wait a little....\n");
+        trace_qemu_rdma_write_one_queue_full();
         ret = qemu_rdma_block_for_wrid(rdma, RDMA_WRID_RDMA_WRITE, NULL);
         if (ret < 0) {
-            fprintf(stderr, "rdma migration: failed to make "
-                            "room in full send queue! %d\n", ret);
+            error_report("rdma migration: failed to make "
+                         "room in full send queue! %d", ret);
             return ret;
         }
 
@@ -2088,7 +2047,7 @@ static int qemu_rdma_write_flush(QEMUFile *f, RDMAContext *rdma)
 
     if (ret == 0) {
         rdma->nb_sent++;
-        DDDPRINTF("sent total: %d\n", rdma->nb_sent);
+        trace_qemu_rdma_write_flush(rdma->nb_sent);
     }
 
     rdma->current_length = 0;
@@ -2173,7 +2132,7 @@ static int qemu_rdma_write(QEMUFile *f, RDMAContext *rdma,
         ret = qemu_rdma_search_ram_block(rdma, block_offset,
                                          offset, len, &index, &chunk);
         if (ret) {
-            fprintf(stderr, "ram block search failed\n");
+            error_report("ram block search failed");
             return ret;
         }
         rdma->current_index = index;
@@ -2202,19 +2161,19 @@ static void qemu_rdma_cleanup(RDMAContext *rdma)
                                        .type = RDMA_CONTROL_ERROR,
                                        .repeat = 1,
                                      };
-            fprintf(stderr, "Early error. Sending error.\n");
+            error_report("Early error. Sending error.");
             qemu_rdma_post_send_control(rdma, NULL, &head);
         }
 
         ret = rdma_disconnect(rdma->cm_id);
         if (!ret) {
-            DDPRINTF("waiting for disconnect\n");
+            trace_qemu_rdma_cleanup_waiting_for_disconnect();
             ret = rdma_get_cm_event(rdma->channel, &cm_event);
             if (!ret) {
                 rdma_ack_cm_event(cm_event);
             }
         }
-        DDPRINTF("Disconnected.\n");
+        trace_qemu_rdma_cleanup_disconnect();
         rdma->connected = false;
     }
 
@@ -2341,7 +2300,7 @@ static int qemu_rdma_connect(RDMAContext *rdma, Error **errp)
      * on the source first requested the capability.
      */
     if (rdma->pin_all) {
-        DPRINTF("Server pin-all memory requested.\n");
+        trace_qemu_rdma_connect_pin_all_requested();
         cap.flags |= RDMA_CAPABILITY_PIN_ALL;
     }
 
@@ -2389,7 +2348,7 @@ static int qemu_rdma_connect(RDMAContext *rdma, Error **errp)
         rdma->pin_all = false;
     }
 
-    DPRINTF("Pin all memory: %s\n", rdma->pin_all ? "enabled" : "disabled");
+    trace_qemu_rdma_connect_pin_all_outcome(rdma->pin_all);
 
     rdma_ack_cm_event(cm_event);
 
@@ -2456,7 +2415,7 @@ static int qemu_rdma_dest_init(RDMAContext *rdma, Error **errp)
         for (e = res; e != NULL; e = e->ai_next) {
             inet_ntop(e->ai_family,
                 &((struct sockaddr_in *) e->ai_dst_addr)->sin_addr, ip, sizeof ip);
-            DPRINTF("Trying %s => %s\n", rdma->host, ip);
+            trace_qemu_rdma_dest_init_trying(rdma->host, ip);
             ret = rdma_bind_addr(listen_id, e->ai_dst_addr);
             if (!ret) {
                 if (e->ai_family == AF_INET6) {
@@ -2575,8 +2534,7 @@ static size_t qemu_rdma_fill(RDMAContext *rdma, uint8_t *buf,
     size_t len = 0;
 
     if (rdma->wr_data[idx].control_len) {
-        DDDPRINTF("RDMA %" PRId64 " of %d bytes already in buffer\n",
-                    rdma->wr_data[idx].control_len, size);
+        trace_qemu_rdma_fill(rdma->wr_data[idx].control_len, size);
 
         len = MIN(size, rdma->wr_data[idx].control_len);
         memcpy(buf, rdma->wr_data[idx].control_curr, len);
@@ -2643,7 +2601,7 @@ static int qemu_rdma_drain_cq(QEMUFile *f, RDMAContext *rdma)
     while (rdma->nb_sent) {
         ret = qemu_rdma_block_for_wrid(rdma, RDMA_WRID_RDMA_WRITE, NULL);
         if (ret < 0) {
-            fprintf(stderr, "rdma migration: complete polling error!\n");
+            error_report("rdma migration: complete polling error!");
             return -EIO;
         }
     }
@@ -2655,7 +2613,7 @@ static int qemu_rdma_drain_cq(QEMUFile *f, RDMAContext *rdma)
 
 static int qemu_rdma_close(void *opaque)
 {
-    DPRINTF("Shutting down connection.\n");
+    trace_qemu_rdma_close();
     QEMUFileRDMA *r = opaque;
     if (r->rdma) {
         qemu_rdma_cleanup(r->rdma);
@@ -2719,7 +2677,7 @@ static size_t qemu_rdma_save_page(QEMUFile *f, void *opaque,
          */
         ret = qemu_rdma_write(f, rdma, block_offset, offset, size);
         if (ret < 0) {
-            fprintf(stderr, "rdma migration: write error! %d\n", ret);
+            error_report("rdma migration: write error! %d", ret);
             goto err;
         }
 
@@ -2752,7 +2710,7 @@ static size_t qemu_rdma_save_page(QEMUFile *f, void *opaque,
                                          offset, size, &index, &chunk);
 
         if (ret) {
-            fprintf(stderr, "ram block search failed\n");
+            error_report("ram block search failed");
             goto err;
         }
 
@@ -2779,7 +2737,7 @@ static size_t qemu_rdma_save_page(QEMUFile *f, void *opaque,
         uint64_t wr_id, wr_id_in;
         int ret = qemu_rdma_poll(rdma, &wr_id_in, NULL);
         if (ret < 0) {
-            fprintf(stderr, "rdma migration: polling error! %d\n", ret);
+            error_report("rdma migration: polling error! %d", ret);
             goto err;
         }
 
@@ -2824,7 +2782,7 @@ static int qemu_rdma_accept(RDMAContext *rdma)
     network_to_caps(&cap);
 
     if (cap.version < 1 || cap.version > RDMA_CONTROL_VERSION_CURRENT) {
-            fprintf(stderr, "Unknown source RDMA version: %d, bailing...\n",
+            error_report("Unknown source RDMA version: %d, bailing...",
                             cap.version);
             rdma_ack_cm_event(cm_event);
             goto err_rdma_dest_wait;
@@ -2848,17 +2806,17 @@ static int qemu_rdma_accept(RDMAContext *rdma)
 
     rdma_ack_cm_event(cm_event);
 
-    DPRINTF("Memory pin all: %s\n", rdma->pin_all ? "enabled" : "disabled");
+    trace_qemu_rdma_accept_pin_state(rdma->pin_all);
 
     caps_to_network(&cap);
 
-    DPRINTF("verbs context after listen: %p\n", verbs);
+    trace_qemu_rdma_accept_pin_verbsc(verbs);
 
     if (!rdma->verbs) {
         rdma->verbs = verbs;
     } else if (rdma->verbs != verbs) {
-            fprintf(stderr, "ibv context not matching %p, %p!\n",
-                    rdma->verbs, verbs);
+            error_report("ibv context not matching %p, %p!", rdma->verbs,
+                         verbs);
             goto err_rdma_dest_wait;
     }
 
@@ -2866,26 +2824,26 @@ static int qemu_rdma_accept(RDMAContext *rdma)
 
     ret = qemu_rdma_alloc_pd_cq(rdma);
     if (ret) {
-        fprintf(stderr, "rdma migration: error allocating pd and cq!\n");
+        error_report("rdma migration: error allocating pd and cq!");
         goto err_rdma_dest_wait;
     }
 
     ret = qemu_rdma_alloc_qp(rdma);
     if (ret) {
-        fprintf(stderr, "rdma migration: error allocating qp!\n");
+        error_report("rdma migration: error allocating qp!");
         goto err_rdma_dest_wait;
     }
 
     ret = qemu_rdma_init_ram_blocks(rdma);
     if (ret) {
-        fprintf(stderr, "rdma migration: error initializing ram blocks!\n");
+        error_report("rdma migration: error initializing ram blocks!");
         goto err_rdma_dest_wait;
     }
 
     for (idx = 0; idx < RDMA_WRID_MAX; idx++) {
         ret = qemu_rdma_reg_control(rdma, idx);
         if (ret) {
-            fprintf(stderr, "rdma: error registering %d control!\n", idx);
+            error_report("rdma: error registering %d control", idx);
             goto err_rdma_dest_wait;
         }
     }
@@ -2894,18 +2852,18 @@ static int qemu_rdma_accept(RDMAContext *rdma)
 
     ret = rdma_accept(rdma->cm_id, &conn_param);
     if (ret) {
-        fprintf(stderr, "rdma_accept returns %d!\n", ret);
+        error_report("rdma_accept returns %d", ret);
         goto err_rdma_dest_wait;
     }
 
     ret = rdma_get_cm_event(rdma->channel, &cm_event);
     if (ret) {
-        fprintf(stderr, "rdma_accept get_cm_event failed %d!\n", ret);
+        error_report("rdma_accept get_cm_event failed %d", ret);
         goto err_rdma_dest_wait;
     }
 
     if (cm_event->event != RDMA_CM_EVENT_ESTABLISHED) {
-        fprintf(stderr, "rdma_accept not event established!\n");
+        error_report("rdma_accept not event established");
         rdma_ack_cm_event(cm_event);
         goto err_rdma_dest_wait;
     }
@@ -2915,7 +2873,7 @@ static int qemu_rdma_accept(RDMAContext *rdma)
 
     ret = qemu_rdma_post_recv_control(rdma, RDMA_WRID_READY);
     if (ret) {
-        fprintf(stderr, "rdma migration: error posting second control recv!\n");
+        error_report("rdma migration: error posting second control recv");
         goto err_rdma_dest_wait;
     }
 
@@ -2969,7 +2927,7 @@ static int qemu_rdma_registration_handle(QEMUFile *f, void *opaque,
     CHECK_ERROR_STATE();
 
     do {
-        DDDPRINTF("Waiting for next request %" PRIu64 "...\n", flags);
+        trace_qemu_rdma_registration_handle_wait(flags);
 
         ret = qemu_rdma_exchange_recv(rdma, &head, RDMA_CONTROL_NONE);
 
@@ -2978,8 +2936,8 @@ static int qemu_rdma_registration_handle(QEMUFile *f, void *opaque,
         }
 
         if (head.repeat > RDMA_CONTROL_MAX_COMMANDS_PER_MESSAGE) {
-            fprintf(stderr, "rdma: Too many requests in this message (%d)."
-                            "Bailing.\n", head.repeat);
+            error_report("rdma: Too many requests in this message (%d)."
+                            "Bailing.", head.repeat);
             ret = -EIO;
             break;
         }
@@ -2989,9 +2947,9 @@ static int qemu_rdma_registration_handle(QEMUFile *f, void *opaque,
             comp = (RDMACompress *) rdma->wr_data[idx].control_curr;
             network_to_compress(comp);
 
-            DDPRINTF("Zapping zero chunk: %" PRId64
-                    " bytes, index %d, offset %" PRId64 "\n",
-                    comp->length, comp->block_idx, comp->offset);
+            trace_qemu_rdma_registration_handle_compress(comp->length,
+                                                         comp->block_idx,
+                                                         comp->offset);
             block = &(rdma->local_ram_blocks.block[comp->block_idx]);
 
             host_addr = block->local_host_addr +
@@ -3001,17 +2959,17 @@ static int qemu_rdma_registration_handle(QEMUFile *f, void *opaque,
             break;
 
         case RDMA_CONTROL_REGISTER_FINISHED:
-            DDDPRINTF("Current registrations complete.\n");
+            trace_qemu_rdma_registration_handle_finished();
             goto out;
 
         case RDMA_CONTROL_RAM_BLOCKS_REQUEST:
-            DPRINTF("Initial setup info requested.\n");
+            trace_qemu_rdma_registration_handle_ram_blocks();
 
             if (rdma->pin_all) {
                 ret = qemu_rdma_reg_whole_ram_blocks(rdma);
                 if (ret) {
-                    fprintf(stderr, "rdma migration: error dest "
-                                    "registering ram blocks!\n");
+                    error_report("rdma migration: error dest "
+                                    "registering ram blocks");
                     goto out;
                 }
             }
@@ -3044,13 +3002,13 @@ static int qemu_rdma_registration_handle(QEMUFile *f, void *opaque,
                                         (uint8_t *) rdma->block, &blocks);
 
             if (ret < 0) {
-                fprintf(stderr, "rdma migration: error sending remote info!\n");
+                error_report("rdma migration: error sending remote info");
                 goto out;
             }
 
             break;
         case RDMA_CONTROL_REGISTER_REQUEST:
-            DDPRINTF("There are %d registration requests\n", head.repeat);
+            trace_qemu_rdma_registration_handle_register(head.repeat);
 
             reg_resp.repeat = head.repeat;
             registers = (RDMARegister *) rdma->wr_data[idx].control_curr;
@@ -3064,8 +3022,7 @@ static int qemu_rdma_registration_handle(QEMUFile *f, void *opaque,
 
                 reg_result = &results[count];
 
-                DDPRINTF("Registration request (%d): index %d, current_addr %"
-                         PRIu64 " chunks: %" PRIu64 "\n", count,
+                trace_qemu_rdma_registration_handle_register_loop(count,
                          reg->current_index, reg->key.current_addr, reg->chunks);
 
                 block = &(rdma->local_ram_blocks.block[reg->current_index]);
@@ -3084,15 +3041,15 @@ static int qemu_rdma_registration_handle(QEMUFile *f, void *opaque,
                 if (qemu_rdma_register_and_get_keys(rdma, block,
                             (uint8_t *)host_addr, NULL, &reg_result->rkey,
                             chunk, chunk_start, chunk_end)) {
-                    fprintf(stderr, "cannot get rkey!\n");
+                    error_report("cannot get rkey");
                     ret = -EINVAL;
                     goto out;
                 }
 
                 reg_result->host_addr = (uint64_t) block->local_host_addr;
 
-                DDPRINTF("Registered rkey for this request: %x\n",
-                                reg_result->rkey);
+                trace_qemu_rdma_registration_handle_register_rkey(
+                                                           reg_result->rkey);
 
                 result_to_network(reg_result);
             }
@@ -3101,12 +3058,12 @@ static int qemu_rdma_registration_handle(QEMUFile *f, void *opaque,
                             (uint8_t *) results, &reg_resp);
 
             if (ret < 0) {
-                fprintf(stderr, "Failed to send control buffer!\n");
+                error_report("Failed to send control buffer");
                 goto out;
             }
             break;
         case RDMA_CONTROL_UNREGISTER_REQUEST:
-            DDPRINTF("There are %d unregistration requests\n", head.repeat);
+            trace_qemu_rdma_registration_handle_unregister(head.repeat);
             unreg_resp.repeat = head.repeat;
             registers = (RDMARegister *) rdma->wr_data[idx].control_curr;
 
@@ -3114,9 +3071,8 @@ static int qemu_rdma_registration_handle(QEMUFile *f, void *opaque,
                 reg = &registers[count];
                 network_to_register(reg);
 
-                DDPRINTF("Unregistration request (%d): "
-                         " index %d, chunk %" PRIu64 "\n",
-                         count, reg->current_index, reg->key.chunk);
+                trace_qemu_rdma_registration_handle_unregister_loop(count,
+                           reg->current_index, reg->key.chunk);
 
                 block = &(rdma->local_ram_blocks.block[reg->current_index]);
 
@@ -3131,24 +3087,23 @@ static int qemu_rdma_registration_handle(QEMUFile *f, void *opaque,
 
                 rdma->total_registrations--;
 
-                DDPRINTF("Unregistered chunk %" PRIu64 " successfully.\n",
-                            reg->key.chunk);
+                trace_qemu_rdma_registration_handle_unregister_success(
+                                                       reg->key.chunk);
             }
 
             ret = qemu_rdma_post_send_control(rdma, NULL, &unreg_resp);
 
             if (ret < 0) {
-                fprintf(stderr, "Failed to send control buffer!\n");
+                error_report("Failed to send control buffer");
                 goto out;
             }
             break;
         case RDMA_CONTROL_REGISTER_RESULT:
-            fprintf(stderr, "Invalid RESULT message at dest.\n");
+            error_report("Invalid RESULT message at dest.");
             ret = -EIO;
             goto out;
         default:
-            fprintf(stderr, "Unknown control message %s\n",
-                                control_desc[head.type]);
+            error_report("Unknown control message %s", control_desc[head.type]);
             ret = -EIO;
             goto out;
         }
@@ -3168,7 +3123,7 @@ static int qemu_rdma_registration_start(QEMUFile *f, void *opaque,
 
     CHECK_ERROR_STATE();
 
-    DDDPRINTF("start section: %" PRIu64 "\n", flags);
+    trace_qemu_rdma_registration_start(flags);
     qemu_put_be64(f, RAM_SAVE_FLAG_HOOK);
     qemu_fflush(f);
 
@@ -3203,7 +3158,7 @@ static int qemu_rdma_registration_stop(QEMUFile *f, void *opaque,
         int reg_result_idx, i, j, nb_remote_blocks;
 
         head.type = RDMA_CONTROL_RAM_BLOCKS_REQUEST;
-        DPRINTF("Sending registration setup for ram blocks...\n");
+        trace_qemu_rdma_registration_stop_ram();
 
         /*
          * Make sure that we parallelize the pinning on both sides.
@@ -3275,7 +3230,7 @@ static int qemu_rdma_registration_stop(QEMUFile *f, void *opaque,
         }
     }
 
-    DDDPRINTF("Sending registration finish %" PRIu64 "...\n", flags);
+    trace_qemu_rdma_registration_stop(flags);
 
     head.type = RDMA_CONTROL_REGISTER_FINISHED;
     ret = qemu_rdma_exchange_send(rdma, &head, NULL, NULL, NULL, NULL);
@@ -3339,7 +3294,7 @@ static void rdma_accept_incoming_migration(void *opaque)
     QEMUFile *f;
     Error *local_err = NULL, **errp = &local_err;
 
-    DPRINTF("Accepting rdma connection...\n");
+    trace_qemu_dma_accept_incoming_migration();
     ret = qemu_rdma_accept(rdma);
 
     if (ret) {
@@ -3347,7 +3302,7 @@ static void rdma_accept_incoming_migration(void *opaque)
         return;
     }
 
-    DPRINTF("Accepted migration\n");
+    trace_qemu_dma_accept_incoming_migration_accepted();
 
     f = qemu_fopen_rdma(rdma, "rb");
     if (f == NULL) {
@@ -3366,7 +3321,7 @@ void rdma_start_incoming_migration(const char *host_port, Error **errp)
     RDMAContext *rdma;
     Error *local_err = NULL;
 
-    DPRINTF("Starting RDMA-based incoming migration\n");
+    trace_rdma_start_incoming_migration();
     rdma = qemu_rdma_data_init(host_port, &local_err);
 
     if (rdma == NULL) {
@@ -3379,7 +3334,7 @@ void rdma_start_incoming_migration(const char *host_port, Error **errp)
         goto err;
     }
 
-    DPRINTF("qemu_rdma_dest_init success\n");
+    trace_rdma_start_incoming_migration_after_dest_init();
 
     ret = rdma_listen(rdma->listen_id, 5);
 
@@ -3388,7 +3343,7 @@ void rdma_start_incoming_migration(const char *host_port, Error **errp)
         goto err;
     }
 
-    DPRINTF("rdma_listen success\n");
+    trace_rdma_start_incoming_migration_after_rdma_listen();
 
     qemu_set_fd_handler2(rdma->channel->fd, NULL,
                          rdma_accept_incoming_migration, NULL,
@@ -3419,14 +3374,14 @@ void rdma_start_outgoing_migration(void *opaque,
         goto err;
     }
 
-    DPRINTF("qemu_rdma_source_init success\n");
+    trace_rdma_start_outgoing_migration_after_rdma_source_init();
     ret = qemu_rdma_connect(rdma, &local_err);
 
     if (ret) {
         goto err;
     }
 
-    DPRINTF("qemu_rdma_source_connect success\n");
+    trace_rdma_start_outgoing_migration_after_rdma_connect();
 
     s->file = qemu_fopen_rdma(rdma, "wb");
     migrate_fd_connect(s);