search

virtio-win / kvm-guest-drivers-windows

Windows paravirtualized drivers for QEMU\KVM
https://www.linux-kvm.org/page/WindowsGuestDrivers
BSD 3-Clause "New" or "Revised" License
1.92k stars 377 forks source link

vioscsi: logging improvements for SRB tracing #955

Closed sb-ntnx closed 11 months ago

sb-ntnx commented 11 months ago

This PR is consist of two cosmetic logging improvements:

  1. The first one is to slightly change the wording to reflect the current code and make it more comprehensive. Extended the list of SCSI Ops.
  2. The second one is to improve SRB tracing with INFORMATION logging level to reduce the noise from ENTER/LEAVE functions (that is logged with VERBSOE level). With this change we start logging SRB info for VioScsiBuildIo, SendSRB and HandleResponse calls. Also extended the list of SCSI Ops from EWDK2022.

It is the way the log looks like:

[0]0004.01D0::08/06/2023-11:18:36.954 [vioscsi.sys] VioScsiBuildIo <--> Operation SCSIOP_PERSISTENT_RESERVE_IN (0x5E), Target (0::0::2), SRB 0xFFFFCE0C44852980
[0]0004.01D0::08/06/2023-11:18:36.954 [vioscsi.sys] SendSRB <--> Operation SCSIOP_PERSISTENT_RESERVE_IN (0x5E), TargetId (0::0::2), SRB 0xFFFFCE0C44852980
[0]0000.0000::08/06/2023-11:18:36.955 [vioscsi.sys] HandleResponse <--> Operation SCSIOP_PERSISTENT_RESERVE_IN (0x5E), Target (0::0::2), SRB 0xFFFFCE0C44852980
[1]0004.01D0::08/06/2023-11:18:36.970 [vioscsi.sys] VioScsiBuildIo <--> Operation SCSIOP_PERSISTENT_RESERVE_IN (0x5E), Target (0::0::0), SRB 0xFFFFCE0C44853B00
[1]0004.01D0::08/06/2023-11:18:36.970 [vioscsi.sys] SendSRB <--> Operation SCSIOP_PERSISTENT_RESERVE_IN (0x5E), TargetId (0::0::0), SRB 0xFFFFCE0C44853B00
[1]0000.0000::08/06/2023-11:18:36.970 [vioscsi.sys] HandleResponse <--> Operation SCSIOP_PERSISTENT_RESERVE_IN (0x5E), Target (0::0::0), SRB 0xFFFFCE0C44853B00

So with the above change, it is easier to parse the text file when you need to measure IO request time that is spent in the backend.

Note: trace.h seems to have had CRLF, so when I changed it to LF git thinks it is the change of the whole file, however, the changes in this file are only:

#define UCHAR_MAX 0xFF
#define DbgGetScsiOp(Srb) (SRB_CDB(Srb) ? SRB_CDB(Srb)->CDB6GENERIC.OperationCode : UCHAR_MAX)

char *DbgGetScsiOpStr(UCHAR opCode);
...
#define LOG_SRB_INFO() RhelDbgPrint(TRACE_LEVEL_INFORMATION, "%s <--> Operation %s (0x%X), Target (%d::%d::%d), SRB 0x%p\n",__FUNCTION__, DbgGetScsiOpStr(DbgGetScsiOp(Srb)), DbgGetScsiOp(Srb), SRB_PATH_ID(Srb), SRB_TARGET_ID(Srb), SRB_LUN(Srb), Srb)
...
// USEPREFIX (LOG_SRB_INFO(PVOID Srb), "%!STDPREFIX! %!FUNC! <--> Operation %s (0x%X), Target (%d::%d::%d), SRB 0x%p", DbgGetScsiOpStr(DbgGetScsiOp(Srb)), DbgGetScsiOp(Srb), SRB_PATH_ID(Srb), SRB_TARGET_ID(Srb), SRB_LUN(Srb), Srb);
// FUNC LOG_SRB_INFO{LEVEL=TRACE_LEVEL_INFORMATION}(...);