Skip to content

Commit

Permalink
Add helper script to start profiling on windows
Browse files Browse the repository at this point in the history
The script uses invokes XPerf (elevating via Windows UAC dialogs if necessary) and support sample based profiling for regular timing events, as well es PMC events.
Additionally, it introduces a new event provider and event to attach information about the target process that is being profiled to the ETL file.
  • Loading branch information
albertziegenhagel committed May 1, 2024
1 parent eef85ef commit 5788d2b
Show file tree
Hide file tree
Showing 8 changed files with 310 additions and 1 deletion.
28 changes: 28 additions & 0 deletions apps/etl_file.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -31,6 +31,8 @@

#include <snail/etl/parser/records/visual_studio/diagnostics_hub.hpp>

#include <snail/etl/parser/records/snail/profiler.hpp>

#include <snail/common/detail/dump.hpp>

using namespace snail;
Expand Down Expand Up @@ -138,6 +140,7 @@ struct options
bool show_stacks = false;
bool show_config_ex = false;
bool show_vs_diag = false;
bool show_snail = false;

std::optional<std::uint32_t> process_of_interest;
bool all_processes = false;
Expand Down Expand Up @@ -209,6 +212,10 @@ options parse_command_line(int argc, char* argv[]) // NOLINT(modernize-avoid-c-a
{
result.show_vs_diag = true;
}
else if(current_arg == "--snail")
{
result.show_snail = true;
}
else if(current_arg == "--pid")
{
if(argc <= arg_i + 1) print_error_and_exit(application_path, "Missing argument for --pid.");
Expand Down Expand Up @@ -300,6 +307,7 @@ constexpr std::string_view get_guid_provider_name(const common::guid& guid)
if(guid == etl::parser::image_id_guid ||
guid == etl::parser::system_config_ex_guid) return "XPerf";
if(guid == etl::parser::vs_diagnostics_hub_guid) return "VS";
if(guid == etl::parser::snail_profiler_guid) return "Snail";
return "Unknown";
}

Expand Down Expand Up @@ -1025,6 +1033,26 @@ int main(int argc, char* argv[])
});
}

// Snail-Profiler
{
register_known_event_names<etl::parser::snail_profiler_profile_target_event_view>(observer.known_guid_event_names);
observer.register_event<etl::parser::snail_profiler_profile_target_event_view>(
[&options, &observer]([[maybe_unused]] const etl::etl_file::header_data& file_header,
const etl::common_trace_header& header,
const etl::parser::snail_profiler_profile_target_event_view& event)
{
assert(event.dynamic_size() == event.buffer().size());

if(!options.show_snail) return;
if(should_ignore(options, observer.current_event_name)) return;

std::cout << std::format("@{} {:30}: pid {}\n", header.timestamp, observer.current_event_name, event.process_id());

if(options.dump_trace_headers) common::detail::dump_buffer(header.buffer, 0, header.buffer.size(), "header");
if(options.dump_events) common::detail::dump_buffer(event.buffer(), 0, event.buffer().size(), "event");
});
}

std::cout << "\n";
file.process(observer);

Expand Down
42 changes: 42 additions & 0 deletions apps/snail-profiler.manifest.xml
Original file line number Diff line number Diff line change
@@ -0,0 +1,42 @@
<?xml version="1.0" encoding="UTF-8"?>
<instrumentationManifest
xsi:schemaLocation="http://schemas.microsoft.com/win/2004/08/events eventman.xsd"
xmlns="http://schemas.microsoft.com/win/2004/08/events"
xmlns:win="http://manifests.microsoft.com/win/2004/08/windows/events"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xmlns:xs="http://www.w3.org/2001/XMLSchema"
xmlns:trace="http://schemas.microsoft.com/win/2004/08/events/trace">
<instrumentation>
<events>
<provider name="Snail-Profiler"
guid="{460B83B6-FC11-481B-B7AA-4038CA4C4C48}" symbol="SnailProfiler"
resourceFileName="." messageFileName=".">
<events>
<event symbol="ProfilingTarget" value="1" version="0"
level="win:Informational" template="ProfilingTargetTemplate"
message="$(string.Snail-Profiler.event.1.message)">
</event>
</events>
<levels>
</levels>
<templates>
<template tid="ProfilingTargetTemplate">
<data name="ProcessId" inType="win:UInt32" outType="xs:unsignedInt">
</data>
</template>
</templates>
</provider>
</events>
</instrumentation>
<localization>
<resources culture="en-US">
<stringTable>
<string id="level.Informational" value="Information">
</string>
<string id="Snail-Profiler.event.1.message"
value="Profiling target (%1).">
</string>
</stringTable>
</resources>
</localization>
</instrumentationManifest>
122 changes: 122 additions & 0 deletions apps/snail-profiler.ps1
Original file line number Diff line number Diff line change
@@ -0,0 +1,122 @@
function Start-Profiling {
param (
[Parameter()]
[ValidateSet('Low', 'Medium', 'High')]
[string]$SamplingRate = 'Medium',

[Parameter()]
[string]$OutputName = 'profile',

[Parameter()]
[string[]]$Pmc = @(),

[Parameter(Position = 0, ValueFromRemainingArguments)]
[string[]]$Command
)

Set-Variable secondTo100Nanoseconds -Option Constant -Value 10000000
Set-Variable refTimerSamplesPerSecond -Option Constant -Value 1000
Set-Variable refCounterInterval -Option Constant -Value 65536

switch ($SamplingRate) {
{ $_ -eq 'Low' } {
$samplesPerSecond = 100
}
{ $_ -eq 'Medium' } {
$samplesPerSecond = $refTimerSamplesPerSecond
}
{ $_ -eq 'High' } {
$samplesPerSecond = 4000
}
default {
$samplesPerSecond = $refTimerSamplesPerSecond
}
}
$timerInterval = [math]::Round(1 / $samplesPerSecond * $secondTo100Nanoseconds)
$counterInterval = [math]::Round($refTimerSamplesPerSecond / $samplesPerSecond * $refCounterInterval)

$currentPrincipal = New-Object Security.Principal.WindowsPrincipal([Security.Principal.WindowsIdentity]::GetCurrent())
$isElevated = $currentPrincipal.IsInRole([Security.Principal.WindowsBuiltInRole]::Administrator)

$kernelEvents = @(
'PROC_THREAD',
'LOADER',
'PROFILE'
)

$pmcArgs = @()
if ($Pmc.Count -gt 0) {
$kernelEvents += 'PMC_PROFILE'
$pmcArgs += '-PmcProfile'
$pmcArgs += $Pmc -join ','
foreach ($counterName in $Pmc) {
$pmcArgs += '-SetProfInt'
$pmcArgs += $counterName
$pmcArgs += $counterInterval
}
# $kernelEvents += 'CSWITCH'
# $pmcArgs += '-Pmc'
# $pmcArgs += $Pmc -join ','
# $pmcArgs += 'CSWITCH'
# $pmcArgs += 'strict'
}

$kernelEventsArg = $kernelEvents -join '+'

$snailProviderGuid = [System.Guid]'{460B83B6-FC11-481B-B7AA-4038CA4C4C48}'

$xperfStartArgs = @(
'-start', 'SnailProfiling',
'-on', $snailProviderGuid.ToString(),
'-f', "`"${OutputName}_user.etl`""
'-start', '"NT Kernel Logger"',
'-on', $kernelEventsArg,
'-SetProfInt', 'Timer', $timerInterval,
'-stackwalk', 'Profile',
'-f', "`"${OutputName}_kernel.etl`""
)
$xperfStartArgs += $pmcArgs

Write-Host $xperfStartArgs

$commandExecutable = $Command[0]
$commandArguments = $Command | Select-Object -Skip 1

$eventProvider = New-Object -TypeName System.Diagnostics.Eventing.EventProvider -ArgumentList ($snailProviderGuid)
try {
$eventDescriptor = New-Object -TypeName System.Diagnostics.Eventing.EventDescriptor -ArgumentList (0x1, 0x0, 0x0, 0x4, 0x0, 0x0, 0x0);

if ($isElevated) {
$xperfProcess = Start-Process -FilePath xperf -ArgumentList $xperfStartArgs -PassThru -Wait -NoNewWindow
}
else {
$xperfProcess = Start-Process -FilePath xperf -ArgumentList $xperfStartArgs -PassThru -Wait -Verb RunAs
}
if ($xperfProcess.ExitCode -ne 0) { return; }

try {
$process = Start-Process -FilePath $commandExecutable -ArgumentList $commandArguments -PassThru -NoNewWindow
$eventProvider.WriteEvent([ref] $eventDescriptor, $process.Id) | Out-Null
$process.WaitForExit()
$process.Dispose()
}
finally {
xperf -stop SnailProfiling

if ($isElevated) {
Start-Process -FilePath xperf -ArgumentList '-stop' -Wait -NoNewWindow
}
else {
Start-Process -FilePath xperf -ArgumentList '-stop' -Wait -Verb RunAs
}
}

xperf -merge "${OutputName}_user.etl" "${OutputName}_kernel.etl" "${OutputName}.etl" #-suppresspii
if ($LASTEXITCODE -eq 0) {
Remove-Item "${OutputName}_user.etl", "${OutputName}_kernel.etl"
}
}
finally {
$eventProvider.Dispose()
}
}
13 changes: 13 additions & 0 deletions snail/analysis/detail/etl_file_process_context.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@
#include <snail/etl/parser/records/kernel/thread.hpp>
#include <snail/etl/parser/records/kernel_trace_control/image_id.hpp>
#include <snail/etl/parser/records/kernel_trace_control/system_config_ex.hpp>
#include <snail/etl/parser/records/snail/profiler.hpp>
#include <snail/etl/parser/records/visual_studio/diagnostics_hub.hpp>

using namespace snail;
Expand Down Expand Up @@ -55,6 +56,7 @@ etl_file_process_context::etl_file_process_context()
register_event<etl::parser::stackwalk_v2_stack_event_view>();
register_event<etl::parser::image_id_v2_dbg_id_pdb_info_event_view>();
register_event<etl::parser::vs_diagnostics_hub_target_profiling_started_event_view>();
register_event<etl::parser::snail_profiler_profile_target_event_view>();
}

etl_file_process_context::~etl_file_process_context() = default;
Expand Down Expand Up @@ -582,6 +584,17 @@ void etl_file_process_context::handle_event(const etl::etl_file::header_data& /*
.start_timestamp = header.timestamp};
}

void etl_file_process_context::handle_event(const etl::etl_file::header_data& /*file_header*/,
const etl::common_trace_header& header,
const etl::parser::snail_profiler_profile_target_event_view& event)
{
const auto process_id = event.process_id();

profiler_processes_[process_key{process_id, header.timestamp}] = profiler_process_info{
.process_id = process_id,
.start_timestamp = header.timestamp};
}

const std::unordered_map<etl_file_process_context::sample_source_id_t, std::u16string>& etl_file_process_context::sample_source_names() const
{
return sample_source_names_;
Expand Down
3 changes: 2 additions & 1 deletion snail/analysis/detail/etl_file_process_context.hpp
Original file line number Diff line number Diff line change
Expand Up @@ -38,7 +38,7 @@ struct perfinfo_v3_sampled_profile_interval_event_view;
struct stackwalk_v2_stack_event_view;
struct image_id_v2_dbg_id_pdb_info_event_view;
struct vs_diagnostics_hub_target_profiling_started_event_view;
struct vs_diagnostics_hub_target_profiling_stopped_event_view;
struct snail_profiler_profile_target_event_view;

} // namespace snail::etl::parser

Expand Down Expand Up @@ -166,6 +166,7 @@ class etl_file_process_context
void handle_event(const etl::etl_file::header_data& file_header, const etl::common_trace_header& header, const etl::parser::stackwalk_v2_stack_event_view& event);
void handle_event(const etl::etl_file::header_data& file_header, const etl::common_trace_header& header, const etl::parser::image_id_v2_dbg_id_pdb_info_event_view& event);
void handle_event(const etl::etl_file::header_data& file_header, const etl::common_trace_header& header, const etl::parser::vs_diagnostics_hub_target_profiling_started_event_view& event);
void handle_event(const etl::etl_file::header_data& file_header, const etl::common_trace_header& header, const etl::parser::snail_profiler_profile_target_event_view& event);

etl::dispatching_event_observer observer_;

Expand Down
40 changes: 40 additions & 0 deletions snail/etl/parser/records/snail/profiler.hpp
Original file line number Diff line number Diff line change
@@ -0,0 +1,40 @@

#pragma once

#include <cstdint>

#include <array>
#include <optional>
#include <string>

#include <snail/common/guid.hpp>

#include <snail/etl/parser/extract.hpp>
#include <snail/etl/parser/records/identifier.hpp>
#include <snail/etl/parser/utility.hpp>

namespace snail::etl::parser {

constexpr inline auto snail_profiler_guid = common::guid{
0x460b'83b6, 0xfc11, 0x481b, {0xb7, 0xaa, 0x40, 0x38, 0xca, 0x4c, 0x4c, 0x48}
};

struct snail_profiler_profile_target_event_view : private extract_view_dynamic_base
{
static inline constexpr std::string_view event_name = "SnailProf-ProfTarget";
static inline constexpr std::uint16_t event_version = 0;
static inline constexpr auto event_types = std::array{
event_identifier_guid{snail_profiler_guid, 1, "ProfTarget"}
};

using extract_view_dynamic_base::buffer;
using extract_view_dynamic_base::extract_view_dynamic_base;

inline auto process_id() const { return extract<std::uint32_t>(dynamic_offset(0, 0)); }

static inline constexpr std::size_t static_size = 4;

inline std::size_t dynamic_size() const { return static_size; }
};

} // namespace snail::etl::parser
50 changes: 50 additions & 0 deletions tests/unit/analysis/etl_file_process_context.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,7 @@
#include <snail/etl/parser/records/kernel_trace_control/image_id.hpp>
#include <snail/etl/parser/records/kernel_trace_control/system_config_ex.hpp>

#include <snail/etl/parser/records/snail/profiler.hpp>
#include <snail/etl/parser/records/visual_studio/diagnostics_hub.hpp>

#include <snail/common/cast.hpp>
Expand Down Expand Up @@ -544,6 +545,29 @@ void push_prof_started_event(const etl::etl_file::header_data& file_header,
observer.handle(file_header, event_header, event_data.subspan(0, event_data_size));
}

void push_snail_prof_target_event(const etl::etl_file::header_data& file_header,
etl::event_observer& observer,
std::span<std::byte> buffer,
std::uint64_t timestamp,
std::uint32_t process_id)
{
std::ranges::fill(buffer, std::byte{});

const auto event_data = buffer.subspan(etl::parser::full_header_trace_header_view::static_size);

set_at(event_data, 0, process_id);
const auto event_data_size = 4;

assert(etl::parser::snail_profiler_profile_target_event_view(event_data, file_header.pointer_size).process_id() == process_id);

const auto event_header = make_full_trace_header(file_header, buffer, timestamp, event_data_size,
etl::parser::snail_profiler_profile_target_event_view::event_version,
etl::parser::snail_profiler_guid,
1);

observer.handle(file_header, event_header, event_data.subspan(0, event_data_size));
}

// we use the same file_header for all tests (except for the pointer size, it doesn't really matter anyways)
static const etl::etl_file::header_data file_header = {
.start_time = common::nt_sys_time(common::nt_duration(100)),
Expand Down Expand Up @@ -1297,3 +1321,29 @@ TEST(EtlFileProcessContext, VsDiagnosticsHub)
EXPECT_EQ(process_456.process_id, 456);
EXPECT_EQ(process_456.start_timestamp, 20);
}

TEST(EtlFileProcessContext, SnailProfiler)
{
etl_file_process_context context;

std::array<std::uint8_t, 1024> buffer;
const auto writable_bytes_buffer = std::as_writable_bytes(std::span(buffer));

push_snail_prof_target_event(file_header, context.observer(), writable_bytes_buffer,
10, 123);
push_snail_prof_target_event(file_header, context.observer(), writable_bytes_buffer,
20, 456);

context.finish();

const auto& processes = context.profiler_processes();
EXPECT_EQ(processes.size(), 2);

const auto process_123 = processes.at(etl_file_process_context::process_key{123, 10});
EXPECT_EQ(process_123.process_id, 123);
EXPECT_EQ(process_123.start_timestamp, 10);

const auto process_456 = processes.at(etl_file_process_context::process_key{456, 20});
EXPECT_EQ(process_456.process_id, 456);
EXPECT_EQ(process_456.start_timestamp, 20);
}
Loading

0 comments on commit 5788d2b

Please sign in to comment.