classes for managing script profiles

src/CMakeLists.txt

@@ -330,6 +330,7 @@ set(MAIN_SRCS
     ScannedFile.cc
     Scope.cc
     ScriptCoverageManager.cc
+    ScriptProfile.cc
     SerializationFormat.cc
     SmithWaterman.cc
     Stats.cc

src/ScriptProfile.cc

@@ -0,0 +1,185 @@
+// See the file "COPYING" in the main distribution directory for copyright.
+
+#include "zeek/ScriptProfile.h"
+
+namespace zeek
+	{
+
+namespace detail
+	{
+
+void ScriptProfile::StartActivation()
+	{
+	NewCall();
+
+	uint64_t start_memory;
+	util::get_memory_usage(&start_memory, nullptr);
+	start_stats.SetStats(util::curr_CPU_time(), start_memory);
+	}
+
+void ScriptProfile::EndActivation()
+	{
+	uint64_t end_memory;
+	util::get_memory_usage(&end_memory, nullptr);
+
+	delta_stats.SetStats(util::curr_CPU_time() - start_stats.CPUTime(),
+	                     end_memory - start_stats.Memory());
+
+	AddIn(&delta_stats, false);
+	}
+
+void ScriptProfile::ChildFinished(const ScriptProfile* child)
+	{
+	child_stats.AddIn(child->DeltaCPUTime(), child->DeltaMemory());
+	}
+
+void ScriptProfile::Report(FILE* f) const
+	{
+	std::string l;
+
+	if ( loc.first_line == 0 )
+		// Rather than just formatting the no-location loc, we'd like
+		// a version that doesn't have a funky "line 0" in it, nor
+		// an embedded blank.
+		l = "<no-location>";
+	else
+		l = std::string(loc.filename) + ":" + std::to_string(loc.first_line);
+
+	std::string ftype = is_BiF ? "BiF" : func->GetType()->FlavorString();
+
+	fprintf(f, "%s\t%s\t%s\t%d\t%.06f\t%.06f\t%lld\t%lld\n", Name().c_str(), l.c_str(),
+	        ftype.c_str(), NumCalls(), CPUTime(), child_stats.CPUTime(), Memory(),
+	        child_stats.Memory());
+	}
+
+ScriptProfileMgr::ScriptProfileMgr(FILE* _f) : f(_f), non_scripts()
+	{
+	non_scripts.StartActivation();
+	}
+
+ScriptProfileMgr::~ScriptProfileMgr()
+	{
+	ASSERT(call_stack.empty());
+
+	non_scripts.EndActivation();
+
+	ScriptProfileStats total_stats;
+	ScriptProfileStats BiF_stats;
+	std::unordered_map<const Func*, ScriptProfileStats> func_stats;
+
+	fprintf(f,
+	        "#fields\tfunction\tlocation\ttype\tncall\ttot_CPU\tchild_CPU\ttot_Mem\tchild_Mem\n");
+	fprintf(f, "#types\tstring\tstring\tstring\tcount\tinterval\tinterval\tcount\tcount\n");
+
+	for ( auto o : objs )
+		{
+		auto p = profiles[o].get();
+		profiles[o]->Report(f);
+
+		total_stats.AddInstance();
+		total_stats.AddIn(p);
+
+		if ( p->IsBiF() )
+			{
+			BiF_stats.AddInstance();
+			BiF_stats.AddIn(p);
+			}
+		else
+			{
+			ASSERT(body_to_func.count(o) > 0);
+			auto func = body_to_func[o];
+
+			if ( func_stats.count(func) == 0 )
+				func_stats[func] = ScriptProfileStats(func->Name());
+
+			func_stats[func].AddIn(p);
+			}
+		}
+
+	for ( auto& fs : func_stats )
+		{
+		auto func = fs.first;
+		auto& fp = fs.second;
+		auto n = func->GetBodies().size();
+		if ( n > 1 )
+			fprintf(f, "%s\t%lu-locations\t%s\t%d\t%.06f\t%0.6f\t%lld\t%lld\n", fp.Name().c_str(),
+			        n, func->GetType()->FlavorString().c_str(), fp.NumCalls(), fp.CPUTime(), 0.0,
+			        fp.Memory(), 0LL);
+		}
+
+	fprintf(f, "all-BiFs\t%d-locations\tBiF\t%d\t%.06f\t%.06f\t%lld\t%lld\n",
+	        BiF_stats.NumInstances(), BiF_stats.NumCalls(), BiF_stats.CPUTime(), 0.0,
+	        BiF_stats.Memory(), 0LL);
+
+	fprintf(f, "total\t%d-locations\tTOTAL\t%d\t%.06f\t%.06f\t%lld\t%lld\n",
+	        total_stats.NumInstances(), total_stats.NumCalls(), total_stats.CPUTime(), 0.0,
+	        total_stats.Memory(), 0LL);
+
+	fprintf(f, "non-scripts\t<no-location>\tTOTAL\t%d\t%.06f\t%.06f\t%lld\t%lld\n",
+	        non_scripts.NumCalls(), non_scripts.CPUTime(), 0.0, non_scripts.Memory(), 0LL);
+	}
+
+void ScriptProfileMgr::StartInvocation(const Func* f, const detail::StmtPtr& body)
+	{
+	if ( call_stack.empty() )
+		non_scripts.EndActivation();
+
+	const Obj* o = body ? static_cast<Obj*>(body.get()) : f;
+	auto associated_prof = profiles.find(o);
+	ScriptProfile* ep;
+
+	if ( associated_prof == profiles.end() )
+		{
+		auto new_ep = std::make_unique<ScriptProfile>(f, body);
+		ep = new_ep.get();
+		profiles[o] = std::move(new_ep);
+		objs.push_back(o);
+
+		if ( body )
+			body_to_func[o] = f;
+		}
+	else
+		ep = associated_prof->second.get();
+
+	ep->StartActivation();
+	call_stack.push_back(ep);
+	}
+
+void ScriptProfileMgr::EndInvocation()
+	{
+	ASSERT(! call_stack.empty());
+	auto ep = call_stack.back();
+	call_stack.pop_back();
+
+	ep->EndActivation();
+
+	if ( call_stack.empty() )
+		non_scripts.StartActivation();
+	else
+		{
+		auto parent = call_stack.back();
+		parent->ChildFinished(ep);
+		}
+	}
+
+std::unique_ptr<ScriptProfileMgr> spm;
+
+	} // namespace zeek::detail
+
+void activate_script_profiling(const char* fn)
+	{
+	FILE* f;
+
+	if ( fn )
+		{
+		f = fopen(fn, "w");
+		if ( ! f )
+			reporter->FatalError("can't open %s to record scripting profile", fn);
+		}
+	else
+		f = stdout;
+
+	detail::spm = std::make_unique<detail::ScriptProfileMgr>(f);
+	}
+
+	} // namespace zeek

src/ScriptProfile.h

@@ -0,0 +1,184 @@
+// See the file "COPYING" in the main distribution directory for copyright.
+
+// Classes for profiling CPU & memory usage by scripts.
+
+#pragma once
+
+#include <string>
+
+#include "zeek/Func.h"
+#include "zeek/Stmt.h"
+
+namespace zeek
+	{
+
+namespace detail
+	{
+
+// Base class for tracking an instance of profile information.  The instance
+// can be a single function body (equivalently, event handler or hook body),
+// or an aggregate that includes multiple function bodies.
+
+class ScriptProfileStats
+	{
+public:
+	ScriptProfileStats() { }
+	ScriptProfileStats(std::string arg_name) : name(std::move(arg_name)) { }
+
+	virtual ~ScriptProfileStats() { }
+
+	const auto Name() const { return name; }
+
+	// Number of instances included in an aggregate (like for "all BiFs").
+	// This is 1 for non-aggregates.
+	int NumInstances() const { return ninstances; }
+
+	// How many calls were profiled for this instance.
+	int NumCalls() const { return ncalls; }
+
+	// CPU & memory accumulated by the calls.
+	double CPUTime() const { return CPU_time; }
+	uint64_t Memory() const { return memory; }
+
+	// Used to count instances in an aggregate.
+	void AddInstance() { ++ninstances; }
+
+	// Fold into this profile another profile.  Second argument controls
+	// whether the folding should include increasing the number of calls.
+	void AddIn(const ScriptProfileStats* eps, bool bump_num_calls = true)
+		{
+		if ( bump_num_calls )
+			ncalls += eps->NumCalls();
+
+		CPU_time += eps->CPUTime();
+		memory += eps->Memory();
+		}
+
+	// Accumulate a single instance of CPU & memory usage.
+	void AddIn(double delta_CPU_time, uint64_t delta_memory)
+		{
+		CPU_time += delta_CPU_time;
+		memory += delta_memory;
+		}
+
+	// Directly specify the total CPU & memory usage.
+	void SetStats(double arg_CPU_time, uint64_t arg_memory)
+		{
+		CPU_time = arg_CPU_time;
+		memory = arg_memory;
+		}
+
+	// Track that the instance has had another call.
+	void NewCall() { ++ncalls; }
+
+private:
+	std::string name;
+	int ninstances = 0;
+	int ncalls = 0;
+	double CPU_time = 0.0;
+	uint64_t memory = 0;
+	};
+
+// Manages all of the profile instances assocaited with a given script.
+
+class ScriptProfile : public ScriptProfileStats
+	{
+public:
+	ScriptProfile(const Func* _func, const detail::StmtPtr& body)
+		: ScriptProfileStats(_func->Name())
+		{
+		func = _func;
+		is_BiF = body == nullptr;
+
+		if ( is_BiF )
+			loc = *func->GetLocationInfo();
+		else
+			loc = *body->GetLocationInfo();
+		}
+
+	// Constructor used for the special case of non-script acocunting.
+	ScriptProfile() : ScriptProfileStats("non-scripts")
+		{
+		func = nullptr;
+		is_BiF = false;
+		}
+
+	// Called to register the beginning/end of an execution instance.
+	void StartActivation();
+	void EndActivation();
+
+	// Called when a child instance finishes.
+	void ChildFinished(const ScriptProfile* child);
+
+	bool IsBiF() const { return is_BiF; }
+	double DeltaCPUTime() const { return delta_stats.CPUTime(); }
+	uint64_t DeltaMemory() const { return delta_stats.Memory(); }
+
+	// Write the profile to the given file.
+	void Report(FILE* f) const;
+
+private:
+	const Func* func;
+	bool is_BiF;
+	detail::Location loc;
+
+	// Profile associated with child instances (functions or hooks
+	// that this instance calls - does not include events that this
+	// instance generates).
+	ScriptProfileStats child_stats;
+
+	// These are ephemeral, only relevant between Start and End activations.
+	ScriptProfileStats start_stats;
+
+	// Defined for the last activation period.
+	ScriptProfileStats delta_stats;
+	};
+
+// Manages the entire script profiling process.
+class ScriptProfileMgr
+	{
+public:
+	// Argument specifies the file to write the profile to.
+	ScriptProfileMgr(FILE* f);
+
+	// Destructor generates the actual profile.
+	~ScriptProfileMgr();
+
+	// Mark that the given function body has begun/finished.  "body" is
+	// nil for BiFs.
+	void StartInvocation(const Func* f, const detail::StmtPtr& body = nullptr);
+	void EndInvocation();
+
+private:
+	FILE* f; // where to write the profile
+
+	// Separate "script" profile that tracks resource impact of non-script
+	// execution.
+	ScriptProfile non_scripts;
+
+	// Currently active instances.
+	std::vector<ScriptProfile*> call_stack;
+
+	// Maps a given object (either a function body, for scripts, or the
+	// function itself, for BiFs) to its profile.
+	std::unordered_map<const Obj*, std::unique_ptr<ScriptProfile>> profiles;
+
+	// Maps script bodies to their function - used for functions with
+	// multiple bodies.
+	std::unordered_map<const Obj*, const Func*> body_to_func;
+
+	// Tracks the objects encountered.  Used to generate a consistent
+	// and more natural printing order.
+	std::vector<const Obj*> objs;
+	};
+
+// If non-nil, script profiling is active.
+extern std::unique_ptr<ScriptProfileMgr> spm;
+
+	} // namespace zeek::detail
+
+// Called to turn on script profiling to the given file.  If nil, writes
+// the profile to stdout.
+extern void activate_script_profiling(const char* fn);
+
+	} // namespace zeek