From 3fc97a184fae738d94a51a7b24f2b59766d2e247 Mon Sep 17 00:00:00 2001 From: Andy Ayers Date: Wed, 3 Aug 2016 15:37:32 -0700 Subject: [PATCH] Inliner: gather summary stats and dump to Jit CSV log Collect per-method summary stats about inlining: number of calls, number of candidates, etc. Commit migrated from https://github.com/dotnet/coreclr/commit/da5693edb3223adb36aa4088ba7113d7cd065c22 --- src/coreclr/src/jit/compiler.cpp | 12 +++++ src/coreclr/src/jit/flowgraph.cpp | 1 + src/coreclr/src/jit/importer.cpp | 5 +- src/coreclr/src/jit/inline.cpp | 97 +++++++++++++++++++++++++++++++++++---- src/coreclr/src/jit/inline.h | 43 +++++++++++++++-- src/coreclr/src/jit/morph.cpp | 2 + 6 files changed, 147 insertions(+), 13 deletions(-) diff --git a/src/coreclr/src/jit/compiler.cpp b/src/coreclr/src/jit/compiler.cpp index 1f8a319..ad5cdb8 100644 --- a/src/coreclr/src/jit/compiler.cpp +++ b/src/coreclr/src/jit/compiler.cpp @@ -3984,6 +3984,12 @@ void Compiler::compCompile(void * * methodCodePtr, ULONG * methodCodeSize, CORJIT_FLAGS * compileFlags) { + if (compIsForInlining()) + { + // Notify root instance that an inline attempt is about to import IL + impInlineRoot()->m_inlineStrategy->NoteImport(); + } + hashBv::Init(this); VarSetOps::AssignAllowUninitRhs(this, compCurLife, VarSetOps::UninitVal()); @@ -7092,6 +7098,9 @@ void JitTimer::PrintCsvHeader() { fprintf(fp, "\"%s\",", PhaseNames[i]); } + + InlineStrategy::DumpCsvHeader(fp); + fprintf(fp, "\"Total Cycles\","); fprintf(fp, "\"CPS\"\n"); fclose(fp); @@ -7136,6 +7145,9 @@ void JitTimer::PrintCsvMethodStats(Compiler* comp) totCycles += m_info.m_cyclesByPhase[i]; fprintf(fp, "%I64u,", m_info.m_cyclesByPhase[i]); } + + comp->m_inlineStrategy->DumpCsvData(fp); + fprintf(fp, "%I64u,", m_info.m_totalCycles); fprintf(fp, "%f\n", CycleTimer::CyclesPerSecond()); fclose(fp); diff --git a/src/coreclr/src/jit/flowgraph.cpp b/src/coreclr/src/jit/flowgraph.cpp index baf3575..b6f9ce4 100644 --- a/src/coreclr/src/jit/flowgraph.cpp +++ b/src/coreclr/src/jit/flowgraph.cpp @@ -4872,6 +4872,7 @@ TOO_FAR: if (compInlineResult->IsFailure()) { + impInlineRoot()->m_inlineStrategy->NoteUnprofitable(); JITDUMP("\n\nInline expansion aborted, inline not profitable\n"); return; } diff --git a/src/coreclr/src/jit/importer.cpp b/src/coreclr/src/jit/importer.cpp index d2a92ee..eed46f5 100644 --- a/src/coreclr/src/jit/importer.cpp +++ b/src/coreclr/src/jit/importer.cpp @@ -16970,7 +16970,10 @@ void Compiler::impMarkInlineCandidate(GenTreePtr callNode, CORINFO_CONTEXT_HANDLE exactContextHnd, CORINFO_CALL_INFO* callInfo) { - if (!opts.OptEnabled(CLFLG_INLINING)) + // Let the strategy know there's another call + impInlineRoot()->m_inlineStrategy->NoteCall(); + + if (!opts.OptEnabled(CLFLG_INLINING)) { /* XXX Mon 8/18/2008 * This assert is misleading. The caller does not ensure that we have CLFLG_INLINING set before diff --git a/src/coreclr/src/jit/inline.cpp b/src/coreclr/src/jit/inline.cpp index cca6757..f813427 100644 --- a/src/coreclr/src/jit/inline.cpp +++ b/src/coreclr/src/jit/inline.cpp @@ -734,8 +734,13 @@ InlineStrategy::InlineStrategy(Compiler* compiler) : m_Compiler(compiler) , m_RootContext(nullptr) , m_LastSuccessfulPolicy(nullptr) + , m_CallCount(0) , m_CandidateCount(0) - , m_InlineAttemptCount(0) + , m_AlwaysCandidateCount(0) + , m_ForceCandidateCount(0) + , m_DiscretionaryCandidateCount(0) + , m_UnprofitableCandidateCount(0) + , m_ImportCount(0) , m_InlineCount(0) , m_MaxInlineSize(DEFAULT_MAX_INLINE_SIZE) , m_MaxInlineDepth(DEFAULT_MAX_INLINE_DEPTH) @@ -837,11 +842,86 @@ InlineContext* InlineStrategy::GetRootContext() } //------------------------------------------------------------------------ -// NoteCandidate: do bookkeeping for an inline candidate +// NoteAttempt: do bookkeeping for an inline attempt +// +// Arguments: +// result -- InlineResult for successful inline candidate + +void InlineStrategy::NoteAttempt(InlineResult* result) +{ + assert(result->IsCandidate()); + InlineObservation obs = result->GetObservation(); + + if (obs == InlineObservation::CALLEE_BELOW_ALWAYS_INLINE_SIZE) + { + m_AlwaysCandidateCount++; + } + else if (obs == InlineObservation::CALLEE_IS_FORCE_INLINE) + { + m_ForceCandidateCount++; + } + else + { + m_DiscretionaryCandidateCount++; + } +} + +//------------------------------------------------------------------------ +// DumpCsvHeader: dump header for csv inline stats +// +// Argument: +// fp -- file for dump output -void InlineStrategy::NoteCandidate() +void InlineStrategy::DumpCsvHeader(FILE* fp) { - m_CandidateCount++; + fprintf(fp, "\"InlineCalls\","); + fprintf(fp, "\"InlineCandidates\","); + fprintf(fp, "\"InlineAlways\","); + fprintf(fp, "\"InlineForce\","); + fprintf(fp, "\"InlineDiscretionary\","); + fprintf(fp, "\"InlineUnprofitable\","); + fprintf(fp, "\"InlineEarlyFail\","); + fprintf(fp, "\"InlineImport\","); + fprintf(fp, "\"InlineLateFail\","); + fprintf(fp, "\"InlineSuccess\","); +} + +//------------------------------------------------------------------------ +// DumpCsvData: dump data for csv inline stats +// +// Argument: +// fp -- file for dump output + +void InlineStrategy::DumpCsvData(FILE* fp) +{ + fprintf(fp, "%u,", m_CallCount); + fprintf(fp, "%u,", m_CandidateCount); + fprintf(fp, "%u,", m_AlwaysCandidateCount); + fprintf(fp, "%u,", m_ForceCandidateCount); + fprintf(fp, "%u,", m_DiscretionaryCandidateCount); + fprintf(fp, "%u,", m_UnprofitableCandidateCount); + + // Early failures are cases where candates are rejected between + // the time the jit invokes the inlinee compiler and the time it + // starts to import the inlinee IL. + // + // So they are "cheaper" that late failures. + + unsigned profitableCandidateCount = + m_DiscretionaryCandidateCount - m_UnprofitableCandidateCount; + + unsigned earlyFailCount = m_CandidateCount + - m_AlwaysCandidateCount + - m_ForceCandidateCount + - profitableCandidateCount; + + fprintf(fp, "%u,", earlyFailCount); + + unsigned lateFailCount = m_ImportCount - m_InlineCount; + + fprintf(fp, "%u,", m_ImportCount); + fprintf(fp, "%u,", lateFailCount); + fprintf(fp, "%u,", m_InlineCount); } //------------------------------------------------------------------------ @@ -851,7 +931,7 @@ void InlineStrategy::NoteCandidate() // context - context describing this inline // // Return Value: -// Nominal estimate of jit time. +// Nominal estimate of jit time. int InlineStrategy::EstimateTime(InlineContext* context) { @@ -945,10 +1025,9 @@ int InlineStrategy::EstimateSize(InlineContext* context) void InlineStrategy::NoteOutcome(InlineContext* context) { - // Might want to differentiate candidates from non-candidates here... - // We don't really attempt to inline non-candidates. - m_InlineAttemptCount++; - + // Note we can't generally count up failures here -- we only + // create contexts for failures in debug modes, and even then + // we may not get them all. if (context->IsSuccess()) { m_InlineCount++; diff --git a/src/coreclr/src/jit/inline.h b/src/coreclr/src/jit/inline.h index aa0573c..55671b3 100644 --- a/src/coreclr/src/jit/inline.h +++ b/src/coreclr/src/jit/inline.h @@ -400,7 +400,7 @@ public: // Determine if this inline is profitable void DetermineProfitability(CORINFO_METHOD_INFO* methodInfo) { - return m_Policy->DetermineProfitability(methodInfo); + m_Policy->DetermineProfitability(methodInfo); } // Ensure details of this inlining process are appropriately @@ -751,8 +751,40 @@ public: return m_InitialSizeEstimate; } + // Inform strategy that there's another call + void NoteCall() + { + m_CallCount++; + } + // Inform strategy that there's a new inline candidate. - void NoteCandidate(); + void NoteCandidate() + { + m_CandidateCount++; + } + + // Inform strategy that a candidate was assessed and determined to + // be unprofitable. + void NoteUnprofitable() + { + m_UnprofitableCandidateCount++; + } + + // Inform strategy that a candidate has passed screening + // and that the jit will attempt to inline. + void NoteAttempt(InlineResult* result); + + // Inform strategy that jit is about to import the inlinee IL. + void NoteImport() + { + m_ImportCount++; + } + + // Dump csv header for inline stats to indicated file. + static void DumpCsvHeader(FILE* f); + + // Dump csv data for inline stats to indicated file. + void DumpCsvData(FILE* f); // See if an inline of this size would fit within the current jit // time budget. @@ -834,8 +866,13 @@ private: InlineContext* m_RootContext; InlinePolicy* m_LastSuccessfulPolicy; InlineContext* m_LastContext; + unsigned m_CallCount; unsigned m_CandidateCount; - unsigned m_InlineAttemptCount; + unsigned m_AlwaysCandidateCount; + unsigned m_ForceCandidateCount; + unsigned m_DiscretionaryCandidateCount; + unsigned m_UnprofitableCandidateCount; + unsigned m_ImportCount; unsigned m_InlineCount; unsigned m_MaxInlineSize; unsigned m_MaxInlineDepth; diff --git a/src/coreclr/src/jit/morph.cpp b/src/coreclr/src/jit/morph.cpp index 5572d8c..c7fcabb 100755 --- a/src/coreclr/src/jit/morph.cpp +++ b/src/coreclr/src/jit/morph.cpp @@ -6516,6 +6516,8 @@ void Compiler::fgMorphCallInlineHelper(GenTreeCall* call, InlineResult* result) } #endif + impInlineRoot()->m_inlineStrategy->NoteAttempt(result); + // // Invoke the compiler to inline the call. // -- 2.7.4