From c2910a10f4306e1985aa31b628899df21e76a0c4 Mon Sep 17 00:00:00 2001 From: Phil Dennis-Jordan Date: Wed, 20 Jun 2018 12:22:09 +0200 Subject: [PATCH 1/5] Mac kext: Scoped timing wrapper and user client for extracting profile data This adds a scoped time measurement class with splits. Probes are defined in an enum. When a ProfileSample instance is created, the Mach absolute time is taken, and when it is destroyed, another time stamp is taken, and the interval recorded with the sample aggregation probe ID specified during construction. Additionally, split time samples can be taken. The number of samples, total runtime, sum of squares, minimum, and maximum values are recorded. From these, mean and standard deviation can be derived. An external method for extracting the profiling data from the kernel has been added to the logging user client class. The simple log tool has been extended to fetch and dump this data to stdout every 15 seconds. --- .../PrjFSKext.xcodeproj/project.pbxproj | 6 + .../PrjFSKext/PerformanceTracing.cpp | 59 +++++++ .../PrjFSKext/PerformanceTracing.hpp | 155 ++++++++++++++++++ ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSKext.cpp | 3 + .../PrjFSKext/PrjFSLogUserClient.cpp | 43 +++++ .../PrjFSKext/PrjFSLogUserClient.hpp | 13 ++ ProjFS.Mac/PrjFSKext/public/PrjFSCommon.h | 25 +++ .../PrjFSKext/public/PrjFSLogClientShared.h | 8 + .../PrjFSLib.xcodeproj/project.pbxproj | 6 + .../PrjFSLib/prjfs-log/kext-perf-tracing.cpp | 65 ++++++++ .../PrjFSLib/prjfs-log/kext-perf-tracing.hpp | 5 + ProjFS.Mac/PrjFSLib/prjfs-log/prjfs-log.cpp | 34 +++- 12 files changed, 419 insertions(+), 3 deletions(-) create mode 100644 ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.cpp create mode 100644 ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.hpp create mode 100644 ProjFS.Mac/PrjFSLib/prjfs-log/kext-perf-tracing.cpp create mode 100644 ProjFS.Mac/PrjFSLib/prjfs-log/kext-perf-tracing.hpp diff --git a/ProjFS.Mac/PrjFSKext/PrjFSKext.xcodeproj/project.pbxproj b/ProjFS.Mac/PrjFSKext/PrjFSKext.xcodeproj/project.pbxproj index dbd7e2453..44b29d877 100644 --- a/ProjFS.Mac/PrjFSKext/PrjFSKext.xcodeproj/project.pbxproj +++ b/ProjFS.Mac/PrjFSKext/PrjFSKext.xcodeproj/project.pbxproj @@ -15,6 +15,7 @@ 4AC1D7C12091FA0400786861 /* PrjFSProviderUserClient.hpp in Headers */ = {isa = PBXBuildFile; fileRef = 4AC1D7BF2091FA0400786861 /* PrjFSProviderUserClient.hpp */; }; 4AC1D7C52091FBFC00786861 /* PrjFSLogUserClient.cpp in Sources */ = {isa = PBXBuildFile; fileRef = 4AC1D7C32091FBFC00786861 /* PrjFSLogUserClient.cpp */; }; 4AC1D7C62091FBFC00786861 /* PrjFSLogUserClient.hpp in Headers */ = {isa = PBXBuildFile; fileRef = 4AC1D7C42091FBFC00786861 /* PrjFSLogUserClient.hpp */; }; + 4AE187A821203A890026AC68 /* PerformanceTracing.cpp in Sources */ = {isa = PBXBuildFile; fileRef = 4AE187A721203A890026AC68 /* PerformanceTracing.cpp */; }; C6BDD366208BC60400CB7E58 /* VirtualizationRoots.hpp in Headers */ = {isa = PBXBuildFile; fileRef = C6BDD364208BC60400CB7E58 /* VirtualizationRoots.hpp */; }; C6BDD367208BC60400CB7E58 /* VirtualizationRoots.cpp in Sources */ = {isa = PBXBuildFile; fileRef = C6BDD365208BC60400CB7E58 /* VirtualizationRoots.cpp */; }; C6BDD36A208BC99100CB7E58 /* Locks.hpp in Headers */ = {isa = PBXBuildFile; fileRef = C6BDD368208BC99100CB7E58 /* Locks.hpp */; }; @@ -38,6 +39,7 @@ 4A9D139C208F675500376182 /* PrjFSService.hpp */ = {isa = PBXFileReference; fileEncoding = 4; indentWidth = 4; lastKnownFileType = sourcecode.cpp.h; path = PrjFSService.hpp; sourceTree = ""; tabWidth = 4; usesTabs = 0; }; 4AA0BA9920A4500600F33D1C /* vnode.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = vnode.h; sourceTree = ""; }; 4ABB733020B85DA500DC0D17 /* mount.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = mount.h; sourceTree = ""; }; + 4ABB734320B867E000DC0D17 /* PerformanceTracing.hpp */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.h; path = PerformanceTracing.hpp; sourceTree = ""; }; 4ABB734520BED11500DC0D17 /* PrjFSLogClientShared.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = PrjFSLogClientShared.h; sourceTree = ""; }; 4ABB734C20C1A65B00DC0D17 /* PrjFSProviderClientShared.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = PrjFSProviderClientShared.h; sourceTree = ""; }; 4AC1D7BE2091FA0400786861 /* PrjFSProviderUserClient.cpp */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.cpp.cpp; path = PrjFSProviderUserClient.cpp; sourceTree = ""; }; @@ -45,6 +47,7 @@ 4AC1D7C22091FA2300786861 /* PrjFSClasses.hpp */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.h; path = PrjFSClasses.hpp; sourceTree = ""; }; 4AC1D7C32091FBFC00786861 /* PrjFSLogUserClient.cpp */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.cpp.cpp; path = PrjFSLogUserClient.cpp; sourceTree = ""; }; 4AC1D7C42091FBFC00786861 /* PrjFSLogUserClient.hpp */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.cpp.h; path = PrjFSLogUserClient.hpp; sourceTree = ""; }; + 4AE187A721203A890026AC68 /* PerformanceTracing.cpp */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.cpp; path = PerformanceTracing.cpp; sourceTree = ""; }; C6BDD364208BC60400CB7E58 /* VirtualizationRoots.hpp */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.h; path = VirtualizationRoots.hpp; sourceTree = ""; }; C6BDD365208BC60400CB7E58 /* VirtualizationRoots.cpp */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.cpp; path = VirtualizationRoots.cpp; sourceTree = ""; }; C6BDD368208BC99100CB7E58 /* Locks.hpp */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.h; path = Locks.hpp; sourceTree = ""; }; @@ -124,6 +127,8 @@ C6C780CB207FD02400E7E054 /* KextLog.hpp */, C6C780CC207FD02400E7E054 /* KextLog.cpp */, C6C780B5207FC67200E7E054 /* Info.plist */, + 4ABB734320B867E000DC0D17 /* PerformanceTracing.hpp */, + 4AE187A721203A890026AC68 /* PerformanceTracing.cpp */, C6E9E116208BBB62004A5725 /* KauthHandler.hpp */, C6E9E117208BBB62004A5725 /* KauthHandler.cpp */, C6BDD364208BC60400CB7E58 /* VirtualizationRoots.hpp */, @@ -253,6 +258,7 @@ buildActionMask = 2147483647; files = ( C6BDD36B208BC99100CB7E58 /* Locks.cpp in Sources */, + 4AE187A821203A890026AC68 /* PerformanceTracing.cpp in Sources */, C6BDD367208BC60400CB7E58 /* VirtualizationRoots.cpp in Sources */, C6BDD374208C033200CB7E58 /* Memory.cpp in Sources */, 4AC1D7C52091FBFC00786861 /* PrjFSLogUserClient.cpp in Sources */, diff --git a/ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.cpp b/ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.cpp new file mode 100644 index 000000000..644cb574c --- /dev/null +++ b/ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.cpp @@ -0,0 +1,59 @@ +#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 (arguments->structureOutput == nullptr || arguments->structureOutputSize != sizeof(profile_probes)) + { + return kIOReturnBadArgument; + } + + memcpy(arguments->structureOutput, profile_probes, sizeof(profile_probes)); + return kIOReturnSuccess; +} + +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 000000000..4f0099814 --- /dev/null +++ b/ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.hpp @@ -0,0 +1,155 @@ +#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; + + const uint64_t startTimestamp; + PrjFS_PerfCounter wholeSampleProbe; + PrjFS_PerfCounter finalSplitProbe; + uint64_t splitTimestamp; + +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() +{ + 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); + } +}; + +void ProfileSample::TakeSplitSample(PrjFS_PerfCounter splitProbe) +{ + uint64_t newSplitTimestamp = mach_absolute_time(); + PerfTracing_RecordSample(&profile_probes[splitProbe], this->splitTimestamp, newSplitTimestamp); + this->splitTimestamp = newSplitTimestamp; +} + +void ProfileSample::TakeSplitSample(PrjFS_PerfCounter splitProbe, PrjFS_PerfCounter newFinalSplitProbe) +{ + this->TakeSplitSample(splitProbe); + this->finalSplitProbe = newFinalSplitProbe; +} + +void ProfileSample::SetFinalSplitProbe(PrjFS_PerfCounter newFinalSplitProbe) +{ + this->finalSplitProbe = newFinalSplitProbe; +} + +ProfileSample::ProfileSample(PrjFS_PerfCounter defaultProbe) : + startTimestamp(mach_absolute_time()), + wholeSampleProbe(defaultProbe), + finalSplitProbe(Probe_None), + splitTimestamp(this->startTimestamp) +{ +} + +void ProfileSample::SetProbe(PrjFS_PerfCounter probe) +{ + this->wholeSampleProbe = probe; +} + diff --git a/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSKext.cpp b/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSKext.cpp index 508545bcd..97a8ee6e5 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 b39b73bf9..69e59889d 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 a91d456a8..28c3bb66e 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/public/PrjFSCommon.h b/ProjFS.Mac/PrjFSKext/public/PrjFSCommon.h index f7478ece9..35b386b44 100644 --- a/ProjFS.Mac/PrjFSKext/public/PrjFSCommon.h +++ b/ProjFS.Mac/PrjFSKext/public/PrjFSCommon.h @@ -33,4 +33,29 @@ 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_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 ca847b4e9..957a86a73 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 9bfd51e90..f88b6cc2b 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 000000000..30d46eda4 --- /dev/null +++ b/ProjFS.Mac/PrjFSLib/prjfs-log/kext-perf-tracing.cpp @@ -0,0 +1,65 @@ +#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] = +{ +}; + +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 000000000..fedbf92da --- /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 281fc2bd3..aaa32b1c4 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; +} + From 3c86170f8f4fab252af852d12aa5538964a5ec2f Mon Sep 17 00:00:00 2001 From: Phil Dennis-Jordan Date: Fri, 5 Oct 2018 12:11:54 +0200 Subject: [PATCH 2/5] Mac kext: Incorporates code review style feedback In the review, it was pointed out we should be using nullptr instead of 0 for default function argument values which were copied from the declaration of the function being overridden in the log user client. The same is true for the provider user client, so this fixes it there too. --- ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSProviderUserClient.hpp | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSProviderUserClient.hpp b/ProjFS.Mac/PrjFSKext/PrjFSKext/PrjFSProviderUserClient.hpp index de487108c..650b5dc0f 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, From 5f7cc9721b8fff584c8da2991ddf6301bc86aa40 Mon Sep 17 00:00:00 2001 From: Phil Dennis-Jordan Date: Sat, 29 Sep 2018 11:41:51 +0200 Subject: [PATCH 3/5] Mac kext: Placement of profiling probes throughout the vnode listener Using the previously created profiling mechanism, this adds various measurement points to the vnode scope listener handler, and the relevant strings to the user space extraction tool. --- .../PrjFSKext/PrjFSKext/KauthHandler.cpp | 29 ++++++++++++++++++- .../PrjFSKext/VirtualizationRoots.cpp | 5 ++++ ProjFS.Mac/PrjFSKext/public/PrjFSCommon.h | 18 ++++++++++++ .../PrjFSLib/prjfs-log/kext-perf-tracing.cpp | 17 +++++++++++ 4 files changed, 68 insertions(+), 1 deletion(-) diff --git a/ProjFS.Mac/PrjFSKext/PrjFSKext/KauthHandler.cpp b/ProjFS.Mac/PrjFSKext/PrjFSKext/KauthHandler.cpp index 111c9355d..50250b631 100644 --- a/ProjFS.Mac/PrjFSKext/PrjFSKext/KauthHandler.cpp +++ b/ProjFS.Mac/PrjFSKext/PrjFSKext/KauthHandler.cpp @@ -13,6 +13,7 @@ #include "Message.h" #include "Locks.hpp" #include "PrjFSProviderUserClient.hpp" +#include "PerformanceTracing.hpp" // Function prototypes static int HandleVnodeOperation( @@ -61,6 +62,7 @@ static bool ShouldHandleVnodeOpEvent( vfs_context_t context, const vnode_t vnode, kauth_action_t action, + ProfileSample& operationSample, // Out params: VirtualizationRootHandle* root, @@ -252,6 +254,8 @@ static int HandleVnodeOperation( uintptr_t arg3) { atomic_fetch_add(&s_numActiveKauthEvents, 1); + + ProfileSample functionSample(Probe_VnodeOp); vfs_context_t context = reinterpret_cast(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/VirtualizationRoots.cpp b/ProjFS.Mac/PrjFSKext/PrjFSKext/VirtualizationRoots.cpp index 88b0a97db..4949e357b 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 35b386b44..fe44364fb 100644 --- a/ProjFS.Mac/PrjFSKext/public/PrjFSCommon.h +++ b/ProjFS.Mac/PrjFSKext/public/PrjFSCommon.h @@ -37,6 +37,24 @@ 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, diff --git a/ProjFS.Mac/PrjFSLib/prjfs-log/kext-perf-tracing.cpp b/ProjFS.Mac/PrjFSLib/prjfs-log/kext-perf-tracing.cpp index 30d46eda4..45a519a19 100644 --- a/ProjFS.Mac/PrjFSLib/prjfs-log/kext-perf-tracing.cpp +++ b/ProjFS.Mac/PrjFSLib/prjfs-log/kext-perf-tracing.cpp @@ -16,6 +16,23 @@ static uint64_t nanosecondsFromAbsoluteTime(uint64_t machAbsoluteTime) 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) From b26859971b42772abfbe5a784d861ef8e0d3f121 Mon Sep 17 00:00:00 2001 From: Phil Dennis-Jordan Date: Fri, 28 Sep 2018 19:16:57 +0200 Subject: [PATCH 4/5] Mac kext: Conditionally enable performance tracing. --- .../PrjFSKext/PrjFSKext/PerformanceTracing.cpp | 4 ++++ .../PrjFSKext/PrjFSKext/PerformanceTracing.hpp | 18 +++++++++++++++++- 2 files changed, 21 insertions(+), 1 deletion(-) diff --git a/ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.cpp b/ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.cpp index 644cb574c..738ee5c79 100644 --- a/ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.cpp +++ b/ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.cpp @@ -20,6 +20,7 @@ void PerfTracing_ProbeInit(PerfTracingProbe* probe) IOReturn PerfTracing_ExportDataUserClient(IOExternalMethodArguments* arguments) { +#if PRJFS_PERFORMANCE_TRACING_ENABLE if (arguments->structureOutput == nullptr || arguments->structureOutputSize != sizeof(profile_probes)) { return kIOReturnBadArgument; @@ -27,6 +28,9 @@ IOReturn PerfTracing_ExportDataUserClient(IOExternalMethodArguments* arguments) 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) diff --git a/ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.hpp b/ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.hpp index 4f0099814..664f1d5e3 100644 --- a/ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.hpp +++ b/ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.hpp @@ -94,10 +94,12 @@ 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); @@ -110,6 +112,7 @@ class ProfileSample ProfileSample::~ProfileSample() { +#if PRJFS_PERFORMANCE_TRACING_ENABLE uint64_t endTimestamp = mach_absolute_time(); if (this->wholeSampleProbe != Probe_None) { @@ -120,36 +123,49 @@ ProfileSample::~ProfileSample() { 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) : + +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 } From 905258ae720f8069071b3dfa44b9498dcbb8aa3c Mon Sep 17 00:00:00 2001 From: Phil Dennis-Jordan Date: Sat, 29 Sep 2018 14:24:42 +0200 Subject: [PATCH 5/5] Mac kext: New Profiling(Release) build configuration based on Release --- .../xcshareddata/xcschemes/PrjFS.xcscheme | 2 +- .../PrjFSKext.xcodeproj/project.pbxproj | 92 +++++++++++++++++++ 2 files changed, 93 insertions(+), 1 deletion(-) diff --git a/ProjFS.Mac/PrjFS.xcworkspace/xcshareddata/xcschemes/PrjFS.xcscheme b/ProjFS.Mac/PrjFS.xcworkspace/xcshareddata/xcschemes/PrjFS.xcscheme index 558130ad6..389d98c9a 100644 --- a/ProjFS.Mac/PrjFS.xcworkspace/xcshareddata/xcschemes/PrjFS.xcscheme +++ b/ProjFS.Mac/PrjFS.xcworkspace/xcshareddata/xcschemes/PrjFS.xcscheme @@ -92,7 +92,7 @@