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 81FA4A034F; Tue, 12 Oct 2021 02:42:37 +0200 (CEST) Received: from [217.70.189.124] (localhost [127.0.0.1]) by mails.dpdk.org (Postfix) with ESMTP id AB9E54116D; Tue, 12 Oct 2021 02:42:25 +0200 (CEST) Received: from mail-lf1-f46.google.com (mail-lf1-f46.google.com [209.85.167.46]) by mails.dpdk.org (Postfix) with ESMTP id 3EDD04113E for ; Tue, 12 Oct 2021 02:42:21 +0200 (CEST) Received: by mail-lf1-f46.google.com with SMTP id y15so80468218lfk.7 for ; Mon, 11 Oct 2021 17:42:21 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=4c+LuZVke1OoALx55cGMBLYEwL6urtFyU4WrQ8U8/mw=; b=Ovs6AoNMeHaSQq5EZmmGGPNDU+wFqaChQqyu3HghtFrWcK20uhrswqPScy8Lc4Ezty oyumgswEEqTpH7gtm6nlQOEodgjYcpNRxobQ7Xp9hkBmfzTrsIaDju/hbE2GLsRSG+CP yjYzFxcR5zZ6fl/at7qAho5leme2vF7W0xFjtNEIeSeSviI5uFy2h1Mq3A6gclDoSYh4 D0cDRBNmzym4C/9bjMYXaOKv+S4LfXcRLUOvmLLEJV/zN/KwLbIfiy+xMWMNntRHYgKm Dco28FLGshG1s4pzta5qA1zYrlawRqDogI9g+GaZwrvbdUQcGeyfOcHNTaPoR4tcd71n HARg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=4c+LuZVke1OoALx55cGMBLYEwL6urtFyU4WrQ8U8/mw=; b=s0pOzzfK4EOnDSzvqVZ0LPAdHBddMIbMINuLEI+3QFEZygDezz9wIfLeRzARVcro87 VTktuR2xZgRBpEll7fCjZesxeIU+zeFyVEO2jrSGBHpoSOiuSCs/j6M3z5/7yytcIU1J 6NL1O2FxzjthprgSzLW1/qaLkqB5zckR1naRBt6CGEA/+7X3velLGsbw5uR2xp3rgyMF Qe5Ckf2iux8KFZc7LAszLtckrMzfcMqDPNs1PKy2ueC9GUA/F09ZPkmnRT5seM2zFstg TSBW8zlyLuFUzeYVyPICLeSgQ2yTk/IcX+FygiXfibohUFZvFxJ+GP3iTNIJldZF6ggA V2eg== X-Gm-Message-State: AOAM530mtbi1z5pPPtXEbnY/wKRZJGEdCOGdTCmLkfGtgrDnPQ7cBZbH bkoV0wkP7vMjCealDB55VjGI0PmI+ug= X-Google-Smtp-Source: ABdhPJzw+yWeVSSGdcv0dM8CmSjl0NQ2fXUkG/xxQCGNhw70LTpQwjomnCwoPy5JZGv5ZscJQIiYnQ== X-Received: by 2002:ac2:5b05:: with SMTP id v5mr17405887lfn.39.1633999340676; Mon, 11 Oct 2021 17:42:20 -0700 (PDT) Received: from sovereign.. (broadband-37-110-65-23.ip.moscow.rt.ru. [37.110.65.23]) by smtp.gmail.com with ESMTPSA id a14sm813919lfi.281.2021.10.11.17.42.20 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Mon, 11 Oct 2021 17:42:20 -0700 (PDT) From: Dmitry Kozlyuk To: dev@dpdk.org Cc: Dmitry Kozlyuk , Ranjit Menon , Narcisa Ana Maria Vasile , Dmitry Malloy , Pallavi Kadam Date: Tue, 12 Oct 2021 03:42:12 +0300 Message-Id: <20211012004212.429929-4-dmitry.kozliuk@gmail.com> X-Mailer: git-send-email 2.29.3 In-Reply-To: <20211012004212.429929-1-dmitry.kozliuk@gmail.com> References: <20210526210147.1287-1-dmitry.kozliuk@gmail.com> <20211012004212.429929-1-dmitry.kozliuk@gmail.com> MIME-Version: 1.0 Content-Transfer-Encoding: 8bit Subject: [dpdk-dev] [kmods PATCH v3 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 Acked-by: Ranjit Menon --- windows/virt2phys/virt2phys.c | 18 +++++++- windows/virt2phys/virt2phys.vcxproj | 9 ++-- windows/virt2phys/virt2phys.vcxproj.filters | 3 ++ windows/virt2phys/virt2phys_logic.c | 35 ++++++++++++--- windows/virt2phys/virt2phys_trace.h | 50 +++++++++++++++++++++ 5 files changed, 103 insertions(+), 12 deletions(-) create mode 100644 windows/virt2phys/virt2phys_trace.h diff --git a/windows/virt2phys/virt2phys.c b/windows/virt2phys/virt2phys.c index 44204c9..f4d5298 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; @@ -66,6 +68,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; } @@ -131,11 +135,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_ @@ -157,12 +161,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; } @@ -187,12 +194,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; } @@ -200,6 +209,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; } @@ -207,6 +217,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; } @@ -214,6 +225,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 656b1f2..fd168b1 100644 --- a/windows/virt2phys/virt2phys.vcxproj +++ b/windows/virt2phys/virt2phys.vcxproj @@ -17,6 +17,7 @@ + @@ -63,9 +64,9 @@ - false + true true - trace.h + virt2phys_trace.h true @@ -80,9 +81,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 37b4dd4..e3ff293 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; @@ -38,6 +40,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); @@ -76,6 +80,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); @@ -208,6 +214,8 @@ virt2phys_add_block(struct virt2phys_process *process, struct virt2phys_process *existing; size_t size; + TraceInfo("ID = %p, VA = %p", process->id, block->mdl->StartVa); + existing = virt2phys_process_find(process->id); *process_exists = existing != NULL; if (existing == NULL) { @@ -217,8 +225,11 @@ virt2phys_add_block(struct virt2phys_process *process, * because decrement is done without holding the lock. */ if (virt2phys_exceeeds(g_process_count + 1, - g_params.process_count_limit)) + g_params.process_count_limit)) { + TraceWarning("Process count limit reached (%lu)", + g_params.process_count_limit); return STATUS_QUOTA_EXCEEDED; + } InsertHeadList(&g_processes, &process->next); InterlockedIncrement(&g_process_count); @@ -227,8 +238,11 @@ virt2phys_add_block(struct virt2phys_process *process, size = MmGetMdlByteCount(block->mdl); if (virt2phys_exceeeds(process->memory + size, - g_params.process_memory_limit)) + g_params.process_memory_limit)) { + TraceWarning("Process %p memory limit reached (%llu bytes)", + process->id, g_params.process_memory_limit); return STATUS_QUOTA_EXCEEDED; + } PushEntryList(&process->blocks, &block->next); process->memory += size; @@ -277,8 +291,10 @@ virt2phys_check_memory(PMDL mdl) size_t size; NTSTATUS status; - if (!virt2phys_is_contiguous(mdl)) + if (!virt2phys_is_contiguous(mdl)) { + TraceWarning("Locked region is not physycally contiguous"); return STATUS_UNSUCCESSFUL; + } virt = MmGetMdlVirtualAddress(mdl); size = MmGetMdlByteCount(mdl); @@ -288,12 +304,19 @@ virt2phys_check_memory(PMDL mdl) if (!NT_SUCCESS(status)) return status; - if (info.AllocationBase != virt || info.RegionSize != size) + if (info.AllocationBase != virt || info.RegionSize != size) { + TraceWarning("Race for the region: supplied %p (%llu bytes), locked %p (%llu bytes)", + virt, size, info.AllocationBase, info.RegionSize); return STATUS_UNSUCCESSFUL; - if (info.State != MEM_COMMIT) + } + if (info.State != MEM_COMMIT) { + TraceWarning("Attempt to lock uncommitted memory"); return STATUS_UNSUCCESSFUL; - if (info.Type != MEM_PRIVATE) + } + if (info.Type != MEM_PRIVATE) { + TraceWarning("Attempt to lock shared memory"); return STATUS_UNSUCCESSFUL; + } return status; } diff --git a/windows/virt2phys/virt2phys_trace.h b/windows/virt2phys/virt2phys_trace.h new file mode 100644 index 0000000..df863cb --- /dev/null +++ b/windows/virt2phys/virt2phys_trace.h @@ -0,0 +1,50 @@ +/* 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