Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

How to properly use and visualize Start Stop activities in a custom ETW provider #2116

Open
exelix11 opened this issue Oct 8, 2024 · 4 comments

Comments

@exelix11
Copy link

exelix11 commented Oct 8, 2024

Context
I'm adding profiling support to an application by emitting ETW events that represent logical function calls.
Currently, after i capture an ETL trace i use a tool to convert it to json for use on speedscope.app, but this produces jsons up to 300MB which does not feel optimal.

The problem
I would like to use something like perfview or Windows Performance Analyzer directly, so i looked into the ETW activity pattern which seems to be meant for this kind of use case, however there is not much documentation.

I tried to follow this reference from ms docs, from what i understand this event pattern should allow perfview to group activities and plot them in a hierarchy view.

Several stackoverflow questions point to the fact that this should be possible, however i couldn't find any working reference code in C.

Repro

I tried writing the following code

#include <stdint.h>
#include <stdbool.h>

#include <windows.h>
#include <winmeta.h>
#include <traceloggingprovider.h>

TRACELOGGING_DEFINE_PROVIDER(
	g_profiler,
	"MyProfiler",
	// Example from https://learn.microsoft.com/it-it/windows/win32/api/traceloggingprovider/nf-traceloggingprovider-tracelogging_define_provider
	// {ce5fa4ea-ab00-5402-8b76-9f76ac858fb5}
	(0xce5fa4ea, 0xab00, 0x5402, 0x8b, 0x76, 0x9f, 0x76, 0xac, 0x85, 0x8f, 0xb5));

void RandomSleep() 
{
	Sleep(10 + rand() % 1000);
}

int main(int argc, char** argv)
{
	if (!SUCCEEDED(TraceLoggingRegister(g_profiler)))
		return -1;
	
	// Expected flamegraph:
	//  inner()         |---------|
	//  outer()  |---------------------| ... repeat

	while (true) {
		GUID outer, inner;
		if (!SUCCEEDED(CoCreateGuid(&outer))) return -2;
		if (!SUCCEEDED(CoCreateGuid(&inner))) return -3;

		printf("> enter outer\n");
		TraceLoggingWriteActivity(
			g_profiler, "Function",
			&outer, NULL,
			TraceLoggingOpcode(WINEVENT_OPCODE_START),
			TraceLoggingString("outer()", "func_name")
		);

		RandomSleep();

		printf(">> enter inner\n");
		TraceLoggingWriteActivity(
			g_profiler, "Function",
			&inner, &outer,
			TraceLoggingOpcode(WINEVENT_OPCODE_START),
			TraceLoggingString("inner()", "func_name")
		);

		RandomSleep();

		printf(">> leave inner\n");
		TraceLoggingWriteActivity(
			g_profiler, "Function",
			&inner, NULL,
			TraceLoggingOpcode(WINEVENT_OPCODE_STOP)
		);

		RandomSleep();

		printf("> leave outer\n");
		TraceLoggingWriteActivity(
			g_profiler, "Function",
			&outer, NULL,
			TraceLoggingOpcode(WINEVENT_OPCODE_STOP)
		);

		RandomSleep();
	}

	return 0;
}

You can build it from Visual Studio or just the command line tools with cl Repro.c Advapi32.lib Ole32.lib (i only tried x64 tools).

Then I start an event collection like this:

And the events are collected properly:

However, when i try to open the stacks view for start-stop activities i get Error: Could not find stack source Any Stacks (with StartStop Activities)

Questions

  • Is there a mistake in the code or have I misunderstood the purpose of start stop activities ?
  • If not activities, is there a way to plot custom function stacks in perfview ?
  • Is there a way to generate flamegraphs from this data ?
@brianrob
Copy link
Member

Your code looks generally correct to me, and so does the events view. Would you be able to share a sample trace containing these events? The error that you've described usually represents a programming error in PerfView because we can't match the view name up with a data stream. If you can share a trace, I can try to repro and debug this.

@exelix11
Copy link
Author

Thank you for replying, here's a sample trace: perfviewdata.etl.zip

To create this i did the following:

  1. built the repro with the cl command above
  2. In a clean Windows Sandbox instance started the binary
  3. Then ran PerfView.exe "/DataFile:PerfViewData.etl" /BufferSizeMB:256 /StackCompression /CircularMB:500 /KernelEvents:None /ClrEvents:None /Providers:"ce5fa4ea-ab00-5402-8b76-9f76ac858fb5" /NoGui /FocusProcess:"main.exe" /NoNGenRundown collect (this is the command auto generated by prefview itself)
  4. Manually merge and zip the trace from perfview

@brianrob
Copy link
Member

Thanks @exelix11. I'm not quite sure how you got the error Error: Could not find stack source Any Stacks (with StartStop Activities). The first issue that I see here is that your trace does not contain the event types required to even show this view. You will need:

  1. TPL events (you can enable these by specifying /TPLEvents:Default).
  2. Context switch events (you can enable these by specifying '/ThreadTime`).

I also recommend that you specify /KernelEvents:Default-Profile. This will provide enough context to resolve symbols in the stacks that you'll be looking at.

Hopefully that helps - let me know how it goes. If that doesn't work, please do share an updated trace.

@exelix11
Copy link
Author

I tried again with the following command line PerfView.exe "/DataFile:PerfViewData.etl" /BufferSizeMB:256 /StackCompression /CircularMB:500 /KernelEvents:Default-Profile /TPLEvents:Default /ThreadTime /Providers:"ce5fa4ea-ab00-5402-8b76-9f76ac858fb5" /NoGui /FocusProcess:"main.exe" /NoNGenRundown collect

And i'm still missing the start stop activities view. PerfViewData.etl.zip

To be clear and please correct me if i misunderstand this feature, i'm trying to replicate what i see in this article https://learn.microsoft.com/en-us/archive/blogs/vancem/exploring-eventsource-activity-correlation-and-causation-features so i can get a view like this with my own events:
Image
However the source code and most links of the page are now missing and this feature seems barely documented elsewhere.

This view that i'm after doesn't seem to have any information outside of the custom ETW provider, does it really need the context switch events ? I'm just talking about this simple view, I do understand they will be needed later in case i want to correlate with other events like file io.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants