From c123251df70561aa51e390fec928cae04532f2ce Mon Sep 17 00:00:00 2001 From: Chris Horn Date: Fri, 10 May 2024 11:41:57 -0600 Subject: [PATCH] LU-17935 kfilnd: Cleanup debug logging Log messages that refer to a struct kfilnd_transaction should print the pointer to the struct with "TN %p". Assign kfilnd_transaction::msg_type in the kfilnd_process_rx_event path so that debug messages show the correct message type. HPE-bug-id: LUs-11325 Test-Parameters: trivial Signed-off-by: Chris Horn Change-Id: Iabe3bf245b64f1eb66c85259072491c723fb6119 Reviewed-on: https://review.whamcloud.com/c/fs/lustre-release/+/55398 Reviewed-by: Caleb Carlson Reviewed-by: Ron Gredvig Reviewed-by: Oleg Drokin Tested-by: jenkins Tested-by: Maloo --- lnet/klnds/kfilnd/kfilnd.h | 2 +- lnet/klnds/kfilnd/kfilnd_ep.c | 12 ++++++------ lnet/klnds/kfilnd/kfilnd_tn.c | 30 ++++++++++++++++-------------- 3 files changed, 23 insertions(+), 21 deletions(-) diff --git a/lnet/klnds/kfilnd/kfilnd.h b/lnet/klnds/kfilnd/kfilnd.h index 82b50e5..3ee5b889 100644 --- a/lnet/klnds/kfilnd/kfilnd.h +++ b/lnet/klnds/kfilnd/kfilnd.h @@ -622,7 +622,7 @@ struct kfilnd_msg { } while (0) #define KFILND_TN_DIR_ERROR(tn, fmt, dir, ...) \ - CNETERR("Transaction ID %p: %s:%u %s %s(%p):0x%llx " fmt "\n", \ + CNETERR("TN %p: %s:%u %s %s(%p):0x%llx " fmt "\n", \ (tn), \ libcfs_nidstr(&(tn)->tn_ep->end_dev->kfd_ni->ni_nid), \ (tn)->tn_ep->end_context_id, dir, \ diff --git a/lnet/klnds/kfilnd/kfilnd_ep.c b/lnet/klnds/kfilnd/kfilnd_ep.c index 580ffad..93290d3 100644 --- a/lnet/klnds/kfilnd/kfilnd_ep.c +++ b/lnet/klnds/kfilnd/kfilnd_ep.c @@ -264,14 +264,14 @@ int kfilnd_ep_post_tagged_send(struct kfilnd_ep *ep, case 0: case -EAGAIN: KFILND_EP_DEBUG(ep, - "Transaction ID %p: %s tagged send of with tag 0x%x to peer 0x%llx: rc=%d", + "TN %p: %s tagged send of with tag 0x%x to peer 0x%llx: rc=%d", tn, rc ? "Failed to post" : "Posted", tn->tn_response_mr_key, tn->tn_target_addr, rc); break; default: KFILND_EP_ERROR(ep, - "Transaction ID %p: Failed to post tagged send with tag 0x%x to peer 0x%llx: rc=%d", + "TN %p: Failed to post tagged send with tag 0x%x to peer 0x%llx: rc=%d", tn, tn->tn_response_mr_key, tn->tn_target_addr, rc); } @@ -369,14 +369,14 @@ int kfilnd_ep_post_tagged_recv(struct kfilnd_ep *ep, case 0: case -EAGAIN: KFILND_EP_DEBUG(ep, - "Transaction ID %p: %s tagged recv of %u bytes (%u frags) with tag 0x%llx: rc=%d", + "TN %p: %s tagged recv of %u bytes (%u frags) with tag 0x%llx: rc=%d", tn, rc ? "Failed to post" : "Posted", tn->tn_nob, tn->tn_num_iovec, msg.tag, rc); break; default: KFILND_EP_ERROR(ep, - "Transaction ID %p: Failed to post tagged recv of %u bytes (%u frags) with tag 0x%llx: rc=%d", + "TN %p: Failed to post tagged recv of %u bytes (%u frags) with tag 0x%llx: rc=%d", tn, tn->tn_nob, tn->tn_num_iovec, msg.tag, rc); } @@ -434,14 +434,14 @@ int kfilnd_ep_post_send(struct kfilnd_ep *ep, struct kfilnd_transaction *tn) case 0: case -EAGAIN: KFILND_EP_DEBUG(ep, - "Transaction ID %p: %s send of %lu bytes to peer 0x%llx: rc=%d", + "TN %p: %s send of %lu bytes to peer 0x%llx: rc=%d", tn, rc ? "Failed to post" : "Posted", len, tn->tn_target_addr, rc); break; default: KFILND_EP_ERROR(ep, - "Transaction ID %p: Failed to post send of %lu bytes to peer 0x%llx: rc=%d", + "TN %p: Failed to post send of %lu bytes to peer 0x%llx: rc=%d", tn, len, tn->tn_target_addr, rc); } diff --git a/lnet/klnds/kfilnd/kfilnd_tn.c b/lnet/klnds/kfilnd/kfilnd_tn.c index a812097..e6b3ae8 100644 --- a/lnet/klnds/kfilnd/kfilnd_tn.c +++ b/lnet/klnds/kfilnd/kfilnd_tn.c @@ -354,23 +354,26 @@ void kfilnd_tn_process_rx_event(struct kfilnd_immediate_buffer *bufdesc, struct kfilnd_msg *rx_msg, int msg_size) { struct kfilnd_transaction *tn; + struct kfilnd_ep *ep = bufdesc->immed_end; bool alloc_msg = true; int rc; enum tn_events event = TN_EVENT_RX_HELLO; + enum kfilnd_msg_type msg_type; /* Increment buf ref count for this work */ atomic_inc(&bufdesc->immed_ref); /* Unpack the message */ - rc = kfilnd_tn_unpack_msg(bufdesc->immed_end, rx_msg, msg_size); + rc = kfilnd_tn_unpack_msg(ep, rx_msg, msg_size); if (rc || CFS_FAIL_CHECK(CFS_KFI_FAIL_MSG_UNPACK)) { kfilnd_ep_imm_buffer_put(bufdesc); - KFILND_EP_ERROR(bufdesc->immed_end, - "Failed to unpack message %d", rc); + KFILND_EP_ERROR(ep, "Failed to unpack message %d", rc); return; } - switch ((enum kfilnd_msg_type)rx_msg->type) { + msg_type = (enum kfilnd_msg_type)rx_msg->type; + + switch (msg_type) { case KFILND_MSG_IMMEDIATE: case KFILND_MSG_BULK_PUT_REQ: case KFILND_MSG_BULK_GET_REQ: @@ -384,14 +387,13 @@ void kfilnd_tn_process_rx_event(struct kfilnd_immediate_buffer *bufdesc, * Allocate a Tn structure, set its values, then launch the * receive. */ - tn = kfilnd_tn_alloc(bufdesc->immed_end->end_dev, - bufdesc->immed_end->end_cpt, + tn = kfilnd_tn_alloc(ep->end_dev, ep->end_cpt, rx_msg->srcnid, alloc_msg, false, false); if (IS_ERR(tn)) { kfilnd_ep_imm_buffer_put(bufdesc); - KFILND_EP_ERROR(bufdesc->immed_end, - "Failed to allocate transaction struct: rc=%ld", + KFILND_EP_ERROR(ep, + "Failed to allocate transaction struct: rc=%ld", PTR_ERR(tn)); return; } @@ -399,16 +401,16 @@ void kfilnd_tn_process_rx_event(struct kfilnd_immediate_buffer *bufdesc, tn->tn_rx_msg.msg = rx_msg; tn->tn_rx_msg.length = msg_size; tn->tn_posted_buf = bufdesc; + tn->msg_type = msg_type; - KFILND_EP_DEBUG(bufdesc->immed_end, "%s transaction ID %u", - msg_type_to_str((enum kfilnd_msg_type)rx_msg->type), + KFILND_EP_DEBUG(ep, "%s TN %p tmk %u", + msg_type_to_str(tn->msg_type), tn, tn->tn_mr_key); break; default: - KFILND_EP_ERROR(bufdesc->immed_end, - "Unhandled kfilnd message type: %d", - (enum kfilnd_msg_type)rx_msg->type); + KFILND_EP_ERROR(ep, "Unhandled kfilnd message type: %d", + msg_type); LBUG(); }; @@ -1621,7 +1623,7 @@ static struct kfilnd_transaction *kfilnd_tn_alloc_common(struct kfilnd_ep *ep, tn->tn_alloc_ts = tn_alloc_ts; tn->tn_state_ts = ktime_get(); - KFILND_EP_DEBUG(ep, "Transaction ID %u allocated", tn->tn_mr_key); + KFILND_EP_DEBUG(ep, "TN %p allocated with tmk %u", tn, tn->tn_mr_key); return tn; -- 1.8.3.1