Evaluate total impact of template library

.hgignore

@@ -0,0 +1,6 @@
+syntax: regexp
+^out\/
+^packages\/
+\.vs\/
+Release\/
+Debug\/

README.md

@@ -1,3 +1,36 @@
+# Fork changes
+
+Added `/sumof` command, which computes total time for all stuff matching given wildcard. Given a raw trace, it can be used as follows:
+
+    vcperf /sumof *Eigen* rawTrace.etl 
+
+It prints results to stdout:
+```
+Total time for parsing files matching "*Eigen*":
+  CPU Time:      79.565226 /  96.567721 / 110.676782
+  Duration:     448.373768 / 1112.570639 / 1168.585713
+Total time for template instantiations matching "*Eigen*":
+  CPU Time:     169.516602 / 169.516602 / 170.677942
+  Duration:     122.637069 / 188.706707 / 190.002096
+```
+
+Ideally, this should show how much time is spent on Eigen template library.
+Better use "CPU Time" instead of "Duration", unless you disable parallel builds.
+
+Note that every line reports three numbers, which are slightly different.
+The first one is the sum of exclusive time (as reported by framework) over all matching activities.
+The second one also the sum of exclusive time over all matches, but exclusive time is computed as inclusive time minus inclusive time of all children.
+The last one is the sum of inclusive time over all topmost matches.
+
+For instance, if we consider parsing files in the sample above:
+
+* 110.676782 seconds is spent on Eigen headers and all headers included from them (regardless of whether they are from Eigen of not).
+* 96.567721 or 79.565226 seconds is spent on Eigen headers only, and excludes time for non-Eigen headers included from them. No idea why these two numbers are different...
+
+*(Original vcperf readme follows)*
+
+---------------------
+
 # vcperf
 
 ## Overview

src/Commands.cpp

@@ -14,6 +14,8 @@
 #include "WPA\Views\TemplateInstantiationsView.h"
 #include "TimeTrace\ExecutionHierarchy.h"
 #include "TimeTrace\TimeTraceGenerator.h"
+#include "FilteredAggregator\FilteredAggregator.h"
+#include "FilteredAggregator\StatisticsCollector.h"
 
 using namespace Microsoft::Cpp::BuildInsights;
 
@@ -243,6 +245,29 @@ RESULT_CODE AnalyzeToTimeTrace(const std::filesystem::path& inputFile, const std
     return Analyze(inputFile.c_str(), analysisPassCount, analyzerGroup);
 }
 
+std::string ws2s(const std::wstring& wstr)
+{
+    std::string res;
+    for (int i = 0; i < wstr.size(); i++) {
+        // I feel sorry =)
+        assert(wstr[i] >= 0 && wstr[i] < 128);
+        res += char(wstr[i]);
+    }
+    return res;
+}
+HRESULT DoFilteredAggregate(const std::filesystem::path& inputFile, const std::wstring& wildcard)
+{
+    FilteringAggregator analyzer{ ws2s(wildcard) };
+    auto analyzerGroup = MakeStaticAnalyzerGroup(&analyzer);
+    return Analyze(inputFile.c_str(), 2, analyzerGroup);
+}
+HRESULT DoCollectStatistics(const std::filesystem::path& inputFile)
+{
+    StatisticsCollector analyzer;
+    auto analyzerGroup = MakeStaticAnalyzerGroup(&analyzer);
+    return Analyze(inputFile.c_str(), 2, analyzerGroup);
+}
+
 HRESULT DoStart(const std::wstring& sessionName, bool cpuSampling, VerbosityLevel verbosityLevel)
 {
     TRACING_SESSION_OPTIONS options{};

src/Commands.h

@@ -18,5 +18,7 @@ HRESULT DoStart(const std::wstring& sessionName, bool cpuSampling, VerbosityLeve
 HRESULT DoStop(const std::wstring& sessionName, const std::filesystem::path& outputFile, bool analyzeTemplates = false, bool generateTimeTrace = false);
 HRESULT DoStopNoAnalyze(const std::wstring& sessionName, const std::filesystem::path& outputFile);
 HRESULT DoAnalyze(const std::filesystem::path& inputFile, const std::filesystem::path& outputFile, bool analyzeTemplates = false, bool generateTimeTrace = false);
+HRESULT DoFilteredAggregate(const std::filesystem::path& inputFile, const std::wstring& wildcard);
+HRESULT DoCollectStatistics(const std::filesystem::path& inputFile);
 
 } // namespace vcperf

src/FilteredAggregator/FilteredAggregator.cpp

@@ -0,0 +1,168 @@
+#include "FilteredAggregator.h"
+#include <algorithm>
+#include <stdio.h>
+#include "Wildcard.h"
+#include "Undecorate.h"
+
+using namespace Microsoft::Cpp::BuildInsights;
+using namespace vcperf;
+
+
+FilteringAggregator::FilteringAggregator(const std::string& wildcard)
+{
+    wildcard_ = wildcard;
+}
+
+void FilteringAggregator::WildcardTime::Print() const
+{
+    printf("  CPU Time:     %10.6lf / %10.6lf / %10.6lf\n", 1e-9 * exclusiveCpuTime_, 1e-9 * subtractedCpuTime_, 1e-9 * inclusiveCpuTime_);
+    printf("  Duration:     %10.6lf / %10.6lf / %10.6lf\n", 1e-9 * exclusiveDuration_, 1e-9 * subtractedDuration_, 1e-9 * inclusiveDuration_);
+}
+
+BI::AnalysisControl FilteringAggregator::OnEndAnalysisPass()
+{
+    if (passNumber_ == 0) {
+        std::sort(filteredKeys_.begin(), filteredKeys_.end());
+        filteredKeys_.resize(std::unique(filteredKeys_.begin(), filteredKeys_.end()) - filteredKeys_.begin());
+
+        std::sort(functionNamesDecorated_.begin(), functionNamesDecorated_.end());
+        functionNamesDecorated_.resize(std::unique(functionNamesDecorated_.begin(), functionNamesDecorated_.end()) - functionNamesDecorated_.begin());
+        Undecorate(functionNamesDecorated_, functionNamesUndecorated_);
+    }
+    else if (passNumber_ == 1) {
+        filteredKeys_.clear();
+
+        printf("Total time for parsing files matching \"%s\":\n", wildcard_.c_str());
+        _parsingTime.Print();
+        printf("Total time for template instantiations matching \"%s\":\n", wildcard_.c_str());
+        _instantiationsTime.Print();
+        printf("Total time for code generation matching \"%s\":\n", wildcard_.c_str());
+        _generationTime.Print();
+    }
+    passNumber_++;
+
+    return AnalysisControl::CONTINUE;
+}
+
+AnalysisControl FilteringAggregator::OnStopActivity(const EventStack& eventStack)
+{
+    if (passNumber_ == 1) {
+        MatchEventStackInMemberFunction(eventStack, this, &FilteringAggregator::OnFinishTemplateInstantiation);
+        MatchEventStackInMemberFunction(eventStack, this, &FilteringAggregator::OnFileParse);
+    }
+    MatchEventStackInMemberFunction(eventStack, this, &FilteringAggregator::OnFunction);
+
+    return AnalysisControl::CONTINUE;
+}
+
+AnalysisControl FilteringAggregator::OnSimpleEvent(const EventStack& eventStack)
+{
+    if (passNumber_ == 0) {
+        MatchEventStackInMemberFunction(eventStack, this, &FilteringAggregator::OnSymbolName);
+    }
+
+    return AnalysisControl::CONTINUE;
+}
+
+void FilteringAggregator::OnSymbolName(const SE::SymbolName& symbolName)
+{
+    const char *name = symbolName.Name();
+    size_t len = strlen(name);
+    if (WildcardMatch(wildcard_.c_str(), name)) {
+        filteredKeys_.push_back(symbolName.Key());
+    }
+}
+
+bool FilteringAggregator::InstantiationMatchesWildcard(const A::TemplateInstantiation& templateInstantiation) const
+{
+    uint64_t primaryKey = templateInstantiation.PrimaryTemplateSymbolKey();
+    size_t pos = std::lower_bound(filteredKeys_.begin(), filteredKeys_.end(), primaryKey) - filteredKeys_.begin();
+    return (pos < filteredKeys_.size() && filteredKeys_[pos] == primaryKey);
+}
+
+bool FilteringAggregator::FileParseMatchesWildcard(const A::FrontEndFile& file) const
+{
+    const char *path = file.Path();
+    //bool isHeader = !(WildcardMatch("*.cpp", path) || WildcardMatch("*.cxx", path) || WildcardMatch("*.c", path));
+    return WildcardMatch(wildcard_.c_str(), path);
+}
+
+bool FilteringAggregator::FunctionMatchesWildcard(const A::Function& function) const
+{
+    std::string decName = function.Name();
+    size_t pos = std::lower_bound(functionNamesDecorated_.begin(), functionNamesDecorated_.end(), decName) - functionNamesDecorated_.begin();
+    if (pos == functionNamesDecorated_.size() || functionNamesDecorated_[pos] != decName)
+        return false;   //not even registered
+    const std::string& undecName = functionNamesUndecorated_[pos];
+    return WildcardMatch(wildcard_.c_str(), undecName.c_str());
+}
+
+template<class Activity> void FilteringAggregator::UpdateWildcardTime(const BI::EventGroup<Activity>& activityGroup, bool (FilteringAggregator::*matchFunc)(const Activity&) const, WildcardTime& totalTime) const
+{
+    int n = (int)activityGroup.Size();
+    uint64_t inclCpuTime = activityGroup.Back().CPUTime().count();
+    uint64_t inclDuration = activityGroup.Back().Duration().count();
+    uint64_t exclCpuTime = activityGroup.Back().ExclusiveCPUTime().count();
+    uint64_t exclDuration = activityGroup.Back().ExclusiveDuration().count();
+
+    if (n >= 1 && (this->*matchFunc)(activityGroup[n-1])) {
+        bool hasMatchingAncestor = false;
+        for (int i = n-2; i >= 0; i--)
+            if ((this->*matchFunc)(activityGroup[i])) {
+                hasMatchingAncestor = true;
+                break;
+            }
+        if (!hasMatchingAncestor) {
+            //instantiation stack looks like:  no, no, no, ..., no, match
+            totalTime.inclusiveCpuTime_ += inclCpuTime;
+            totalTime.inclusiveDuration_ += inclDuration;
+        }
+        //instantiation stack looks like:  any, any, any, ..., any, match
+        totalTime.subtractedCpuTime_ += inclCpuTime;
+        totalTime.subtractedDuration_ += inclDuration;
+        totalTime.exclusiveCpuTime_ += exclCpuTime;
+        totalTime.exclusiveDuration_ +=  exclDuration;
+    }
+    if (n >= 2 && (this->*matchFunc)(activityGroup[n-2])) {
+        //instantiation stack looks like:  any any ... any match any
+        totalTime.subtractedCpuTime_ -= inclCpuTime;
+        totalTime.subtractedDuration_ -= inclDuration;
+    }
+}
+
+template<class Activity> void FilteringAggregator::UpdateWildcardTime(const Activity& activity, bool (FilteringAggregator::* matchFunc)(const Activity&) const, WildcardTime& totalTime) const
+{
+    if (!(this->*matchFunc)(activity))
+        return;
+
+    uint64_t inclCpuTime = activity.CPUTime().count();
+    uint64_t inclDuration = activity.Duration().count();
+    uint64_t exclCpuTime = activity.ExclusiveCPUTime().count();
+    uint64_t exclDuration = activity.ExclusiveDuration().count();
+    totalTime.inclusiveCpuTime_ += inclCpuTime;
+    totalTime.inclusiveDuration_ += inclDuration;
+    totalTime.subtractedCpuTime_ += inclCpuTime;
+    totalTime.subtractedDuration_ += inclDuration;
+    totalTime.exclusiveCpuTime_ += exclCpuTime;
+    totalTime.exclusiveDuration_ += exclDuration;
+}
+
+void FilteringAggregator::OnFinishTemplateInstantiation(const A::Activity& parent, const A::TemplateInstantiationGroup& templateInstantiationGroup)
+{
+    UpdateWildcardTime(templateInstantiationGroup, &FilteringAggregator::InstantiationMatchesWildcard, _instantiationsTime);
+}
+
+void FilteringAggregator::OnFileParse(const A::FrontEndFileGroup& files)
+{
+    UpdateWildcardTime(files, &FilteringAggregator::FileParseMatchesWildcard, _parsingTime);
+}
+
+void FilteringAggregator::OnFunction(const A::Function& function)
+{
+    if (passNumber_ == 0) {
+        functionNamesDecorated_.push_back(function.Name());
+    }
+    if (passNumber_ == 1) {
+       UpdateWildcardTime(function, &FilteringAggregator::FunctionMatchesWildcard, _generationTime);
+    }
+}

src/FilteredAggregator/FilteredAggregator.h

@@ -0,0 +1,58 @@
+#pragma once
+
+#include <string>
+
+#include "VcperfBuildInsights.h"
+
+
+namespace vcperf
+{
+
+class FilteringAggregator : public BI::IAnalyzer {
+public:
+	FilteringAggregator(const std::string& wildcard);
+
+	BI::AnalysisControl OnEndAnalysisPass() override;
+	BI::AnalysisControl OnStopActivity(const BI::EventStack& eventStack) override;
+	BI::AnalysisControl OnSimpleEvent(const BI::EventStack& eventStack) override;
+
+private:
+	void OnFinishTemplateInstantiation(const A::Activity& parent, const A::TemplateInstantiationGroup& templateInstantiationGroup);
+	void OnSymbolName(const SE::SymbolName& symbolName);
+	void OnFileParse(const A::FrontEndFileGroup& files);
+	void OnFunction(const A::Function& function);
+
+	bool InstantiationMatchesWildcard(const A::TemplateInstantiation& templateInstantiation) const;
+	bool FileParseMatchesWildcard(const A::FrontEndFile& file) const;
+	bool FunctionMatchesWildcard(const A::Function& function) const;
+
+
+	struct WildcardTime {
+		uint64_t exclusiveCpuTime_ = 0;
+		uint64_t exclusiveDuration_ = 0;
+		uint64_t subtractedCpuTime_ = 0;
+		uint64_t subtractedDuration_ = 0;
+		uint64_t inclusiveCpuTime_ = 0;
+		uint64_t inclusiveDuration_ = 0;
+
+		void Print() const;
+	};
+	template<class Activity> void UpdateWildcardTime(const BI::EventGroup<Activity>& activityGroup, bool (FilteringAggregator::*matchFunc)(const Activity&) const, WildcardTime& totalTime) const;
+	template<class Activity> void UpdateWildcardTime(const Activity& activity, bool (FilteringAggregator::* matchFunc)(const Activity&) const, WildcardTime& totalTime) const;
+
+	//global
+	int passNumber_ = 0;
+	std::string wildcard_;
+
+	//pass 0:
+	std::vector<uint64_t> filteredKeys_;
+	std::vector<std::string> functionNamesDecorated_;
+	std::vector<std::string> functionNamesUndecorated_;
+
+	//pass 1:
+	WildcardTime _instantiationsTime;
+	WildcardTime _parsingTime;
+	WildcardTime _generationTime;
+};
+
+}