diff options
Diffstat (limited to 'src')
| -rw-r--r-- | src/main.c | 491 |
1 files changed, 277 insertions, 214 deletions
@@ -1,27 +1,114 @@ #include <stdint.h> -#include <string.h> #include <stdio.h> +#include <assert.h> #include <math.h> #include <Windows.h> + +#define INITGUID #include <evntrace.h> #include <evntprov.h> +#include <evntcons.h> + +#include "events.h" + +typedef uint32_t u32; // #define REAL_TIME_MODE -struct EventTracePropertyData { +#define SOURCE_TIMER "Timer" +#define SOURCE_TIMER_INDEX 0U +#define SOURCE_TOTAL_ISSUES "TotalIssues" +#define SOURCE_TOTAL_ISSUES_INDEX 2U +#define SOURCE_BRANCH_INSTRUCTIONS "BranchInstructions" +#define SOURCE_BRANCH_INSTRUCTIONS_INDEX 6U + +const char* PMC_SOURCES[] = { + SOURCE_TIMER, + "", + SOURCE_TOTAL_ISSUES, + "", + "", + "", + SOURCE_BRANCH_INSTRUCTIONS, + "", + "DcacheMisses", + "IcacheMisses", + "CacheMisses", + "BranchMispredictions", + "", + "", + "", + "", + "", + "", + "", + "TotalCycles", + "IcacheIssues", + "DcacheAccesses", + "", + "", + "", + "", + "InstructionsRetired", + "IcacheL2Hit", + "DcacheL2Hit", + "RetiredMacroOps", + "RetiredTakenBranchInstructions", + "RetiredTakenBranchMispredictions", + "RetiredFarControlTransfers", + "RetiredNearReturns", + "RetiredNearReturnMispredictions", + "RetiredIndirectBranchMispredictions", + "RetiredConditionalBranchInstructions", + "RetiredConditionalBranchMispredictions", + "RetiredFusedInstructions", + "VariableTargetPredictions", + "EarlyRedirects", + "InefectiveSoftwarePrefetches", + "TlbFlushes", + "SmiReceived", + "DemandDcacheFills", + "RetiredLockInstructions", + "BusLock", + "Retiredx87Instructions", + "RetiredMmxInstructions", + "RetiredSseInstructions", +}; +const u32 PMC_SOURCES_COUNT = 49U; + +void log_error(DWORD dw) { + // Retrieve the system error message for the last-error code + LPVOID lpMsgBuf; + + FormatMessage( + FORMAT_MESSAGE_ALLOCATE_BUFFER | + FORMAT_MESSAGE_FROM_SYSTEM | + FORMAT_MESSAGE_IGNORE_INSERTS, + NULL, + dw, + MAKELANGID(LANG_NEUTRAL, SUBLANG_DEFAULT), + (LPTSTR) &lpMsgBuf, + 0, NULL ); + + // Display the error message and exit the process + printf("error %lu: %s\n", dw, (char*)lpMsgBuf); + + LocalFree(lpMsgBuf); +} + +struct event_trace_property_data { EVENT_TRACE_PROPERTIES_V2 props; #if !defined(REAL_TIME_MODE) char log_file_name[128]; #endif char logger_name[1024]; - char buffer[64 * 1024U]; + char buffer[256 * 1024U]; } data = { .props = { .Wnode = { - .BufferSize = offsetof(struct EventTracePropertyData, buffer), + .BufferSize = offsetof(struct event_trace_property_data, buffer), .Flags = WNODE_FLAG_TRACED_GUID | WNODE_FLAG_VERSIONED_PROPERTIES, - .Guid = { 0x9E814AAD, 0x3204, 0x11D2, 0x9A, 0x82, 0x00, 0x60, 0x08, 0xA8, 0x69, 0x39 }, }, .BufferSize = sizeof(data.buffer), .MinimumBuffers = 4U, @@ -39,205 +126,198 @@ struct EventTracePropertyData { #if defined(REAL_TIME_MODE) .LogFileMode = EVENT_TRACE_REAL_TIME_MODE, #else - .LogFileNameOffset = offsetof(struct EventTracePropertyData, log_file_name), + .LogFileNameOffset = offsetof(struct event_trace_property_data, log_file_name), #endif - .LoggerNameOffset = offsetof(struct EventTracePropertyData, logger_name), + .LoggerNameOffset = offsetof(struct event_trace_property_data, logger_name), }, +#if !defined(REAL_TIME_MODE) .log_file_name = "test_etw_log.etl", +#endif .logger_name = KERNEL_LOGGER_NAMEA, }; -GUID system_profile_provider_guid = { 0xbfeb0324, 0x1cee, 0x496f, 0xa4, 0x09, 0x2a, 0xc2, 0xb4, 0x8a, 0x63, 0x22 }; -GUID thread_provider_guid = { 0x3d6fa8d1, 0xfe05, 0x11d0, 0x9d, 0xda, 0x00, 0xc0, 0x4f, 0xd7, 0xba, 0x7c }; -GUID process_provider_guid = { 0x3d6fa8d0, 0xfe05, 0x11d0, 0x9d, 0xda, 0x00, 0xc0, 0x4f, 0xd7, 0xba, 0x7c }; -GUID perf_info_provider_guid = { 0xce1dbfb4, 0x137e, 0x4da6, 0x87, 0xb0, 0x3f, 0x59, 0xaa, 0x10, 0x2c, 0xbc }; +DWORD pid = 0U; -void LogError(DWORD dw) -{ - // Retrieve the system error message for the last-error code - LPVOID lpMsgBuf; +void PeventRecordCallback(PEVENT_RECORD pEventRecord) { + // if (pEventRecord->EventHeader.ProcessId != pid) { + // return; + // } + EVENT_HEADER* header = &pEventRecord->EventHeader; + u32* sources = (u32*)pEventRecord->UserContext; - FormatMessage( - FORMAT_MESSAGE_ALLOCATE_BUFFER | - FORMAT_MESSAGE_FROM_SYSTEM | - FORMAT_MESSAGE_IGNORE_INSERTS, - NULL, - dw, - MAKELANGID(LANG_NEUTRAL, SUBLANG_DEFAULT), - (LPTSTR) &lpMsgBuf, - 0, NULL ); + PEVENT_HEADER_EXTENDED_DATA_ITEM extended_data = pEventRecord->ExtendedData; + PEVENT_HEADER_EXTENDED_DATA_ITEM cur_data = extended_data; + for (u32 index = 0U; index < pEventRecord->ExtendedDataCount; index++, cur_data++) { + if (cur_data->ExtType == EVENT_HEADER_EXT_TYPE_PMC_COUNTERS) { + printf("PID: %lx, TID: %lx\n", header->ProcessId, header->ThreadId); + ULONG64* pmc = (ULONG64*)cur_data->DataPtr; + size_t pmc_count = cur_data->DataSize / sizeof(pmc[0U]); + for (u32 pmc_index = 0U; pmc_index < pmc_count; pmc_index++, pmc++) { + printf("%s: %llu\n", PMC_SOURCES[sources[pmc_index]], *pmc); + } + } + } +} - // Display the error message and exit the process - printf("error %lu: %s\n", dw, (char*)lpMsgBuf); +EVENT_TRACE_LOGFILEA trace_log = { +#if defined(REAL_TIME_MODE) + .LoggerName = KERNEL_LOGGER_NAMEA, + .ProcessTraceMode = PROCESS_TRACE_MODE_REAL_TIME | PROCESS_TRACE_MODE_EVENT_RECORD, +#else + .LogFileName = "test_etw_log.etl", + .ProcessTraceMode = PROCESS_TRACE_MODE_EVENT_RECORD, +#endif + .EventRecordCallback = &PeventRecordCallback, + // .LogFileMode = EVENT_TRACE_SYSTEM_LOGGER_MODE, +}; - LocalFree(lpMsgBuf); +u32 end_trace(TRACEHANDLE handle) { + ULONG res = 0U; + if ((res = ControlTraceA(handle, KERNEL_LOGGER_NAMEA, (EVENT_TRACE_PROPERTIES*)&data.props, EVENT_TRACE_CONTROL_STOP)) != ERROR_SUCCESS) { + log_error(res); + return 1U; + } + return 0U; } -int main() { - LPSTR log_file_name = "test_etw_log.etl"; - TRACEHANDLE trace_handle = 0U; +u32 begin_trace(TRACEHANDLE* handle, u32* pmc_sources, u32 sources_size) { ULONG res = 0U; - if ((res = StartTraceA(&trace_handle, KERNEL_LOGGER_NAMEA, (EVENT_TRACE_PROPERTIES*)&data.props)) != ERROR_SUCCESS) { - LogError(res); - goto close_trace; + + data.props.Wnode.Guid = SystemTraceControlGuid; + if ((res = StartTraceA(handle, KERNEL_LOGGER_NAMEA, (EVENT_TRACE_PROPERTIES*)&data.props)) != ERROR_SUCCESS) { + log_error(res); + return 1U; + } + + if ((res = TraceSetInformation(*handle, TracePmcCounterListInfo, pmc_sources, sources_size)) != ERROR_SUCCESS) { // PMCs to collect + log_error(res); + end_trace(*handle); + return 1U; } + return 0U; +} + +u32 begin_PMCs_capture(TRACEHANDLE handle) { + CLASSIC_EVENT_ID events[] = { + EventProcessPMC, + EventProcessPMCRundown, + }; + ULONG res = 0U; + if ((res = TraceSetInformation(handle, TracePmcEventListInfo, &events, sizeof(events))) != ERROR_SUCCESS) { // Events on which we collect PMCs + log_error(res); + end_trace(handle); + return 1U; + } + return 0U; +} + +u32 end_PMCs_capture(TRACEHANDLE handle) { + ULONG res = 0U; + // TODO: Make it stop + // if ((res = TraceSetInformation(handle, TracePmcEventListInfo, NULL, 0U)) != ERROR_SUCCESS) { + // log_error(res); + // end_trace(handle); + // return 1U; + // } + return 0U; +} + +u32 PMC_sources_from_names(const char** names, u32 names_count, u32* sources, u32* sources_count) { + for (u32 name_index = 0U; name_index < names_count; name_index++) { + for (u32 list_index = 0U; list_index < PMC_SOURCES_COUNT; list_index++) { + if (strcmp(names[name_index], PMC_SOURCES[list_index]) == 0U) { + sources[*sources_count] = list_index; + (*sources_count)++; + } + } + } + + return (names_count != *sources_count); +} + +u32 list_sources() { char* profile_source_infos[sizeof(PROFILE_SOURCE_INFO) * 256U]; ULONG bwrite = 0U; + ULONG res = 0U; if ((res = TraceQueryInformation(0U, TraceProfileSourceListInfo, (void*)profile_source_infos, sizeof(profile_source_infos), &bwrite)) != ERROR_SUCCESS) { - LogError(res); - goto close_trace; + log_error(res); + return 1U; } - ULONG masks[8U] = { - // EVENT_TRACE_FLAG_PROFILE | - EVENT_TRACE_FLAG_INTERRUPT | - EVENT_TRACE_FLAG_SYSTEMCALL | - EVENT_TRACE_FLAG_DPC | - EVENT_TRACE_FLAG_THREAD | - EVENT_TRACE_FLAG_CSWITCH | - EVENT_TRACE_FLAG_DISPATCHER | - EVENT_TRACE_FLAG_PROCESS | - EVENT_TRACE_FLAG_PROCESS_COUNTERS, - 0x20000400, // PERF_PERF_PMC - 0U, - 0U, - 0U, - 0U, - 0U, - 0U, - }; - if ((res = TraceSetInformation(trace_handle, TraceSystemTraceEnableFlagsInfo, &masks, sizeof(masks))) != ERROR_SUCCESS) { - LogError(res); - goto close_trace; - } + PROFILE_SOURCE_INFO* cur_profile_source_info = (PROFILE_SOURCE_INFO*)&profile_source_infos[0U]; + while (1) { + printf("%lu: %S\n", cur_profile_source_info->Source, cur_profile_source_info->Description); - uint32_t pmc_sources[] = { 6U, 19U, }; // instructions count, branch count - if ((res = TraceSetInformation(trace_handle, TracePmcCounterListInfo, pmc_sources, sizeof(pmc_sources))) != ERROR_SUCCESS) { // PMCs to collect - LogError(res); - goto close_trace; + if (cur_profile_source_info->NextEntryOffset == 0U) { + break; + } + + cur_profile_source_info = (PROFILE_SOURCE_INFO*)((char*)cur_profile_source_info + cur_profile_source_info->NextEntryOffset); } - CLASSIC_EVENT_ID events[] = { - { - .EventGuid = perf_info_provider_guid, - .Type = 46U, - .Reserved = { 0U }, - }, - { - .EventGuid = perf_info_provider_guid, - .Type = 51U, - .Reserved = { 0U }, - }, - { - .EventGuid = perf_info_provider_guid, - .Type = 52U, - .Reserved = { 0U }, - }, - { - .EventGuid = perf_info_provider_guid, - .Type = 66U, - .Reserved = { 0U }, - }, - { - .EventGuid = perf_info_provider_guid, - .Type = 67U, - .Reserved = { 0U }, - }, - { - .EventGuid = perf_info_provider_guid, - .Type = 68U, - .Reserved = { 0U }, - }, - { - .EventGuid = perf_info_provider_guid, - .Type = 69U, - .Reserved = { 0U }, - }, - { - .EventGuid = thread_provider_guid, - .Type = 1U, - .Reserved = { 0U }, - }, - { - .EventGuid = thread_provider_guid, - .Type = 2U, - .Reserved = { 0U }, - }, - { - .EventGuid = thread_provider_guid, - .Type = 3U, - .Reserved = { 0U }, - }, - { - .EventGuid = thread_provider_guid, - .Type = 4U, - .Reserved = { 0U }, - }, - { - .EventGuid = thread_provider_guid, - .Type = 36U, - .Reserved = { 0U }, - }, - { - .EventGuid = thread_provider_guid, - .Type = 50U, - .Reserved = { 0U }, - }, - { - .EventGuid = process_provider_guid, - .Type = 1U, - .Reserved = { 0U }, - }, - { - .EventGuid = process_provider_guid, - .Type = 2U, - .Reserved = { 0U }, - }, - { - .EventGuid = process_provider_guid, - .Type = 3U, - .Reserved = { 0U }, - }, - { - .EventGuid = process_provider_guid, - .Type = 4U, - .Reserved = { 0U }, - }, - { - .EventGuid = process_provider_guid, - .Type = 32U, - .Reserved = { 0U }, - }, - { - .EventGuid = process_provider_guid, - .Type = 33U, - .Reserved = { 0U }, - }, - { - .EventGuid = process_provider_guid, - .Type = 39U, - .Reserved = { 0U }, - }, + return 0U; +} + +int main() { + pid = GetProcessId(GetCurrentProcess()); + + TRACEHANDLE handle; + u32 PMCs[] = { + SOURCE_TOTAL_ISSUES_INDEX, + SOURCE_BRANCH_INSTRUCTIONS_INDEX, }; - uint32_t index = 0U; - if ((res = TraceSetInformation(trace_handle, TracePmcEventListInfo, &events[index], sizeof(events))) != ERROR_SUCCESS) { // Events on which we collect PMCs - LogError(res); - goto close_trace; + static_assert(sizeof(PMCs) / sizeof(PMCs[0U]) <= 4U, "Too much PMCs"); + if (begin_trace(&handle, PMCs, sizeof(PMCs))) { + end_trace(handle); + return 1; } - // Looks like we aren't allowed to use system providers without some special previlegies, to be investigated - // EnableTraceEx2(trace_handle, &system_profile_provider_guid, EVENT_CONTROL_CODE_ENABLE_PROVIDER, TRACE_LEVEL_VERBOSE, ~0U, 0U, 0U, NULL); - if ((res = EnableTraceEx2(trace_handle, &perf_info_provider_guid, EVENT_CONTROL_CODE_ENABLE_PROVIDER, TRACE_LEVEL_VERBOSE, ~0U, 0U, 0U, NULL)) != ERROR_SUCCESS) { - LogError(res); - goto close_trace; + + ULONG res = 0U; +#ifdef REAL_TIME_MODE + TRACEHANDLE pt_handle = OpenTraceA(&trace_log); + if (pt_handle == INVALID_PROCESSTRACE_HANDLE) { + log_error(GetLastError()); + end_trace(handle); } - if ((res = EnableTraceEx2(trace_handle, &process_provider_guid, EVENT_CONTROL_CODE_ENABLE_PROVIDER, TRACE_LEVEL_VERBOSE, ~0U, 0U, 0U, NULL)) != ERROR_SUCCESS) { - LogError(res); - goto close_trace; + + if ((res = ProcessTrace(&pt_handle, 1U, NULL, NULL)) != ERROR_SUCCESS) { + log_error(res); + end_trace(handle); } - if ((res = EnableTraceEx2(trace_handle, &thread_provider_guid, EVENT_CONTROL_CODE_ENABLE_PROVIDER, TRACE_LEVEL_VERBOSE, ~0U, 0U, 0U, NULL)) != ERROR_SUCCESS) { - LogError(res); - goto close_trace; +#endif + + // ULONG masks[8U] = { + // // EVENT_TRACE_FLAG_PROFILE | + // EVENT_TRACE_FLAG_INTERRUPT | + // EVENT_TRACE_FLAG_SYSTEMCALL | + // EVENT_TRACE_FLAG_DPC | + // EVENT_TRACE_FLAG_THREAD | + // EVENT_TRACE_FLAG_CSWITCH | + // EVENT_TRACE_FLAG_DISPATCHER | + // EVENT_TRACE_FLAG_PROCESS | + // EVENT_TRACE_FLAG_PROCESS_COUNTERS, + // // 0x20000400, // PERF_PERF_PMC + // 0U, + // 0U, + // 0U, + // 0U, + // 0U, + // 0U, + // }; + // if ((res = TraceSetInformation(trace_handle, TraceSystemTraceEnableFlagsInfo, &masks, sizeof(masks))) != ERROR_SUCCESS) { + // log_error(res); + // end_trace(handle); + // } + + // if ((res = EnableTraceEx2(trace_handle, &SystemProcessProviderGuid, EVENT_CONTROL_CODE_ENABLE_PROVIDER, TRACE_LEVEL_VERBOSE, ~0U, 0U, 0U, NULL)) != ERROR_SUCCESS) { + // log_error(res); + // end_trace(handle); + // } + + if (begin_PMCs_capture(handle)) { + end_trace(handle); + return 1; } int i = 0; @@ -248,51 +328,34 @@ int main() { i++; } + if (end_PMCs_capture(handle)) { + end_trace(handle); + return 1; + } - // EVENT_TRACE_LOGFILEA log = { 0U }; - // strncpy(log.LogFileName, log_file_name, strlen(log_file_name)); - // strncpy(log.LoggerName, logger_name, strlen(logger_name)); - // TRACEHANDLE pt_handle = OpenTraceA(&log); - // if (pt_handle == INVALID_PROCESSTRACE_HANDLE) { - // ErrorExit(); - // return 1; - // } - // uint32_t counter = 0U; - - // while (counter < ~0U) { - // // counter++; + // if ((res = EnableTraceEx2(trace_handle, &SystemProcessProviderGuid, EVENT_CONTROL_CODE_DISABLE_PROVIDER, TRACE_LEVEL_VERBOSE, ~0U, 0U, 0U, NULL)) != ERROR_SUCCESS) { + // log_error(res); + // end_trace(handle); // } - - if ((res = EnableTraceEx2(trace_handle, &thread_provider_guid, EVENT_CONTROL_CODE_DISABLE_PROVIDER, TRACE_LEVEL_VERBOSE, ~0U, 0U, 0U, NULL)) != ERROR_SUCCESS) { - LogError(res); - goto close_trace; - } - if ((res = EnableTraceEx2(trace_handle, &process_provider_guid, EVENT_CONTROL_CODE_DISABLE_PROVIDER, TRACE_LEVEL_VERBOSE, ~0U, 0U, 0U, NULL)) != ERROR_SUCCESS) { - LogError(res); - goto close_trace; - } - if ((res = EnableTraceEx2(trace_handle, &perf_info_provider_guid, EVENT_CONTROL_CODE_DISABLE_PROVIDER, TRACE_LEVEL_VERBOSE, ~0U, 0U, 0U, NULL)) != ERROR_SUCCESS) { - LogError(res); - goto close_trace; - goto close_trace; + if (end_trace(handle)) { + return 1; } +#if !defined(REAL_TIME_MODE) + trace_log.Context = PMCs; + TRACEHANDLE pt_handle = OpenTraceA(&trace_log); + if (pt_handle == INVALID_PROCESSTRACE_HANDLE) { + log_error(GetLastError()); + } - PROFILE_SOURCE_INFO* cur_profile_source_info = (PROFILE_SOURCE_INFO*)&profile_source_infos[0U]; - while (1) { - printf("%S\n", cur_profile_source_info->Description); - - if (cur_profile_source_info->NextEntryOffset == 0U) { - break; - } - - cur_profile_source_info = (PROFILE_SOURCE_INFO*)((char*)cur_profile_source_info + cur_profile_source_info->NextEntryOffset); + if ((res = ProcessTrace(&pt_handle, 1U, NULL, NULL)) != ERROR_SUCCESS) { + log_error(res); } +#endif -close_trace: - if ((res = ControlTraceA(trace_handle, KERNEL_LOGGER_NAMEA, (EVENT_TRACE_PROPERTIES*)&data.props, EVENT_TRACE_CONTROL_STOP)) != ERROR_SUCCESS) { - LogError(res); + if ((res = CloseTrace(pt_handle)) != ERROR_SUCCESS) { + log_error(res); return 1; } |