Skip to content

Commit

Permalink
Merge pull request #281 from pmj/performance-tracing
Browse files Browse the repository at this point in the history
Mac: a performance tracing mechanism for the kext
  • Loading branch information
pmj authored Oct 7, 2018
2 parents 5747bf8 + 905258a commit e1db074
Show file tree
Hide file tree
Showing 16 changed files with 603 additions and 8 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -92,7 +92,7 @@
</AdditionalOptions>
</LaunchAction>
<ProfileAction
buildConfiguration = "Release"
buildConfiguration = "Profiling(Release)"
shouldUseLaunchSchemeArgsEnv = "YES"
savedToolIdentifier = ""
useCustomWorkingDirectory = "NO"
Expand Down
98 changes: 98 additions & 0 deletions ProjFS.Mac/PrjFSKext/PrjFSKext.xcodeproj/project.pbxproj
Original file line number Diff line number Diff line change
Expand Up @@ -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 */; };
Expand All @@ -38,13 +39,15 @@
4A9D139C208F675500376182 /* PrjFSService.hpp */ = {isa = PBXFileReference; fileEncoding = 4; indentWidth = 4; lastKnownFileType = sourcecode.cpp.h; path = PrjFSService.hpp; sourceTree = "<group>"; tabWidth = 4; usesTabs = 0; };
4AA0BA9920A4500600F33D1C /* vnode.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = vnode.h; sourceTree = "<group>"; };
4ABB733020B85DA500DC0D17 /* mount.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = mount.h; sourceTree = "<group>"; };
4ABB734320B867E000DC0D17 /* PerformanceTracing.hpp */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.h; path = PerformanceTracing.hpp; sourceTree = "<group>"; };
4ABB734520BED11500DC0D17 /* PrjFSLogClientShared.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = PrjFSLogClientShared.h; sourceTree = "<group>"; };
4ABB734C20C1A65B00DC0D17 /* PrjFSProviderClientShared.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = PrjFSProviderClientShared.h; sourceTree = "<group>"; };
4AC1D7BE2091FA0400786861 /* PrjFSProviderUserClient.cpp */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.cpp.cpp; path = PrjFSProviderUserClient.cpp; sourceTree = "<group>"; };
4AC1D7BF2091FA0400786861 /* PrjFSProviderUserClient.hpp */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.cpp.h; path = PrjFSProviderUserClient.hpp; sourceTree = "<group>"; };
4AC1D7C22091FA2300786861 /* PrjFSClasses.hpp */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.h; path = PrjFSClasses.hpp; sourceTree = "<group>"; };
4AC1D7C32091FBFC00786861 /* PrjFSLogUserClient.cpp */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.cpp.cpp; path = PrjFSLogUserClient.cpp; sourceTree = "<group>"; };
4AC1D7C42091FBFC00786861 /* PrjFSLogUserClient.hpp */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.cpp.h; path = PrjFSLogUserClient.hpp; sourceTree = "<group>"; };
4AE187A721203A890026AC68 /* PerformanceTracing.cpp */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.cpp; path = PerformanceTracing.cpp; sourceTree = "<group>"; };
C6BDD364208BC60400CB7E58 /* VirtualizationRoots.hpp */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.h; path = VirtualizationRoots.hpp; sourceTree = "<group>"; };
C6BDD365208BC60400CB7E58 /* VirtualizationRoots.cpp */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.cpp; path = VirtualizationRoots.cpp; sourceTree = "<group>"; };
C6BDD368208BC99100CB7E58 /* Locks.hpp */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.h; path = Locks.hpp; sourceTree = "<group>"; };
Expand Down Expand Up @@ -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 */,
Expand Down Expand Up @@ -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 */,
Expand All @@ -269,6 +275,96 @@
/* End PBXSourcesBuildPhase section */

/* Begin XCBuildConfiguration section */
4A91E087215FA5FF0079FE1B /* Profiling(Release) */ = {
isa = XCBuildConfiguration;
buildSettings = {
ALWAYS_SEARCH_USER_PATHS = NO;
CLANG_ANALYZER_NONNULL = YES;
CLANG_ANALYZER_NUMBER_OBJECT_CONVERSION = YES_AGGRESSIVE;
CLANG_CXX_LANGUAGE_STANDARD = "gnu++14";
CLANG_CXX_LIBRARY = "libc++";
CLANG_ENABLE_MODULES = YES;
CLANG_ENABLE_OBJC_ARC = YES;
CLANG_ENABLE_OBJC_WEAK = YES;
CLANG_WARN_BLOCK_CAPTURE_AUTORELEASING = YES;
CLANG_WARN_BOOL_CONVERSION = YES;
CLANG_WARN_COMMA = YES;
CLANG_WARN_CONSTANT_CONVERSION = YES;
CLANG_WARN_DEPRECATED_OBJC_IMPLEMENTATIONS = YES;
CLANG_WARN_DIRECT_OBJC_ISA_USAGE = YES_ERROR;
CLANG_WARN_DOCUMENTATION_COMMENTS = YES;
CLANG_WARN_EMPTY_BODY = YES;
CLANG_WARN_ENUM_CONVERSION = YES;
CLANG_WARN_INFINITE_RECURSION = YES;
CLANG_WARN_INT_CONVERSION = YES;
CLANG_WARN_NON_LITERAL_NULL_CONVERSION = YES;
CLANG_WARN_OBJC_IMPLICIT_RETAIN_SELF = YES;
CLANG_WARN_OBJC_LITERAL_CONVERSION = YES;
CLANG_WARN_OBJC_ROOT_CLASS = YES_ERROR;
CLANG_WARN_RANGE_LOOP_ANALYSIS = YES;
CLANG_WARN_STRICT_PROTOTYPES = YES;
CLANG_WARN_SUSPICIOUS_MOVE = YES;
CLANG_WARN_UNGUARDED_AVAILABILITY = YES_AGGRESSIVE;
CLANG_WARN_UNREACHABLE_CODE = YES;
CLANG_WARN__DUPLICATE_METHOD_MATCH = YES;
CODE_SIGN_IDENTITY = "Mac Developer";
COPY_PHASE_STRIP = NO;
DEBUG_INFORMATION_FORMAT = "dwarf-with-dsym";
ENABLE_NS_ASSERTIONS = NO;
ENABLE_STRICT_OBJC_MSGSEND = YES;
GCC_C_LANGUAGE_STANDARD = gnu11;
GCC_NO_COMMON_BLOCKS = YES;
GCC_PREPROCESSOR_DEFINITIONS = "PRJFS_PERFORMANCE_TRACING_ENABLE=1";
GCC_TREAT_IMPLICIT_FUNCTION_DECLARATIONS_AS_ERRORS = YES;
GCC_TREAT_WARNINGS_AS_ERRORS = NO;
GCC_WARN_64_TO_32_BIT_CONVERSION = YES;
GCC_WARN_ABOUT_MISSING_PROTOTYPES = YES;
GCC_WARN_ABOUT_RETURN_TYPE = YES_ERROR;
GCC_WARN_UNDECLARED_SELECTOR = YES;
GCC_WARN_UNINITIALIZED_AUTOS = YES_AGGRESSIVE;
GCC_WARN_UNUSED_FUNCTION = YES;
GCC_WARN_UNUSED_VARIABLE = YES;
MACOSX_DEPLOYMENT_TARGET = 10.13;
MODULE_START = PrjFSKext_Start;
MODULE_STOP = PrjFSKext_Stop;
MTL_ENABLE_DEBUG_INFO = NO;
SDKROOT = macosx;
SYMROOT = "$(SRCROOT)/../../../BuildOutput/ProjFS.Mac/Native";
WARNING_CFLAGS = (
"-Werror=undefined-internal",
"-Werror=missing-prototypes",
);
};
name = "Profiling(Release)";
};
4A91E088215FA5FF0079FE1B /* Profiling(Release) */ = {
isa = XCBuildConfiguration;
buildSettings = {
CODE_SIGN_IDENTITY = "";
CODE_SIGN_STYLE = Automatic;
DEVELOPMENT_TEAM = "";
GCC_PREPROCESSOR_DEFINITIONS = (
"MACH_ASSERT=1",
"$(inherited)",
);
GCC_WARN_SHADOW = YES;
INFOPLIST_FILE = PrjFSKext/Info.plist;
MODULE_NAME = io.gvfs.PrjFSKext;
MODULE_START = PrjFSKext_Start;
MODULE_STOP = PrjFSKext_Stop;
MODULE_VERSION = 1.0.0d1;
PRODUCT_BUNDLE_IDENTIFIER = io.gvfs.PrjFSKext;
PRODUCT_NAME = "$(TARGET_NAME)";
WARNING_CFLAGS = (
"-Werror",
"-Werror=undefined-internal",
"-Werror=missing-prototypes",
"-Werror=format",
);
WRAPPER_EXTENSION = kext;
};
name = "Profiling(Release)";
};
C6C780B6207FC67200E7E054 /* Debug */ = {
isa = XCBuildConfiguration;
buildSettings = {
Expand Down Expand Up @@ -461,6 +557,7 @@
buildConfigurations = (
C6C780B6207FC67200E7E054 /* Debug */,
C6C780B7207FC67200E7E054 /* Release */,
4A91E087215FA5FF0079FE1B /* Profiling(Release) */,
);
defaultConfigurationIsVisible = 0;
defaultConfigurationName = Release;
Expand All @@ -470,6 +567,7 @@
buildConfigurations = (
C6C780B9207FC67200E7E054 /* Debug */,
C6C780BA207FC67200E7E054 /* Release */,
4A91E088215FA5FF0079FE1B /* Profiling(Release) */,
);
defaultConfigurationIsVisible = 0;
defaultConfigurationName = Release;
Expand Down
29 changes: 28 additions & 1 deletion ProjFS.Mac/PrjFSKext/PrjFSKext/KauthHandler.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,7 @@
#include "Message.h"
#include "Locks.hpp"
#include "PrjFSProviderUserClient.hpp"
#include "PerformanceTracing.hpp"

// Function prototypes
static int HandleVnodeOperation(
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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<vfs_context_t>(arg0);
vnode_t currentVnode = reinterpret_cast<vnode_t>(arg1);
Expand Down Expand Up @@ -296,6 +300,7 @@ static int HandleVnodeOperation(
context,
currentVnode,
action,
functionSample,
&root,
&vnodeType,
&currentVnodeFileFlags,
Expand Down Expand Up @@ -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 ?
Expand Down Expand Up @@ -376,6 +383,8 @@ static int HandleVnodeOperation(
{
if (FileFlagsBitIsSet(currentVnodeFileFlags, FileFlags_IsEmpty))
{
functionSample.SetProbe(Probe_VnodeOp_HydratePlaceholderFile);

if (!TrySendRequestAndWaitForResponse(
root,
MessageType_KtoU_HydrateFile,
Expand Down Expand Up @@ -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;

Expand Down Expand Up @@ -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,
Expand All @@ -582,23 +594,30 @@ static bool ShouldHandleVnodeOpEvent(

if (!VirtualizationRoot_VnodeIsOnAllowedFilesystem(vnode))
{
operationSample.SetProbe(Probe_Op_EarlyOut);
*kauthResult = KAUTH_RESULT_DEFER;
return false;
}

*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;
}
Expand All @@ -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;
Expand All @@ -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;
}
Expand Down
63 changes: 63 additions & 0 deletions ProjFS.Mac/PrjFSKext/PrjFSKext/PerformanceTracing.cpp
Original file line number Diff line number Diff line change
@@ -0,0 +1,63 @@
#include "PerformanceTracing.hpp"
#include <sys/types.h>
#include <stdatomic.h>
#include <IOKit/IOUserClient.h>

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);
}

Loading

0 comments on commit e1db074

Please sign in to comment.