diff --git a/CHANGES b/CHANGES index 1466070107..47137cfd53 100644 --- a/CHANGES +++ b/CHANGES @@ -1,3 +1,7 @@ +6.0.0-dev.387 | 2023-04-19 09:01:32 -0700 + + * Add call stacks to script profiler output (Tim Wojtulewicz, Corelight) + 6.0.0-dev.385 | 2023-04-19 11:58:09 +0200 * different fix for MSVC compiler issues (Vern Paxson, Corelight) diff --git a/VERSION b/VERSION index f431765c08..ff2aa57cb9 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -6.0.0-dev.385 +6.0.0-dev.387 diff --git a/src/Options.cc b/src/Options.cc index dd0913d019..d937957f90 100644 --- a/src/Options.cc +++ b/src/Options.cc @@ -147,6 +147,9 @@ void usage(const char* prog, int code) fprintf( stderr, " --profile-scripts[=file] | profile scripts to given file (default stdout)\n"); + fprintf(stderr, + " --profile-script-call-stacks | add call stacks to profile output (requires " + "--profile-scripts)\n"); fprintf(stderr, " --pseudo-realtime[=] | enable pseudo-realtime for performance " "evaluation (default 1)\n"); fprintf(stderr, " -j|--jobs | enable supervisor mode\n"); @@ -369,8 +372,13 @@ Options parse_cmdline(int argc, char** argv) } int profile_scripts = 0; + int profile_script_call_stacks = 0; + std::string profile_filename; int no_unused_warnings = 0; + bool enable_script_profile = false; + bool enable_script_profile_call_stacks = false; + struct option long_opts[] = { {"parse-only", no_argument, nullptr, 'a'}, {"bare-mode", no_argument, nullptr, 'b'}, @@ -414,6 +422,7 @@ Options parse_cmdline(int argc, char** argv) #endif {"profile-scripts", optional_argument, &profile_scripts, 1}, + {"profile-script-call-stacks", optional_argument, &profile_script_call_stacks, 1}, {"no-unused-warnings", no_argument, &no_unused_warnings, 1}, {"pseudo-realtime", optional_argument, nullptr, '~'}, {"jobs", optional_argument, nullptr, 'j'}, @@ -618,10 +627,17 @@ Options parse_cmdline(int argc, char** argv) // a short-option equivalent. if ( profile_scripts ) { - activate_script_profiling(optarg); + profile_filename = optarg ? optarg : ""; + enable_script_profile = true; profile_scripts = 0; } + if ( profile_script_call_stacks ) + { + enable_script_profile_call_stacks = true; + profile_script_call_stacks = 0; + } + if ( no_unused_warnings ) rval.no_unused_warnings = true; break; @@ -632,6 +648,17 @@ Options parse_cmdline(int argc, char** argv) break; } + if ( ! enable_script_profile && enable_script_profile_call_stacks ) + fprintf( + stderr, + "ERROR: --profile-scripts-traces requires --profile-scripts to be passed as well.\n"); + + if ( enable_script_profile ) + { + activate_script_profiling(profile_filename.empty() ? nullptr : profile_filename.c_str(), + enable_script_profile_call_stacks); + } + // Process remaining arguments. X=Y arguments indicate script // variable/parameter assignments. X::Y arguments indicate plugins to // activate/query. The remainder are treated as scripts to load. diff --git a/src/ScriptProfile.cc b/src/ScriptProfile.cc index cef5744652..e96f1bf328 100644 --- a/src/ScriptProfile.cc +++ b/src/ScriptProfile.cc @@ -17,7 +17,7 @@ void ScriptProfile::StartActivation() start_stats.SetStats(util::curr_CPU_time(), start_memory); } -void ScriptProfile::EndActivation() +void ScriptProfile::EndActivation(const std::string& stack) { uint64_t end_memory; util::get_memory_usage(&end_memory, nullptr); @@ -25,7 +25,7 @@ void ScriptProfile::EndActivation() delta_stats.SetStats(util::curr_CPU_time() - start_stats.CPUTime(), end_memory - start_stats.Memory()); - AddIn(&delta_stats, false); + AddIn(&delta_stats, false, stack); } void ScriptProfile::ChildFinished(const ScriptProfile* child) @@ -33,7 +33,7 @@ void ScriptProfile::ChildFinished(const ScriptProfile* child) child_stats.AddIn(child->DeltaCPUTime(), child->DeltaMemory()); } -void ScriptProfile::Report(FILE* f) const +void ScriptProfile::Report(FILE* f, bool with_traces) const { std::string l; @@ -46,10 +46,50 @@ void ScriptProfile::Report(FILE* f) const l = std::string(loc.filename) + ":" + std::to_string(loc.first_line); std::string ftype = is_BiF ? "BiF" : func->GetType()->FlavorString(); + std::string call_stacks; - fprintf(f, "%s\t%s\t%s\t%d\t%.06f\t%.06f\t%" PRIu64 "\t%" PRIu64 "\n", Name().c_str(), + if ( with_traces ) + { + std::string calls, counts, cpu, memory; + + for ( const auto& [s, stats] : Stacks() ) + { + calls += util::fmt("%s|", s.c_str()); + counts += util::fmt("%d|", stats.call_count); + cpu += util::fmt("%f|", stats.cpu_time); + memory += util::fmt("%llu|", stats.memory); + } + + calls.pop_back(); + counts.pop_back(); + cpu.pop_back(); + memory.pop_back(); + + call_stacks = util::fmt("\t%s\t%s\t%s\t%s", calls.c_str(), counts.c_str(), cpu.c_str(), + memory.c_str()); + } + + fprintf(f, "%s\t%s\t%s\t%d\t%.06f\t%.06f\t%" PRIu64 "\t%" PRIu64 "\t%s\n", Name().c_str(), l.c_str(), ftype.c_str(), NumCalls(), CPUTime(), child_stats.CPUTime(), Memory(), - child_stats.Memory()); + child_stats.Memory(), call_stacks.c_str()); + } + +void ScriptProfileStats::AddIn(const ScriptProfileStats* eps, bool bump_num_calls, + const std::string& stack) + { + if ( bump_num_calls ) + ncalls += eps->NumCalls(); + + CPU_time += eps->CPUTime(); + memory += eps->Memory(); + + if ( ! stack.empty() ) + { + auto& data = stacks[stack]; + data.call_count++; + data.cpu_time += eps->CPUTime(); + data.memory += eps->Memory(); + } } ScriptProfileMgr::ScriptProfileMgr(FILE* _f) : f(_f), non_scripts() @@ -67,14 +107,28 @@ ScriptProfileMgr::~ScriptProfileMgr() ScriptProfileStats BiF_stats; std::unordered_map func_stats; + std::string call_stack_header; + std::string call_stack_types; + std::string call_stack_nulls; + + if ( with_traces ) + { + call_stack_header = "\tstacks\tstack_calls\tstack_CPU\tstack_memory"; + call_stack_types = "\tstring\tstring\tstring\tstring"; + call_stack_nulls = "\t-\t-\t-\t-"; + } + 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"); + "#fields\tfunction\tlocation\ttype\tncall\ttot_CPU\tchild_CPU\ttot_Mem\tchild_" + "Mem%s\n", + call_stack_header.c_str()); + fprintf(f, "#types\tstring\tstring\tstring\tcount\tinterval\tinterval\tcount\tcount%s\n", + call_stack_types.c_str()); for ( auto o : objs ) { auto p = profiles[o].get(); - profiles[o]->Report(f); + profiles[o]->Report(f, with_traces); total_stats.AddInstance(); total_stats.AddIn(p); @@ -102,21 +156,22 @@ ScriptProfileMgr::~ScriptProfileMgr() auto& fp = fs.second; auto n = func->GetBodies().size(); if ( n > 1 ) - fprintf(f, "%s\t%zu-locations\t%s\t%d\t%.06f\t%0.6f\t%" PRIu64 "\t%lld\n", + fprintf(f, "%s\t%zu-locations\t%s\t%d\t%.06f\t%0.6f\t%" PRIu64 "\t%lld%s\n", fp.Name().c_str(), n, func->GetType()->FlavorString().c_str(), fp.NumCalls(), - fp.CPUTime(), 0.0, fp.Memory(), 0LL); + fp.CPUTime(), 0.0, fp.Memory(), 0LL, call_stack_nulls.c_str()); } - fprintf(f, "all-BiFs\t%d-locations\tBiF\t%d\t%.06f\t%.06f\t%" PRIu64 "\t%lld\n", + fprintf(f, "all-BiFs\t%d-locations\tBiF\t%d\t%.06f\t%.06f\t%" PRIu64 "\t%lld%s\n", BiF_stats.NumInstances(), BiF_stats.NumCalls(), BiF_stats.CPUTime(), 0.0, - BiF_stats.Memory(), 0LL); + BiF_stats.Memory(), 0LL, call_stack_nulls.c_str()); - fprintf(f, "total\t%d-locations\tTOTAL\t%d\t%.06f\t%.06f\t%" PRIu64 "\t%lld\n", + fprintf(f, "total\t%d-locations\tTOTAL\t%d\t%.06f\t%.06f\t%" PRIu64 "\t%lld%s\n", total_stats.NumInstances(), total_stats.NumCalls(), total_stats.CPUTime(), 0.0, - total_stats.Memory(), 0LL); + total_stats.Memory(), 0LL, call_stack_nulls.c_str()); - fprintf(f, "non-scripts\t\tTOTAL\t%d\t%.06f\t%.06f\t%" PRIu64 "\t%lld\n", - non_scripts.NumCalls(), non_scripts.CPUTime(), 0.0, non_scripts.Memory(), 0LL); + fprintf(f, "non-scripts\t\tTOTAL\t%d\t%.06f\t%.06f\t%" PRIu64 "\t%lld%s\n", + non_scripts.NumCalls(), non_scripts.CPUTime(), 0.0, non_scripts.Memory(), 0LL, + call_stack_nulls.c_str()); if ( f != stdout ) fclose(f); @@ -152,9 +207,17 @@ void ScriptProfileMgr::EndInvocation() { ASSERT(! call_stack.empty()); auto ep = call_stack.back(); + call_stack.pop_back(); - ep->EndActivation(); + std::string stack_string = ep->Name(); + for ( const auto& sep : call_stack ) + { + stack_string.append(";"); + stack_string.append(sep->Name()); + } + + ep->EndActivation(stack_string); if ( call_stack.empty() ) non_scripts.StartActivation(); @@ -169,7 +232,7 @@ std::unique_ptr spm; } // namespace zeek::detail -void activate_script_profiling(const char* fn) +void activate_script_profiling(const char* fn, bool with_traces) { FILE* f; @@ -186,6 +249,9 @@ void activate_script_profiling(const char* fn) f = stdout; detail::spm = std::make_unique(f); + + if ( with_traces ) + detail::spm->EnableTraces(); } } // namespace zeek diff --git a/src/ScriptProfile.h b/src/ScriptProfile.h index 99b3c8f419..13c74d8ea9 100644 --- a/src/ScriptProfile.h +++ b/src/ScriptProfile.h @@ -22,6 +22,13 @@ namespace detail class ScriptProfileStats { public: + struct StackData + { + int call_count = 0; + double cpu_time = 0.0; + uint64_t memory = 0; + }; + ScriptProfileStats() = default; ScriptProfileStats(std::string arg_name) : name(std::move(arg_name)) { } @@ -46,19 +53,16 @@ public: double CPUTime() const { return CPU_time; } uint64_t Memory() const { return memory; } + // Stacks for all of the calls plus counters. + std::unordered_map Stacks() const { return stacks; } + // 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(); - } + void AddIn(const ScriptProfileStats* eps, bool bump_num_calls = true, + const std::string& stack = ""); // Accumulate a single instance of CPU & memory usage. void AddIn(double delta_CPU_time, uint64_t delta_memory) @@ -83,6 +87,7 @@ private: int ncalls = 0; double CPU_time = 0.0; uint64_t memory = 0; + std::unordered_map stacks; }; // Manages all of the profile instances associated with a given script. @@ -111,7 +116,7 @@ public: // Called to register the beginning/end of an execution instance. void StartActivation(); - void EndActivation(); + void EndActivation(const std::string& stack = ""); // Called when a child instance finishes. void ChildFinished(const ScriptProfile* child); @@ -121,7 +126,7 @@ public: uint64_t DeltaMemory() const { return delta_stats.Memory(); } // Write the profile to the given file. - void Report(FILE* f) const; + void Report(FILE* f, bool with_traces) const; private: // We store "func" as a FuncPtr to ensure it sticks around when @@ -157,6 +162,8 @@ public: void StartInvocation(const Func* f, const detail::StmtPtr& body = nullptr); void EndInvocation(); + void EnableTraces() { with_traces = true; } + private: FILE* f; // where to write the profile @@ -178,6 +185,8 @@ private: // Tracks the objects encountered. Used to generate a consistent // and more natural printing order. std::vector objs; + + bool with_traces = false; }; // If non-nil, script profiling is active. @@ -187,6 +196,6 @@ extern std::unique_ptr spm; // 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); +extern void activate_script_profiling(const char* fn, bool with_traces); } // namespace zeek