From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mails.dpdk.org (mails.dpdk.org [217.70.189.124]) by inbox.dpdk.org (Postfix) with ESMTP id EBB3CA0546; Sat, 1 May 2021 19:19:07 +0200 (CEST) Received: from [217.70.189.124] (localhost [127.0.0.1]) by mails.dpdk.org (Postfix) with ESMTP id 121C041128; Sat, 1 May 2021 19:18:52 +0200 (CEST) Received: from mail-lf1-f45.google.com (mail-lf1-f45.google.com [209.85.167.45]) by mails.dpdk.org (Postfix) with ESMTP id 0399C40693 for ; Sat, 1 May 2021 19:18:48 +0200 (CEST) Received: by mail-lf1-f45.google.com with SMTP id 12so1823909lfq.13 for ; Sat, 01 May 2021 10:18:48 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=/5JD6tV9rxEP80P4JHeSk5aRYd2ZHREeM7pBycyIU/8=; b=W1iG7Hsfeqy4GUL0ix+YSmz7ATRP+P+QUoZesEQFOkyrFsjoG3MuSC4yu5PzuHPK4k dqPVXA9T2D1Dq8v+y3wKayj2naLaUMwerBrlzNupusLznMA6/D0EZi36nlbRafTB8vDc jh93rB5qCLbcMXaDKefl7FXvhKg4sgraXCWbQp79JJ0FYn7AI3u7zA0jyfsjE5stYIpG OAyExiENB9KaRQujYBQceJ7OmXIJwguCaGbQ3K6siyqtD0ANg5MqtH5LKuatHNwbeP93 4KWMvaa0kfhM6frwEnT72aB1MxGyInAdtlCjRd+dDsIlFeSQTupW8j/oPeIjcaQJfJ7l 4ZuQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=/5JD6tV9rxEP80P4JHeSk5aRYd2ZHREeM7pBycyIU/8=; b=sup3Is4aUbI99VpBc4+Ww+f6Pl1NeyAd7vvF5x8BPSA8O1XrgASFpZKd3JLV1pEdXV gsVmwzuvCOGOpYS4ZuL0xJzOMcIpc7+Ri9o85EznstwiOeVB+5gRV5L/jslN+v5/GaEu XKikoXlrpPaexrlTOKC2D+XoJM6dWUbpmhnkQEVmsIYXLjt+GS/YU/ilwE6eRm9lGxoD yJC35QfolycjQnnrKLlxHuGxc3bI2AmmgGW8phnTNt1m/E3ch+wf3uXVaD1ctHeyROGw 0ev9kSAM+179+BzAoE/NynUutnQtJKkS7GzRKxOhkP2CyUtLX3ifbvXws79WjWFdtgWB ekBQ== X-Gm-Message-State: AOAM530w2hu11CanzNXKRjEWjDbfdF6ZWBp2pb7USciKymVNShlElMs+ GnHalz1oVdnCf+il3C1KaSUgvjAPH+splw== X-Google-Smtp-Source: ABdhPJyuIf4MXK01AwgGWhwAOuVN73B/k3FgCJmyWf5R8z8PHOu9MFiZ1GrZTNQqUKNYCwOiN2uisg== X-Received: by 2002:a05:6512:3c95:: with SMTP id h21mr3096939lfv.446.1619889528307; Sat, 01 May 2021 10:18:48 -0700 (PDT) Received: from localhost.localdomain (broadband-37-110-65-23.ip.moscow.rt.ru. [37.110.65.23]) by smtp.gmail.com with ESMTPSA id i1sm616703lfe.53.2021.05.01.10.18.47 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Sat, 01 May 2021 10:18:47 -0700 (PDT) From: Dmitry Kozlyuk To: dev@dpdk.org Cc: Dmitry Malloy , Narcisa Ana Maria Vasile , Pallavi Kadam , Tyler Retzlaff , Nick Connolly , Dmitry Kozlyuk Date: Sat, 1 May 2021 20:18:37 +0300 Message-Id: <20210501171837.13282-4-dmitry.kozliuk@gmail.com> X-Mailer: git-send-email 2.29.3 In-Reply-To: <20210501171837.13282-1-dmitry.kozliuk@gmail.com> References: <20210501171837.13282-1-dmitry.kozliuk@gmail.com> MIME-Version: 1.0 Content-Transfer-Encoding: 8bit Subject: [dpdk-dev] [kmods PATCH 3/3] windows/virt2phys: add tracing X-BeenThere: dev@dpdk.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: DPDK patches and discussions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: dev-bounces@dpdk.org Sender: "dev" WPP tracing [1] allows kernel drivers to print logs that can be viewed without attaching a debugger to the running system. Traces are colelcted only when enabled. Instrument virt2phys with traces: * ERROR: failures that prevent the driver from working. * WARNING: incorrect calls to the driver. * INFO: starting or completing operations with memory. [1]: https://docs.microsoft.com/en-us/windows-hardware/drivers/devtest/wpp-software-tracing Signed-off-by: Dmitry Kozlyuk --- windows/virt2phys/virt2phys.c | 18 +++++++- windows/virt2phys/virt2phys.vcxproj | 5 ++- windows/virt2phys/virt2phys.vcxproj.filters | 3 ++ windows/virt2phys/virt2phys_logic.c | 8 ++++ windows/virt2phys/virt2phys_trace.h | 49 +++++++++++++++++++++ 5 files changed, 79 insertions(+), 4 deletions(-) create mode 100644 windows/virt2phys/virt2phys_trace.h diff --git a/windows/virt2phys/virt2phys.c b/windows/virt2phys/virt2phys.c index 0c05fe3..54f4bc0 100644 --- a/windows/virt2phys/virt2phys.c +++ b/windows/virt2phys/virt2phys.c @@ -8,6 +8,8 @@ #include "virt2phys.h" #include "virt2phys_logic.h" +#include "virt2phys_trace.h" +#include "virt2phys.tmh" DRIVER_INITIALIZE DriverEntry; EVT_WDF_DRIVER_UNLOAD virt2phys_driver_unload; @@ -46,6 +48,8 @@ DriverEntry(PDRIVER_OBJECT driver_object, PUNICODE_STRING registry_path) if (!NT_SUCCESS(status)) return status; + WPP_INIT_TRACING(driver_object, registry_path); + return status; } @@ -53,11 +57,11 @@ _Use_decl_annotations_ VOID virt2phys_driver_unload(WDFDRIVER driver) { - UNREFERENCED_PARAMETER(driver); - PsSetCreateProcessNotifyRoutine(virt2phys_on_process_event, TRUE); virt2phys_cleanup(); + + WPP_CLEANUP(WdfDriverWdmGetDriverObject(driver)); } _Use_decl_annotations_ @@ -79,12 +83,15 @@ virt2phys_driver_EvtDeviceAdd(WDFDRIVER driver, PWDFDEVICE_INIT init) status = WdfDeviceCreate(&init, &attributes, &device); if (!NT_SUCCESS(status)) { + TraceError("WdfDriverCreate() = %!STATUS!", status); return status; } status = WdfDeviceCreateDeviceInterface( device, &GUID_DEVINTERFACE_VIRT2PHYS, NULL); if (!NT_SUCCESS(status)) { + TraceError("WdfDeviceCreateDeviceInterface() = %!STATUS!", + status); return status; } @@ -109,12 +116,14 @@ virt2phys_device_EvtIoInCallerContext(WDFDEVICE device, WDFREQUEST request) WdfRequestGetParameters(request, ¶ms); if (params.Type != WdfRequestTypeDeviceControl) { + TraceWarning("Bogus IO request type %lu", params.Type); WdfRequestComplete(request, STATUS_NOT_SUPPORTED); return; } code = params.Parameters.DeviceIoControl.IoControlCode; if (code != IOCTL_VIRT2PHYS_TRANSLATE) { + TraceWarning("Bogus IO control code %lx", code); WdfRequestComplete(request, STATUS_NOT_SUPPORTED); return; } @@ -122,6 +131,7 @@ virt2phys_device_EvtIoInCallerContext(WDFDEVICE device, WDFREQUEST request) status = WdfRequestRetrieveInputBuffer( request, sizeof(*virt), (PVOID *)&virt, &size); if (!NT_SUCCESS(status)) { + TraceWarning("Retrieving input buffer: %!STATUS!", status); WdfRequestComplete(request, status); return; } @@ -129,6 +139,7 @@ virt2phys_device_EvtIoInCallerContext(WDFDEVICE device, WDFREQUEST request) status = WdfRequestRetrieveOutputBuffer( request, sizeof(*phys), (PVOID *)&phys, &size); if (!NT_SUCCESS(status)) { + TraceWarning("Retrieving output buffer: %!STATUS!", status); WdfRequestComplete(request, status); return; } @@ -136,6 +147,9 @@ virt2phys_device_EvtIoInCallerContext(WDFDEVICE device, WDFREQUEST request) status = virt2phys_translate(*virt, phys); if (NT_SUCCESS(status)) WdfRequestSetInformation(request, sizeof(*phys)); + + TraceInfo("Translate %p to %llx: %!STATUS!", + virt, phys->QuadPart, status); WdfRequestComplete(request, status); } diff --git a/windows/virt2phys/virt2phys.vcxproj b/windows/virt2phys/virt2phys.vcxproj index 294f086..a3e18dc 100644 --- a/windows/virt2phys/virt2phys.vcxproj +++ b/windows/virt2phys/virt2phys.vcxproj @@ -41,6 +41,7 @@ + @@ -170,9 +171,9 @@ - false + true true - trace.h + virt2phys_trace.h true diff --git a/windows/virt2phys/virt2phys.vcxproj.filters b/windows/virt2phys/virt2phys.vcxproj.filters index 6b65d71..b2f6776 100644 --- a/windows/virt2phys/virt2phys.vcxproj.filters +++ b/windows/virt2phys/virt2phys.vcxproj.filters @@ -30,6 +30,9 @@ Header Files + + Header Files + diff --git a/windows/virt2phys/virt2phys_logic.c b/windows/virt2phys/virt2phys_logic.c index 155d34f..7d5bf02 100644 --- a/windows/virt2phys/virt2phys_logic.c +++ b/windows/virt2phys/virt2phys_logic.c @@ -6,6 +6,8 @@ #include #include "virt2phys_logic.h" +#include "virt2phys_trace.h" +#include "virt2phys_logic.tmh" struct virt2phys_process { HANDLE id; @@ -37,6 +39,8 @@ virt2phys_block_create(PMDL mdl) static void virt2phys_block_free(struct virt2phys_block *block, BOOLEAN unmap) { + TraceInfo("VA = %p, unmap = %!bool!", block->mdl->StartVa, unmap); + if (unmap) MmUnlockPages(block->mdl); @@ -63,6 +67,8 @@ virt2phys_process_free(struct virt2phys_process *process, BOOLEAN unmap) PSINGLE_LIST_ENTRY node; struct virt2phys_block *block; + TraceInfo("ID = %p, unmap = %!bool!", process->id, unmap); + node = process->blocks.Next; while (node != NULL) { block = CONTAINING_RECORD(node, struct virt2phys_block, next); @@ -185,6 +191,8 @@ virt2phys_add_block(struct virt2phys_process *process, { struct virt2phys_process *existing; + TraceInfo("ID = %p, VA = %p", process->id, block->mdl->StartVa); + existing = virt2phys_process_find(process->id); if (existing == NULL) InsertHeadList(&g_processes, &process->next); diff --git a/windows/virt2phys/virt2phys_trace.h b/windows/virt2phys/virt2phys_trace.h new file mode 100644 index 0000000..ebd7618 --- /dev/null +++ b/windows/virt2phys/virt2phys_trace.h @@ -0,0 +1,49 @@ +/* SPDX-License-Identifier: BSD-3-Clause + * Copyright 2021 Dmitry Kozlyuk + */ + +/* Tracing GUID: C5C835BB-5CFB-4757-B1D4-9DD74662E212 */ +#define WPP_CONTROL_GUIDS \ + WPP_DEFINE_CONTROL_GUID( \ + VIRT2PHYS_TRACE_GUID, (C5C835BB,5CFB,4757,B1D4,9DD74662E212), \ + WPP_DEFINE_BIT(TRACE_GENERAL)) + +#define WPP_FLAG_LEVEL_LOGGER(flag, level) \ + WPP_LEVEL_LOGGER(flag) + +#define WPP_FLAG_LEVEL_ENABLED(flag, level) \ + (WPP_LEVEL_ENABLED(flag) && \ + WPP_CONTROL(WPP_BIT_ ## flag).Level >= level) + +#define WPP_LEVEL_FLAGS_LOGGER(lvl,flags) \ + WPP_LEVEL_LOGGER(flags) + +#define WPP_LEVEL_FLAGS_ENABLED(lvl, flags) \ + (WPP_LEVEL_ENABLED(flags) && \ + WPP_CONTROL(WPP_BIT_ ## flags).Level >= lvl) + +/* + * WPP orders static parameters before dynamic parameters. + * To support trace functions defined below which sets FLAGS and LEVEL, + * a custom macro must be defined to reorder the arguments + * to what the .tpl configuration file expects. + */ +#define WPP_RECORDER_FLAGS_LEVEL_ARGS(flags, lvl) \ + WPP_RECORDER_LEVEL_FLAGS_ARGS(lvl, flags) +#define WPP_RECORDER_FLAGS_LEVEL_FILTER(flags, lvl) \ + WPP_RECORDER_LEVEL_FLAGS_FILTER(lvl, flags) + +/* +begin_wpp config + +USEPREFIX(TraceError, "[%!FUNC!] "); +FUNC TraceError{FLAGS=TRACE_GENERAL, LEVEL=TRACE_LEVEL_ERROR}(MSG, ...); + +USEPREFIX(TraceWarning, "[%!FUNC!] "); +FUNC TraceWarning{FLAGS=TRACE_GENERAL, LEVEL=TRACE_LEVEL_WARNING}(MSG, ...); + +USEPREFIX(TraceInfo, "[%!FUNC!] "); +FUNC TraceInfo{FLAGS=TRACE_GENERAL, LEVEL=TRACE_LEVEL_INFORMATION}(MSG, ...); + +end_wpp +*/ -- 2.29.3