diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index f5158bcb50..81834cf7d2 100644 --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -330,6 +330,7 @@ set(MAIN_SRCS ScannedFile.cc Scope.cc ScriptCoverageManager.cc + ScriptProfile.cc SerializationFormat.cc SmithWaterman.cc Stats.cc diff --git a/src/ScriptProfile.cc b/src/ScriptProfile.cc new file mode 100644 index 0000000000..198d6cd268 --- /dev/null +++ b/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 = ""; + 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 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\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(body.get()) : f; + auto associated_prof = profiles.find(o); + ScriptProfile* ep; + + if ( associated_prof == profiles.end() ) + { + auto new_ep = std::make_unique(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 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(f); + } + + } // namespace zeek diff --git a/src/ScriptProfile.h b/src/ScriptProfile.h new file mode 100644 index 0000000000..2ea7de2d7b --- /dev/null +++ b/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 + +#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 call_stack; + + // Maps a given object (either a function body, for scripts, or the + // function itself, for BiFs) to its profile. + std::unordered_map> profiles; + + // Maps script bodies to their function - used for functions with + // multiple bodies. + std::unordered_map body_to_func; + + // Tracks the objects encountered. Used to generate a consistent + // and more natural printing order. + std::vector objs; + }; + +// If non-nil, script profiling is active. +extern std::unique_ptr 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