Merge remote-tracking branch 'origin/topic/timw/2485-script-profile-call-stacks'

* origin/topic/timw/2485-script-profile-call-stacks:
  Add call stacks to script profiler output

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)

VERSION

@@ -1 +1 @@
-6.0.0-dev.385
+6.0.0-dev.387

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[=<speedup>]   | 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.

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<const Func*, ScriptProfileStats> 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");
+	        "#fields\tfunction\tlocation\ttype\tncall\ttot_CPU\tchild_CPU\ttot_Mem\tchild_"
-	fprintf(f, "#types\tstring\tstring\tstring\tcount\tinterval\tinterval\tcount\tcount\n");
+	        "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<no-location>\tTOTAL\t%d\t%.06f\t%.06f\t%" PRIu64 "\t%lld\n",
+	fprintf(f, "non-scripts\t<no-location>\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);
+	        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<ScriptProfileMgr> 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<detail::ScriptProfileMgr>(f);
+
+	if ( with_traces )
+		detail::spm->EnableTraces();
 	}
 
 	} // namespace zeek

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<std::string, StackData> 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)
+	void AddIn(const ScriptProfileStats* eps, bool bump_num_calls = true,
-		{
+	           const std::string& stack = "");
-		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)
@@ -83,6 +87,7 @@ private:
 	int ncalls = 0;
 	double CPU_time = 0.0;
 	uint64_t memory = 0;
+	std::unordered_map<std::string, StackData> 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<const Obj*> objs;
+
+	bool with_traces = false;
 	};
 
 // If non-nil, script profiling is active.
@@ -187,6 +196,6 @@ extern std::unique_ptr<ScriptProfileMgr> 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