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 D6D18A0546; Wed, 26 May 2021 23:02:24 +0200 (CEST) Received: from [217.70.189.124] (localhost [127.0.0.1]) by mails.dpdk.org (Postfix) with ESMTP id 8AC5841115; Wed, 26 May 2021 23:02:04 +0200 (CEST) Received: from mail-lf1-f44.google.com (mail-lf1-f44.google.com [209.85.167.44]) by mails.dpdk.org (Postfix) with ESMTP id 0BFFE410E6 for ; Wed, 26 May 2021 23:02:00 +0200 (CEST) Received: by mail-lf1-f44.google.com with SMTP id j6so4597253lfr.11 for ; Wed, 26 May 2021 14:01:59 -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=mHIWlvJvsetZOZSHZbPP3aO2UJoWOWIrAtPW0s2kb2U=; b=BmXOg8NIk+dppkESnfQYyGwBOMvb7aZFF807eIjuRIc5ktDljPLMKD9dIohfr1+AmB JM3mcY/DdLESxkErfOubDwin4bCUb4JGIX+BlczOoLuRN3vWqKGm+I+SXQaTXrfzgjI6 szlAy9DWyBmctX5TDdTkup3t73l4wloGuANPvyDZk8yJo6fbcvsVOmXojkTRYc1PMsAn NRtUpf1Iux/2pb5Yp/Bo/9/s4TpC8hE6mCNhLtnZVPO8qdo07FmfLAsU7d2h1hobAbJj 2YaxQepwVbn/VzeV9gtCYSbU5lF3cZbyOxSYkh3ajcovVj3v6vR/BsqD272M/RRkGOIO 5XbQ== 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=mHIWlvJvsetZOZSHZbPP3aO2UJoWOWIrAtPW0s2kb2U=; b=Khi21Yh5bEw8mHbwO0+trevNYO/97KvjoOVksvaiyBGtdpyquHhCLzw4yON5emV3Ol DuSttu1FGM4TW69s67TP/KOhcEEWfCSkFN77psfb1M2Mr1MWPkpOySFNIqyto8KjeVbT QKoRG8huvg65noAYQBe8TUIHguh/gOH5ScZ6i6pY7MYJglrd59QEqZDhfyS7UIGhinya xcBNyJsw57y5fNtONbOrFa/HRQbvDswy3MaRZrldI0YiCDZvOP7Wh7DZFq7IxZHThfOP gZtX7cqb0ugRlkb4Spy2YdE3a7EkvhbgdGPIqoOayusBZHzPb8ZLvrO3z8vqbjcrjubD GDpQ== X-Gm-Message-State: AOAM533S+o+h056h3F8p4HC2xelI7HeFBbnQpLz26TLXPoxxJItROyY3 eQKtxTOcKKAdDFYd/DRHsqNccu9pQjngVg== X-Google-Smtp-Source: ABdhPJwHi+DsGgqIOjBxByRFEP+awWEo533wHpWT+PuW2oklFThKn+c3nn5CQnEXfj0kyulhN0OS1Q== X-Received: by 2002:a05:6512:1328:: with SMTP id x40mr7973lfu.589.1622062919250; Wed, 26 May 2021 14:01:59 -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 u28sm13205lfk.172.2021.05.26.14.01.58 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Wed, 26 May 2021 14:01:58 -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: Thu, 27 May 2021 00:01:47 +0300 Message-Id: <20210526210147.1287-5-dmitry.kozliuk@gmail.com> X-Mailer: git-send-email 2.29.3 In-Reply-To: <20210526210147.1287-1-dmitry.kozliuk@gmail.com> References: <20210501171837.13282-1-dmitry.kozliuk@gmail.com> <20210526210147.1287-1-dmitry.kozliuk@gmail.com> MIME-Version: 1.0 Content-Transfer-Encoding: 8bit Subject: [dpdk-dev] [kmods PATCH v2 4/4] 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 --- Comment at the bottom of virt2phys_trace.h is consumed by WPP code generator, which is the reason it has no leading asterisks. windows/virt2phys/virt2phys.c | 18 +++++++- windows/virt2phys/virt2phys.vcxproj | 5 ++- windows/virt2phys/virt2phys.vcxproj.filters | 3 ++ windows/virt2phys/virt2phys_logic.c | 35 ++++++++++++--- windows/virt2phys/virt2phys_trace.h | 50 +++++++++++++++++++++ 5 files changed, 101 insertions(+), 10 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 b462493..c9f884a 100644 --- a/windows/virt2phys/virt2phys.vcxproj +++ b/windows/virt2phys/virt2phys.vcxproj @@ -41,6 +41,7 @@ + @@ -169,9 +170,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 acd159f..6afff72 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