diff --git a/ProjFS.Mac/PrjFS.xcworkspace/xcshareddata/xcschemes/PrjFS.xcscheme b/ProjFS.Mac/PrjFS.xcworkspace/xcshareddata/xcschemes/PrjFS.xcscheme index 558130ad60..389d98c9a2 100644 --- a/ProjFS.Mac/PrjFS.xcworkspace/xcshareddata/xcschemes/PrjFS.xcscheme +++ b/ProjFS.Mac/PrjFS.xcworkspace/xcshareddata/xcschemes/PrjFS.xcscheme @@ -92,7 +92,7 @@ (arg0); vnode_t currentVnode = reinterpret_cast(arg1); @@ -296,6 +300,7 @@ static int HandleVnodeOperation( context, currentVnode, action, + functionSample, &root, &vnodeType, ¤tVnodeFileFlags, @@ -343,6 +348,8 @@ static int HandleVnodeOperation( // Recursively expand directory on delete to ensure child placeholders are created before rename operations if (isDeleteAction || FileFlagsBitIsSet(currentVnodeFileFlags, FileFlags_IsEmpty)) { + functionSample.SetProbe(Probe_VnodeOp_PopulatePlaceholderDirectory); + if (!TrySendRequestAndWaitForResponse( root, isDeleteAction ? @@ -376,6 +383,8 @@ static int HandleVnodeOperation( { if (FileFlagsBitIsSet(currentVnodeFileFlags, FileFlags_IsEmpty)) { + functionSample.SetProbe(Probe_VnodeOp_HydratePlaceholderFile); + if (!TrySendRequestAndWaitForResponse( root, MessageType_KtoU_HydrateFile, @@ -416,6 +425,8 @@ static int HandleFileOpOperation( { atomic_fetch_add(&s_numActiveKauthEvents, 1); + ProfileSample functionSample(Probe_FileOp); + vfs_context_t context = vfs_context_create(NULL); vnode_t currentVnodeFromPath = NULLVP; @@ -567,6 +578,7 @@ static bool ShouldHandleVnodeOpEvent( vfs_context_t context, const vnode_t vnode, kauth_action_t action, + ProfileSample& operationSample, // Out params: VirtualizationRootHandle* root, @@ -582,6 +594,7 @@ static bool ShouldHandleVnodeOpEvent( if (!VirtualizationRoot_VnodeIsOnAllowedFilesystem(vnode)) { + operationSample.SetProbe(Probe_Op_EarlyOut); *kauthResult = KAUTH_RESULT_DEFER; return false; } @@ -589,16 +602,22 @@ static bool ShouldHandleVnodeOpEvent( *vnodeType = vnode_vtype(vnode); if (ShouldIgnoreVnodeType(*vnodeType, vnode)) { + operationSample.SetProbe(Probe_Op_EarlyOut); *kauthResult = KAUTH_RESULT_DEFER; return false; } - *vnodeFileFlags = ReadVNodeFileFlags(vnode, context); + { + ProfileSample readflags(Probe_ReadFileFlags); + *vnodeFileFlags = ReadVNodeFileFlags(vnode, context); + } + if (!FileFlagsBitIsSet(*vnodeFileFlags, FileFlags_IsInVirtualizationRoot)) { // This vnode is not part of ANY virtualization root, so exit now before doing any more work. // This gives us a cheap way to avoid adding overhead to IO outside of a virtualization root. + operationSample.SetProbe(Probe_Op_NoVirtualizationRootFlag); *kauthResult = KAUTH_RESULT_DEFER; return false; } @@ -618,14 +637,21 @@ static bool ShouldHandleVnodeOpEvent( // get called again, so we lose the opportunity to hydrate the file/directory and it will appear as though // it is missing its contents. + operationSample.SetProbe(Probe_Op_DenyCrawler); *kauthResult = KAUTH_RESULT_DENY; return false; } + + operationSample.SetProbe(Probe_Op_EmptyFlag); } + operationSample.TakeSplitSample(Probe_Op_IdentifySplit); + *vnodeFsidInode = Vnode_GetFsidAndInode(vnode, context); *root = VirtualizationRoot_FindForVnode(vnode, *vnodeFsidInode); + operationSample.TakeSplitSample(Probe_Op_VirtualizationRootFindSplit); + if (RootHandle_ProviderTemporaryDirectory == *root) { *kauthResult = KAUTH_RESULT_DEFER; @@ -650,6 +676,7 @@ static bool ShouldHandleVnodeOpEvent( // If the calling process is the provider, we must exit right away to avoid deadlocks if (VirtualizationRoot_PIDMatchesProvider(*root, *pid)) { + operationSample.SetProbe(Probe_Op_Provider); *kauthResult = KAUTH_RESULT_DEFER; return false; } diff --git a/ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.cpp b/ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.cpp new file mode 100644 index 0000000000..738ee5c79c --- /dev/null +++ b/ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.cpp @@ -0,0 +1,63 @@ +#include "PerformanceTracing.hpp" +#include +#include +#include + +PerfTracingProbe profile_probes[Probe_Count]; + +void PerfTracing_Init() +{ + for (size_t i = 0; i < Probe_Count; ++i) + { + PerfTracing_ProbeInit(&profile_probes[i]); + } +} + +void PerfTracing_ProbeInit(PerfTracingProbe* probe) +{ + *probe = PerfTracingProbe{ .min = UINT64_MAX }; +} + +IOReturn PerfTracing_ExportDataUserClient(IOExternalMethodArguments* arguments) +{ +#if PRJFS_PERFORMANCE_TRACING_ENABLE + if (arguments->structureOutput == nullptr || arguments->structureOutputSize != sizeof(profile_probes)) + { + return kIOReturnBadArgument; + } + + memcpy(arguments->structureOutput, profile_probes, sizeof(profile_probes)); + return kIOReturnSuccess; +#else + return kIOReturnUnsupported; +#endif +} + +void PerfTracing_RecordSample(PerfTracingProbe* probe, uint64_t startTime, uint64_t endTime) +{ + uint64_t interval = endTime - startTime; + + atomic_fetch_add(&probe->numSamples1, 1); + atomic_fetch_add(&probe->sum, interval); + + __uint128_t intervalSquared = interval; + intervalSquared *= intervalSquared; + atomic_fetch_add(&probe->sumSquares, intervalSquared); + + // Update minimum sample if necessary + { + uint64_t oldMin = atomic_load(&probe->min); + while (interval < oldMin && !atomic_compare_exchange_weak(&probe->min, &oldMin, interval)) + {} + } + + // Update maximum sample if necessary + { + uint64_t oldMax = atomic_load(&probe->max); + while (interval > oldMax && !atomic_compare_exchange_weak(&probe->max, &oldMax, interval)) + {} + } + + atomic_fetch_add(&probe->numSamples2, 1); +} + diff --git a/ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.hpp b/ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.hpp new file mode 100644 index 0000000000..664f1d5e38 --- /dev/null +++ b/ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.hpp @@ -0,0 +1,171 @@ +#pragma once + +#include "PrjFSCommon.h" + +#include +#include + +void PerfTracing_Init(); +void PerfTracing_ProbeInit(PerfTracingProbe* probe); +void PerfTracing_RecordSample(PerfTracingProbe* probe, uint64_t startTime, uint64_t endTime); + +struct IOExternalMethodArguments; +IOReturn PerfTracing_ExportDataUserClient(IOExternalMethodArguments* arguments); + +extern PerfTracingProbe profile_probes[Probe_Count]; +// A scope-based manual instrumentation profiling mechanism. +// In the simplest case, the time between construction and destruction of the ProfileSample +// is measured and registered with the probe specified during construction: +// +// void MyFunction() +// { +// ProfileSample functionSample(Probe_MyFunction); +// // ... The code for which we're measuring the runtime ... +// } // <-- functionSample goes out of scope here, so that's when timing ends +// +// +// To allow runtimes different code paths in the same scope to be recorded separately, the +// probe identity can be modified using SetProbe(): +// +// void MyFunction() +// { +// ProfileSample functionSample(Probe_MyFunction); +// // ... The code for which we're measuring the runtime ... +// if (specialCase) +// { +// // We want to be able to distinguish between the runtimes of MyFunction for this +// // special case vs "normal" runs. +// functionSample.SetProbe(Probe_MyFunctionSpecialCase); +// // ... do something potentially expensive here ... +// } +// // ... more code ... +// } // <-- Runtime to here will be recorded either under Probe_MyFunction or Probe_MyFunctionSpecialCase +// +// +// For tracing sub-sections of code, such as the special case logic above, in isolation, +// we have 2 options: taking additional scoped samples, or split timings. Scoped samples are +// easier to understand: +// +// void MyFunction() +// { +// ProfileSample functionSample(Probe_MyFunction); +// // ... +// if (specialCase) +// { +// // Measure only the special case code on its own: +// ProfileSample specialCaseSample(Probe_MyFunctionSpecialCase); +// // ... do something potentially expensive here ... +// } // <-- scope of specialCaseSample ends here +// // ... more code ... +// } // <-- end of Probe_MyFunction in all cases +// +// In the above example, the runtimes of all MyFunction() calls are recorded under Probe_MyFunction, +// while the special case code on its own is recorded in Probe_MyFunctionSpecialCase. +// +// Taking split timings meanwhile allows us to carve up scoped samples into constituent sub-samples, +// useful for drilling down to find the source of performance issues: +// +// void MyFunction() +// { +// ProfileSample functionSample(Probe_MyFunction); +// // ... +// // The time from the creation of functionSample to this point is recorded as Probe_MyFunctionPart1. +// functionSample.TakeSplitSample(Probe_MyFunctionPart1, Probe_MyFunctionRemainder); +// if (specialCase) +// { +// // ... do something potentially expensive here ... +// functionSample.TakeSplitSample(Probe_MyFunctionSpecialCase); // This measures time since the Part1 split +// } // <-- scope of specialCaseSample ends here +// // ... more code ... +// } // <-- end of Probe_MyFunction in all cases; the time since the last split (Probe_MyFunctionPart1 +// // or Probe_MyFunctionSpecialCase depending on code path) is recorded as Probe_MyFunctionRemainder. +// +// The end time stamp for a split is taken as the start of the next split, and the overall start and end +// stamps of the scoped sample are alse the start and end of the first and last (remainder) split, +// respectively. +// So in this case, the sum total runtime of all samples of Probe_MyFunction is exactly equal to the sum of +// Probe_MyFunctionPart1 + Probe_MyFunctionSpecialCase + Probe_MyFunctionRemainder. +// Note that Probe_MyFunctionSpecialCase may have a lower sample count. +// Note also that the "remainder" split is optional - if only the 1-argument version of TakeSplitSample +// is used, the split time to the end of scope is not recorded. (And like the scoped sample, it can be changed, +// in this case using SetFinalSplitProbe()) +class ProfileSample +{ + ProfileSample(const ProfileSample&) = delete; + ProfileSample() = delete; + +#if PRJFS_PERFORMANCE_TRACING_ENABLE + const uint64_t startTimestamp; + PrjFS_PerfCounter wholeSampleProbe; + PrjFS_PerfCounter finalSplitProbe; + uint64_t splitTimestamp; +#endif + +public: + inline ProfileSample(PrjFS_PerfCounter defaultProbe); + inline void SetProbe(PrjFS_PerfCounter probe); + inline void TakeSplitSample(PrjFS_PerfCounter splitProbe); + inline void TakeSplitSample(PrjFS_PerfCounter splitProbe, PrjFS_PerfCounter newFinalSplitProbe); + inline void SetFinalSplitProbe(PrjFS_PerfCounter newFinalSplitProbe); + inline ~ProfileSample(); +}; + +ProfileSample::~ProfileSample() +{ +#if PRJFS_PERFORMANCE_TRACING_ENABLE + uint64_t endTimestamp = mach_absolute_time(); + if (this->wholeSampleProbe != Probe_None) + { + PerfTracing_RecordSample(&profile_probes[this->wholeSampleProbe], this->startTimestamp, endTimestamp); + } + + if (this->finalSplitProbe != Probe_None) + { + PerfTracing_RecordSample(&profile_probes[this->finalSplitProbe], this->splitTimestamp, endTimestamp); + } +#endif +}; + +void ProfileSample::TakeSplitSample(PrjFS_PerfCounter splitProbe) +{ +#if PRJFS_PERFORMANCE_TRACING_ENABLE + uint64_t newSplitTimestamp = mach_absolute_time(); + PerfTracing_RecordSample(&profile_probes[splitProbe], this->splitTimestamp, newSplitTimestamp); + this->splitTimestamp = newSplitTimestamp; +#endif +} + +void ProfileSample::TakeSplitSample(PrjFS_PerfCounter splitProbe, PrjFS_PerfCounter newFinalSplitProbe) +{ +#if PRJFS_PERFORMANCE_TRACING_ENABLE + this->TakeSplitSample(splitProbe); + this->finalSplitProbe = newFinalSplitProbe; +#endif +} + +void ProfileSample::SetFinalSplitProbe(PrjFS_PerfCounter newFinalSplitProbe) +{ +#if PRJFS_PERFORMANCE_TRACING_ENABLE + this->finalSplitProbe = newFinalSplitProbe; +#endif +} + + +ProfileSample::ProfileSample(PrjFS_PerfCounter defaultProbe) +#if PRJFS_PERFORMANCE_TRACING_ENABLE + : + startTimestamp(mach_absolute_time()), + wholeSampleProbe(defaultProbe), + finalSplitProbe(Probe_None), + splitTimestamp(this->startTimestamp) +#endif +{ +} + +void ProfileSample::SetProbe(PrjFS_PerfCounter probe) +{ +#if PRJFS_PERFORMANCE_TRACING_ENABLE + this->wholeSampleProbe = probe; +#endif +} + diff --git a/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSKext.cpp b/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSKext.cpp index 508545bcd6..97a8ee6e54 100644 --- a/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSKext.cpp +++ b/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSKext.cpp @@ -5,12 +5,15 @@ #include "KauthHandler.hpp" #include "Locks.hpp" #include "Memory.hpp" +#include "PerformanceTracing.hpp" extern "C" kern_return_t PrjFSKext_Start(kmod_info_t* ki, void* d); extern "C" kern_return_t PrjFSKext_Stop(kmod_info_t* ki, void* d); kern_return_t PrjFSKext_Start(kmod_info_t* ki, void* d) { + PerfTracing_Init(); + if (Locks_Init()) { goto CleanupAndFail; diff --git a/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSLogUserClient.cpp b/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSLogUserClient.cpp index b39b73bf9f..69e59889d0 100644 --- a/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSLogUserClient.cpp +++ b/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSLogUserClient.cpp @@ -2,6 +2,7 @@ #include "PrjFSLogClientShared.h" #include "KextLog.hpp" #include "PrjFSCommon.h" +#include "PerformanceTracing.hpp" #include @@ -9,6 +10,20 @@ OSDefineMetaClassAndStructors(PrjFSLogUserClient, IOUserClient); // Amount of memory to set aside for kernel -> userspace log messages. static const uint32_t LogMessageQueueCapacityBytes = 1024 * 1024; + +static const IOExternalMethodDispatch LogUserClientDispatch[] = +{ + [LogSelector_FetchProfilingData] = + { + .function = &PrjFSLogUserClient::fetchProfilingData, + .checkScalarInputCount = 0, + .checkStructureInputSize = 0, + .checkScalarOutputCount = 0, + .checkStructureOutputSize = Probe_Count * sizeof(PerfTracingProbe), // array of probes + }, +}; + + bool PrjFSLogUserClient::initWithTask( task_t owningTask, void* securityToken, @@ -129,3 +144,31 @@ void PrjFSLogUserClient::sendLogMessage(KextLog_MessageHeader* message, uint32_t Mutex_Release(this->dataQueueWriterMutex); } +IOReturn PrjFSLogUserClient::externalMethod( + uint32_t selector, + IOExternalMethodArguments* arguments, + IOExternalMethodDispatch* dispatch, + OSObject* target, + void* reference) +{ + IOExternalMethodDispatch local_dispatch = {}; + if (selector < sizeof(LogUserClientDispatch) / sizeof(LogUserClientDispatch[0])) + { + if (nullptr != LogUserClientDispatch[selector].function) + { + local_dispatch = LogUserClientDispatch[selector]; + dispatch = &local_dispatch; + target = this; + } + } + return this->super::externalMethod(selector, arguments, dispatch, target, reference); +} + +IOReturn PrjFSLogUserClient::fetchProfilingData( + OSObject* target, + void* reference, + IOExternalMethodArguments* arguments) +{ + return PerfTracing_ExportDataUserClient(arguments); +} + diff --git a/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSLogUserClient.hpp b/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSLogUserClient.hpp index a91d456a8c..28c3bb66ef 100644 --- a/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSLogUserClient.hpp +++ b/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSLogUserClient.hpp @@ -26,5 +26,18 @@ class PrjFSLogUserClient : public IOUserClient virtual IOReturn clientMemoryForType(UInt32 type, IOOptionBits* options, IOMemoryDescriptor** memory) override; virtual IOReturn registerNotificationPort(mach_port_t port, UInt32 type, io_user_reference_t refCon) override; + virtual IOReturn externalMethod( + uint32_t selector, + IOExternalMethodArguments* arguments, + IOExternalMethodDispatch* dispatch = nullptr, + OSObject* target = nullptr, + void* reference = nullptr) override; + + + static IOReturn fetchProfilingData( + OSObject* target, + void* reference, + IOExternalMethodArguments* arguments); + void sendLogMessage(KextLog_MessageHeader* message, uint32_t size); }; diff --git a/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSProviderUserClient.hpp b/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSProviderUserClient.hpp index de487108c1..650b5dc0fc 100644 --- a/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSProviderUserClient.hpp +++ b/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSProviderUserClient.hpp @@ -30,9 +30,9 @@ class PrjFSProviderUserClient : public IOUserClient virtual IOReturn externalMethod( uint32_t selector, IOExternalMethodArguments* arguments, - IOExternalMethodDispatch* dispatch = 0, - OSObject* target = 0, - void* reference = 0) override; + IOExternalMethodDispatch* dispatch = nullptr, + OSObject* target = nullptr, + void* reference = nullptr) override; virtual IOReturn clientMemoryForType( UInt32 type, IOOptionBits* options, diff --git a/ProjFS.Mac/PrjFSKext/PrjFSKext/VirtualizationRoots.cpp b/ProjFS.Mac/PrjFSKext/PrjFSKext/VirtualizationRoots.cpp index 88b0a97dba..4949e357bf 100644 --- a/ProjFS.Mac/PrjFSKext/PrjFSKext/VirtualizationRoots.cpp +++ b/ProjFS.Mac/PrjFSKext/PrjFSKext/VirtualizationRoots.cpp @@ -11,6 +11,7 @@ #include "PrjFSProviderUserClient.hpp" #include "kernel-header-wrappers/mount.h" #include "VnodeUtilities.hpp" +#include "PerformanceTracing.hpp" struct VirtualizationRoot @@ -133,12 +134,16 @@ kern_return_t VirtualizationRoots_Cleanup() VirtualizationRootHandle VirtualizationRoot_FindForVnode(vnode_t vnode, const FsidInode& vnodeFsidInode) { + ProfileSample functionSample(Probe_VirtualizationRoot_Find); + VirtualizationRootHandle rootHandle = RootHandle_None; vnode_get(vnode); // Search up the tree until we hit a known virtualization root or THE root of the file system while (RootHandle_None == rootHandle && NULLVP != vnode && !vnode_isvroot(vnode)) { + ProfileSample iterationSample(Probe_VirtualizationRoot_FindIteration); + rootHandle = FindOrDetectRootAtVnode(vnode, nullptr /* vfs context */, vnodeFsidInode); // Note: if FindOrDetectRootAtVnode returns a "special" handle other // than RootHandle_None, we want to stop the search and return that. diff --git a/ProjFS.Mac/PrjFSKext/public/PrjFSCommon.h b/ProjFS.Mac/PrjFSKext/public/PrjFSCommon.h index f7478ece94..fe44364fbf 100644 --- a/ProjFS.Mac/PrjFSKext/public/PrjFSCommon.h +++ b/ProjFS.Mac/PrjFSKext/public/PrjFSCommon.h @@ -33,4 +33,47 @@ enum PrjFSServiceUserClientType UserClientType_Log, }; +enum PrjFS_PerfCounter : int32_t +{ + // Note: ensure that any changes to this list are reflected in the PerfCounterNames array of strings + + Probe_VnodeOp = 0, + Probe_FileOp, + Probe_Op_EarlyOut, + Probe_Op_NoVirtualizationRootFlag, + Probe_Op_EmptyFlag, + Probe_Op_DenyCrawler, + Probe_Op_Offline, + Probe_Op_Provider, + Probe_VnodeOp_PopulatePlaceholderDirectory, + Probe_VnodeOp_HydratePlaceholderFile, + + Probe_Op_IdentifySplit, + Probe_Op_VirtualizationRootFindSplit, + + Probe_ReadFileFlags, + + Probe_VirtualizationRoot_Find, + Probe_VirtualizationRoot_FindIteration, + + Probe_Count, + + Probe_None = -1 +}; + +struct PerfTracingProbe +{ + _Atomic uint64_t numSamples1; + _Atomic uint64_t numSamples2; + // Units: Mach absolute time (squared for sumSquares) + // Sum of measured sample intervals + _Atomic uint64_t sum; + // Smallest encountered interval + _Atomic uint64_t min; + // Largest encountered interval + _Atomic uint64_t max; + // Sum-of-squares of measured time intervals (for stddev) + _Atomic __uint128_t sumSquares; +}; + #endif /* PrjFSCommon_h */ diff --git a/ProjFS.Mac/PrjFSKext/public/PrjFSLogClientShared.h b/ProjFS.Mac/PrjFSKext/public/PrjFSLogClientShared.h index ca847b4e98..957a86a738 100644 --- a/ProjFS.Mac/PrjFSKext/public/PrjFSLogClientShared.h +++ b/ProjFS.Mac/PrjFSKext/public/PrjFSLogClientShared.h @@ -2,6 +2,14 @@ #include +// External method selectors for log user clients +enum PrjFSLogUserClientSelector +{ + LogSelector_Invalid = 0, + + LogSelector_FetchProfilingData, +}; + enum PrjFSLogUserClientMemoryType { LogMemoryType_Invalid = 0, diff --git a/ProjFS.Mac/PrjFSLib/PrjFSLib.xcodeproj/project.pbxproj b/ProjFS.Mac/PrjFSLib/PrjFSLib.xcodeproj/project.pbxproj index 9bfd51e90c..f88b6cc2b1 100644 --- a/ProjFS.Mac/PrjFSLib/PrjFSLib.xcodeproj/project.pbxproj +++ b/ProjFS.Mac/PrjFSLib/PrjFSLib.xcodeproj/project.pbxproj @@ -9,6 +9,7 @@ /* Begin PBXBuildFile section */ 4A440DDE2093AD3300AADA76 /* IOKit.framework in Frameworks */ = {isa = PBXBuildFile; fileRef = 4A440DDD2093AD3300AADA76 /* IOKit.framework */; }; 4A8A1BEE20A0D5940024BC10 /* CoreFoundation.framework in Frameworks */ = {isa = PBXBuildFile; fileRef = 4A8A1BED20A0D5940024BC10 /* CoreFoundation.framework */; }; + 4A91E086215E76A90079FE1B /* kext-perf-tracing.cpp in Sources */ = {isa = PBXBuildFile; fileRef = 4A91E084215E76A90079FE1B /* kext-perf-tracing.cpp */; }; C6C780D120816BDC00E7E054 /* PrjFSLib.h in Headers */ = {isa = PBXBuildFile; fileRef = C6C780CF20816BDC00E7E054 /* PrjFSLib.h */; }; C6C780D220816BDC00E7E054 /* PrjFSLib.cpp in Sources */ = {isa = PBXBuildFile; fileRef = C6C780D020816BDC00E7E054 /* PrjFSLib.cpp */; }; D308478120B4431200F69E92 /* prjfs-log.cpp in Sources */ = {isa = PBXBuildFile; fileRef = D308478020B4431200F69E92 /* prjfs-log.cpp */; }; @@ -34,6 +35,8 @@ /* Begin PBXFileReference section */ 4A440DDD2093AD3300AADA76 /* IOKit.framework */ = {isa = PBXFileReference; lastKnownFileType = wrapper.framework; name = IOKit.framework; path = System/Library/Frameworks/IOKit.framework; sourceTree = SDKROOT; }; 4A8A1BED20A0D5940024BC10 /* CoreFoundation.framework */ = {isa = PBXFileReference; lastKnownFileType = wrapper.framework; name = CoreFoundation.framework; path = System/Library/Frameworks/CoreFoundation.framework; sourceTree = SDKROOT; }; + 4A91E084215E76A90079FE1B /* kext-perf-tracing.cpp */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.cpp; path = "kext-perf-tracing.cpp"; sourceTree = ""; }; + 4A91E085215E76A90079FE1B /* kext-perf-tracing.hpp */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.h; path = "kext-perf-tracing.hpp"; sourceTree = ""; }; C6C780C4207FC6AB00E7E054 /* libPrjFSLib.dylib */ = {isa = PBXFileReference; explicitFileType = "compiled.mach-o.dylib"; includeInIndex = 0; path = libPrjFSLib.dylib; sourceTree = BUILT_PRODUCTS_DIR; }; C6C780CF20816BDC00E7E054 /* PrjFSLib.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = PrjFSLib.h; sourceTree = ""; }; C6C780D020816BDC00E7E054 /* PrjFSLib.cpp */ = {isa = PBXFileReference; indentWidth = 4; lastKnownFileType = sourcecode.cpp.cpp; path = PrjFSLib.cpp; sourceTree = ""; tabWidth = 4; usesTabs = 0; }; @@ -103,6 +106,8 @@ isa = PBXGroup; children = ( D308478020B4431200F69E92 /* prjfs-log.cpp */, + 4A91E085215E76A90079FE1B /* kext-perf-tracing.hpp */, + 4A91E084215E76A90079FE1B /* kext-perf-tracing.cpp */, ); path = "prjfs-log"; sourceTree = ""; @@ -207,6 +212,7 @@ buildActionMask = 2147483647; files = ( D308478920B4432500F69E92 /* PrjFSUser.cpp in Sources */, + 4A91E086215E76A90079FE1B /* kext-perf-tracing.cpp in Sources */, D308478120B4431200F69E92 /* prjfs-log.cpp in Sources */, ); runOnlyForDeploymentPostprocessing = 0; diff --git a/ProjFS.Mac/PrjFSLib/prjfs-log/kext-perf-tracing.cpp b/ProjFS.Mac/PrjFSLib/prjfs-log/kext-perf-tracing.cpp new file mode 100644 index 0000000000..45a519a196 --- /dev/null +++ b/ProjFS.Mac/PrjFSLib/prjfs-log/kext-perf-tracing.cpp @@ -0,0 +1,82 @@ +#include "kext-perf-tracing.hpp" +#include "../../PrjFSKext/public/PrjFSCommon.h" +#include "../../PrjFSKext/public/PrjFSLogClientShared.h" +#include +#include +#include +#include +#include + +static mach_timebase_info_data_t s_machTimebase; + +static uint64_t nanosecondsFromAbsoluteTime(uint64_t machAbsoluteTime) +{ + return static_cast<__uint128_t>(machAbsoluteTime) * s_machTimebase.numer / s_machTimebase.denom; +} + +static const char* const PerfCounterNames[Probe_Count] = +{ + [Probe_VnodeOp] = "VnodeOp", + [Probe_FileOp] = "FileOp", + [Probe_Op_EarlyOut] = "Op_EarlyOut", + [Probe_Op_NoVirtualizationRootFlag] = "Op_NoVirtualizationRootFlag", + [Probe_Op_EmptyFlag] = "Op_EmptyFlag", + [Probe_Op_DenyCrawler] = "Op_DenyCrawler", + [Probe_Op_Offline] = "Op_Offline", + [Probe_Op_Provider] = "Op_Provider", + [Probe_VnodeOp_PopulatePlaceholderDirectory] = "VnodeOp_PopulatePlaceholderDirectory", + [Probe_VnodeOp_HydratePlaceholderFile] = "VnodeOp_HydratePlaceholderFile", + + [Probe_Op_IdentifySplit] = "Op_IdentifySplit", + [Probe_Op_VirtualizationRootFindSplit] = "Op_VirtualizationRootFindSplit", + + [Probe_ReadFileFlags] = "Probe_ReadFileFlags", + [Probe_VirtualizationRoot_Find] = "VirtualizationRoot_Find", + [Probe_VirtualizationRoot_FindIteration] = "VirtualizationRoot_FindIteration", +}; + +bool PrjFSLog_FetchAndPrintKextProfilingData(io_connect_t connection) +{ + static dispatch_once_t onceToken; + dispatch_once(&onceToken, ^{ + mach_timebase_info(&s_machTimebase); + }); + + PerfTracingProbe probes[Probe_Count]; + size_t out_size = sizeof(probes); + IOReturn ret = IOConnectCallStructMethod(connection, LogSelector_FetchProfilingData, nullptr, 0, probes, &out_size); + if (ret == kIOReturnUnsupported) + { + return false; + } + else if (ret == kIOReturnSuccess) + { + for (unsigned i = 0; i < Probe_Count; ++i) + { + double samples = probes[i].numSamples1; + double sum_abs = probes[i].sum; + double stddev_abs = samples > 1 ? sqrt((samples * probes[i].sumSquares - sum_abs * sum_abs) / (samples * (samples - 1))) : 0.0; + + double sum_ns = nanosecondsFromAbsoluteTime(sum_abs); + double stddev_ns = nanosecondsFromAbsoluteTime(stddev_abs); + double mean_ns = samples > 0 ? sum_ns / samples : 0; + printf("%2u %40s %8llu [%8llu] samples, total time: %15.0f ns, mean: %10.2f ns +/- %11.2f", + i, PerfCounterNames[i], probes[i].numSamples1, probes[i].numSamples2, sum_ns, mean_ns, stddev_ns); + if (probes[i].min != UINT64_MAX) + { + printf(", min: %7llu ns, max: %10llu ns\n", nanosecondsFromAbsoluteTime(probes[i].min), nanosecondsFromAbsoluteTime(probes[i].max)); + } + else + { + printf("\n"); + } + } + } + else + { + fprintf(stderr, "fetching profiling data from kernel failed: 0x%x\n", ret); + return false; + } + fflush(stdout); + return true; +} diff --git a/ProjFS.Mac/PrjFSLib/prjfs-log/kext-perf-tracing.hpp b/ProjFS.Mac/PrjFSLib/prjfs-log/kext-perf-tracing.hpp new file mode 100644 index 0000000000..fedbf92dac --- /dev/null +++ b/ProjFS.Mac/PrjFSLib/prjfs-log/kext-perf-tracing.hpp @@ -0,0 +1,5 @@ +#pragma once + +#include + +bool PrjFSLog_FetchAndPrintKextProfilingData(io_connect_t connection); diff --git a/ProjFS.Mac/PrjFSLib/prjfs-log/prjfs-log.cpp b/ProjFS.Mac/PrjFSLib/prjfs-log/prjfs-log.cpp index 281fc2bd3b..aaa32b1c4e 100644 --- a/ProjFS.Mac/PrjFSLib/prjfs-log/prjfs-log.cpp +++ b/ProjFS.Mac/PrjFSLib/prjfs-log/prjfs-log.cpp @@ -1,4 +1,5 @@ #include "../PrjFSUser.hpp" +#include "kext-perf-tracing.hpp" #include "../../PrjFSKext/public/PrjFSLogClientShared.h" #include #include @@ -7,10 +8,12 @@ #include static const char* KextLogLevelAsString(KextLog_Level level); -static uint64_t nanosecondsFromAbsoluteTime(uint64_t machAbsoluteTime); +static uint64_t NanosecondsFromAbsoluteTime(uint64_t machAbsoluteTime); +static dispatch_source_t StartKextProfilingDataPolling(io_connect_t connection); static mach_timebase_info_data_t s_machTimebase; + int main(int argc, const char * argv[]) { mach_timebase_info(&s_machTimebase); @@ -55,7 +58,7 @@ int main(int argc, const char * argv[]) const char* messageType = KextLogLevelAsString(message.level); int logStringLength = messageSize - sizeof(KextLog_MessageHeader) - 1; - uint64_t timeOffsetNS = nanosecondsFromAbsoluteTime(message.machAbsoluteTimestamp - machStartTime); + uint64_t timeOffsetNS = NanosecondsFromAbsoluteTime(message.machAbsoluteTimestamp - machStartTime); uint64_t timeOffsetMS = timeOffsetNS / NSEC_PER_MSEC; printf("(%d: %5llu.%03llu) %s: %.*s\n", lineCount, timeOffsetMS / 1000u, timeOffsetMS % 1000u, messageType, logStringLength, entry->data + sizeof(KextLog_MessageHeader)); @@ -66,8 +69,21 @@ int main(int argc, const char * argv[]) } }); dispatch_resume(dataQueue.dispatchSource); + + dispatch_source_t timer = nullptr; + if (PrjFSLog_FetchAndPrintKextProfilingData(connection)) + { + timer = StartKextProfilingDataPolling(connection); + } + CFRunLoopRun(); + if (nullptr != timer) + { + dispatch_cancel(timer); + dispatch_release(timer); + } + return 0; } @@ -86,7 +102,19 @@ static const char* KextLogLevelAsString(KextLog_Level level) } } -static uint64_t nanosecondsFromAbsoluteTime(uint64_t machAbsoluteTime) +static uint64_t NanosecondsFromAbsoluteTime(uint64_t machAbsoluteTime) { return static_cast<__uint128_t>(machAbsoluteTime) * s_machTimebase.numer / s_machTimebase.denom; } + +static dispatch_source_t StartKextProfilingDataPolling(io_connect_t connection) +{ + dispatch_source_t timer = dispatch_source_create(DISPATCH_SOURCE_TYPE_TIMER, 0, 0, dispatch_get_main_queue()); + dispatch_source_set_timer(timer, DISPATCH_TIME_NOW, 15 * NSEC_PER_SEC, 10 * NSEC_PER_SEC); + dispatch_source_set_event_handler(timer, ^{ + PrjFSLog_FetchAndPrintKextProfilingData(connection); + }); + dispatch_resume(timer); + return timer; +} +