Merge remote-tracking branch 'origin/topic/vern/fine-grained-ZAM-profiling'

* origin/topic/vern/fine-grained-ZAM-profiling:
  tie into updates to gen-zam
  ZAM documentation updated to reflect finer-grained profiling
  ZAM-specific BTest baseline changes for tweak to how ZAM bodies print
  BTest baseline changes for tweak to how ZAM bodies print
  ZAM execution changes to support richer profiling
  use richer block-aware location information for ZAM instructions
  better isolation of ZAM instruction elements hooks for tracking extended ZAM profiling location
  framework for --enable-ZAM-profiling configuration profiles go to zprof.log rather than stdout
  ZAM classes in support of finer-grained profiling
  refined ZAM function profiling to include (correct) statement line number blocks
  avoid potentially expensive mallinfo() call if result won't be used

CHANGES

@@ -1,3 +1,27 @@
+7.0.0-dev.92 | 2024-03-19 14:39:26 -0700
+
+  * ZAM documentation updated to reflect finer-grained profiling (Vern Paxson, Corelight)
+
+  * ZAM-specific BTest baseline changes for tweak to how ZAM bodies print (Vern Paxson, Corelight)
+
+  * BTest baseline changes for tweak to how ZAM bodies print (Vern Paxson, Corelight)
+
+  * ZAM execution changes to support richer profiling (Vern Paxson, Corelight)
+
+  * use richer block-aware location information for ZAM instructions (Vern Paxson, Corelight)
+
+  * better isolation of ZAM instruction elements (Vern Paxson, Corelight)
+    hooks for tracking extended ZAM profiling location
+
+  * framework for --enable-ZAM-profiling configuration (Vern Paxson, Corelight)
+    profiles go to zprof.log rather than stdout
+
+  * ZAM classes in support of finer-grained profiling (Vern Paxson, Corelight)
+
+  * refined ZAM function profiling to include (correct) statement line number blocks (Vern Paxson, Corelight)
+
+  * avoid potentially expensive mallinfo() call if result won't be used (Vern Paxson, Corelight)
+
 7.0.0-dev.80 | 2024-03-19 10:59:22 -0700
 
   * Remove variant from StdFunctionStmt (Tim Wojtulewicz, Corelight)

VERSION

@@ -1 +1 @@
-7.0.0-dev.80
+7.0.0-dev.92

auxil/gen-zam

@@ -1 +1 @@
-Subproject commit bbb5b3645aa7b65db9183b5fc0b3be8a952ea308
+Subproject commit c1eba47ad91762ba165189cd9c4cfddc2a8f0bd0

cmake_templates/zeek-config.h.in

@@ -241,6 +241,9 @@
 /* Spicy analyzers built in. */
 #cmakedefine01 USE_SPICY_ANALYZERS
 
+/* Enable/disable ZAM profiling capability */
+#cmakedefine ENABLE_ZAM_PROFILE
+
 /* String with host architecture (e.g., "linux-x86_64") */
 #define HOST_ARCHITECTURE "@HOST_ARCHITECTURE@"
 

configure

@@ -65,6 +65,7 @@ Usage: $0 [OPTION]... [VAR=VALUE]...
     --enable-static-binpac build binpac statically (ignored if --with-binpac is specified)
     --enable-static-broker build Broker statically (ignored if --with-broker is specified)
     --enable-werror        build with -Werror
+    --enable-ZAM-profiling build with ZAM profiling enabled (--enable-debug implies this)
     --disable-af-packet    don't include native AF_PACKET support (Linux only)
     --disable-archiver     don't build or install zeek-archiver tool
     --disable-auxtools     don't build or install auxiliary tools
@@ -254,9 +255,11 @@ while [ $# -ne 0 ]; do
         --enable-coverage)
             append_cache_entry ENABLE_COVERAGE BOOL true
             append_cache_entry ENABLE_DEBUG BOOL true
+            append_cache_entry ENABLE_ZAM_PROFILE BOOL true
             ;;
         --enable-debug)
             append_cache_entry ENABLE_DEBUG BOOL true
+            append_cache_entry ENABLE_ZAM_PROFILE BOOL true
             ;;
         --enable-fuzzers)
             append_cache_entry ZEEK_ENABLE_FUZZERS BOOL true
@@ -280,6 +283,9 @@ while [ $# -ne 0 ]; do
         --enable-werror)
             append_cache_entry BUILD_WITH_WERROR BOOL true
             ;;
+        --enable-ZAM-profiling)
+            append_cache_entry ENABLE_ZAM_PROFILE BOOL true
+            ;;
         --disable-af-packet)
             append_cache_entry DISABLE_AF_PACKET BOOL true
             ;;

src/CMakeLists.txt

@@ -424,6 +424,7 @@ set(MAIN_SRCS
     script_opt/ZAM/Expr.cc
     script_opt/ZAM/Inst-Gen.cc
     script_opt/ZAM/Low-Level.cc
+    script_opt/ZAM/Profile.cc
     script_opt/ZAM/Stmt.cc
     script_opt/ZAM/Support.cc
     script_opt/ZAM/Vars.cc

src/Options.cc

@@ -192,7 +192,7 @@ static void print_analysis_help() {
     fprintf(stderr, "    no-ZAM-opt	omit low-level ZAM optimization\n");
     fprintf(stderr, "    optimize-all	optimize all scripts, even inlined ones\n");
     fprintf(stderr, "    optimize-AST	optimize the (transformed) AST; implies xform\n");
-    fprintf(stderr, "    profile-ZAM	generate to stdout a ZAM execution profile; implies -O ZAM\n");
+    fprintf(stderr, "    profile-ZAM	generate to zprof.out a ZAM execution profile; implies -O ZAM\n");
     fprintf(stderr, "    report-recursive	report on recursive functions and exit\n");
     fprintf(stderr, "    xform	transform scripts to \"reduced\" form\n");
 
@@ -245,7 +245,7 @@ static void set_analysis_option(const char* opt, Options& opts) {
     else if ( util::streq(opt, "optimize-AST") )
         a_o.activate = a_o.optimize_AST = true;
     else if ( util::streq(opt, "profile-ZAM") )
-        a_o.activate = a_o.gen_ZAM_code = a_o.profile_ZAM = true;
+        a_o.activate = a_o.profile_ZAM = true;
     else if ( util::streq(opt, "report-C++") )
         a_o.report_CPP = true;
     else if ( util::streq(opt, "report-recursive") )

src/Var.cc

@@ -20,6 +20,7 @@
 #include "zeek/Val.h"
 #include "zeek/module_util.h"
 #include "zeek/script_opt/IDOptInfo.h"
+#include "zeek/script_opt/ScriptOpt.h"
 #include "zeek/script_opt/StmtOptInfo.h"
 #include "zeek/script_opt/UsageAnalyzer.h"
 
@@ -399,7 +400,10 @@ void add_type(ID* id, TypePtr t, std::unique_ptr<std::vector<AttrPtr>> attr) {
 
 static std::set<std::string> all_module_names;
 
-void add_module(const char* module_name) { all_module_names.emplace(module_name); }
+void add_module(const char* module_name) {
+    all_module_names.emplace(module_name);
+    switch_to_module(module_name);
+}
 
 const std::set<std::string>& module_names() { return all_module_names; }
 

src/script_opt/ProfileFunc.cc

@@ -1401,4 +1401,152 @@ std::shared_ptr<SideEffectsOp> ProfileFuncs::GetCallSideEffects(const ScriptFunc
     return seo;
 }
 
+// We associate modules with filenames, and take the first one we see.
+static std::unordered_map<std::string, std::string> filename_module;
+
+void switch_to_module(const char* module_name) {
+    auto loc = GetCurrentLocation();
+    if ( loc.first_line != 0 && filename_module.count(loc.filename) == 0 )
+        filename_module[loc.filename] = module_name;
+}
+
+std::string func_name_at_loc(std::string fname, const Location* loc) {
+    auto find_module = filename_module.find(loc->filename);
+    if ( find_module == filename_module.end() )
+        // No associated module.
+        return fname;
+
+    auto& module = find_module->second;
+    if ( module.empty() || module == "GLOBAL" )
+        // Trivial associated module.
+        return fname;
+
+    auto mod_prefix = module + "::";
+
+    if ( fname.find(mod_prefix) == 0 )
+        return fname; // it already has the module name
+
+    return mod_prefix + fname;
+}
+
+TraversalCode SetBlockLineNumbers::PreStmt(const Stmt* s) {
+    auto loc = const_cast<Location*>(s->GetLocationInfo());
+    UpdateLocInfo(loc);
+    block_line_range.emplace_back(std::pair<int, int>{loc->first_line, loc->last_line});
+    return TC_CONTINUE;
+}
+
+TraversalCode SetBlockLineNumbers::PostStmt(const Stmt* s) {
+    auto loc = const_cast<Location*>(s->GetLocationInfo());
+    auto& r = block_line_range.back();
+    loc->first_line = r.first;
+    loc->last_line = r.second;
+
+    block_line_range.pop_back();
+
+    if ( ! block_line_range.empty() ) {
+        // We may have widened our range, propagate that to our parent.
+        auto& r_p = block_line_range.back();
+        r_p.first = std::min(r_p.first, r.first);
+        r_p.second = std::max(r_p.second, r.second);
+    }
+
+    return TC_CONTINUE;
+}
+
+TraversalCode SetBlockLineNumbers::PreExpr(const Expr* e) {
+    ASSERT(! block_line_range.empty());
+    UpdateLocInfo(const_cast<Location*>(e->GetLocationInfo()));
+    return TC_CONTINUE;
+}
+
+void SetBlockLineNumbers::UpdateLocInfo(Location* loc) {
+    // Sometimes locations are generated with inverted line coverage.
+    if ( loc->first_line > loc->last_line )
+        std::swap(loc->first_line, loc->last_line);
+
+    auto first_line = loc->first_line;
+    auto last_line = loc->last_line;
+
+    if ( ! block_line_range.empty() ) {
+        auto& r = block_line_range.back();
+        r.first = std::min(r.first, first_line);
+        r.second = std::max(r.second, last_line);
+    }
+}
+
+ASTBlockAnalyzer::ASTBlockAnalyzer(std::vector<FuncInfo>& funcs) {
+    for ( auto& f : funcs ) {
+        if ( ! f.ShouldAnalyze() )
+            continue;
+
+        auto func = f.Func();
+        std::string fn = func->Name();
+        auto body = f.Body();
+
+        // First get the line numbers all sorted out.
+        SetBlockLineNumbers sbln;
+        body->Traverse(&sbln);
+
+        auto body_loc = body->GetLocationInfo();
+        fn = func_name_at_loc(fn, body_loc);
+
+        parents.emplace_back(std::pair<std::string, std::string>{fn, fn});
+        func_name_prefix = fn + ":";
+        body->Traverse(this);
+        parents.pop_back();
+    }
+
+    // This should never appear!
+    func_name_prefix = "<MISSING>:";
+}
+
+static bool is_compound_stmt(const Stmt* s) {
+    static std::set<StmtTag> compound_stmts = {STMT_FOR, STMT_IF, STMT_LIST, STMT_SWITCH, STMT_WHEN, STMT_WHILE};
+    return compound_stmts.count(s->Tag()) > 0;
+}
+
+TraversalCode ASTBlockAnalyzer::PreStmt(const Stmt* s) {
+    auto loc = s->GetLocationInfo();
+    auto ls = BuildExpandedDescription(loc);
+
+    if ( is_compound_stmt(s) )
+        parents.push_back(std::pair<std::string, std::string>{LocWithFunc(loc), std::move(ls)});
+
+    return TC_CONTINUE;
+}
+
+TraversalCode ASTBlockAnalyzer::PostStmt(const Stmt* s) {
+    if ( is_compound_stmt(s) )
+        parents.pop_back();
+
+    return TC_CONTINUE;
+}
+
+TraversalCode ASTBlockAnalyzer::PreExpr(const Expr* e) {
+    (void)BuildExpandedDescription(e->GetLocationInfo());
+    return TC_CONTINUE;
+}
+
+std::string ASTBlockAnalyzer::BuildExpandedDescription(const Location* loc) {
+    ASSERT(loc && loc->first_line != 0);
+
+    auto ls = LocWithFunc(loc);
+    if ( ! parents.empty() ) {
+        auto& parent_pair = parents.back();
+        if ( parent_pair.first == ls )
+            ls = parent_pair.second;
+        else
+            ls = parent_pair.second + ";" + ls;
+    }
+
+    auto lk = LocKey(loc);
+    if ( exp_desc.count(lk) == 0 )
+        exp_desc[lk] = ls;
+
+    return ls;
+}
+
+std::unique_ptr<ASTBlockAnalyzer> AST_blocks;
+
 } // namespace zeek::detail

src/script_opt/ProfileFunc.h

@@ -609,4 +609,102 @@ protected:
     bool full_record_hashes;
 };
 
+// Updates the line numbers associated with an AST node to reflect its
+// full block (i.e., correct "first" and "last" for multi-line and compound
+// statements).
+class SetBlockLineNumbers : public TraversalCallback {
+public:
+    // Note, these modify the location information of their "const" arguments.
+    // It would be cleaner if Obj provided an interface for doing so (by making
+    // SetLocationInfo be a "const" method), but unfortunately it's virtual
+    // (unclear why) so we don't know how it might be overridden in user code.
+    TraversalCode PreStmt(const Stmt*) override;
+    TraversalCode PostStmt(const Stmt*) override;
+    TraversalCode PreExpr(const Expr*) override;
+
+private:
+    void UpdateLocInfo(Location* loc);
+
+    // A stack of block ranges. Each entry in the vector corresponds to a
+    // statement block, managed in a LIFO manner reflecting statement nesting.
+    // We start building up a given block's range during pre-traversal and
+    // finish it during post-traversal, propagating the updates to the
+    // nesting parent.
+    std::vector<std::pair<int, int>> block_line_range;
+};
+
+// Goes through all of the functions to associate full location information
+// with each AST node.
+class ASTBlockAnalyzer : public TraversalCallback {
+public:
+    ASTBlockAnalyzer(std::vector<FuncInfo>& funcs);
+
+    TraversalCode PreStmt(const Stmt*) override;
+    TraversalCode PostStmt(const Stmt*) override;
+    TraversalCode PreExpr(const Expr*) override;
+
+    // For a given location, returns its full local description (not
+    // including its parent).
+    std::string GetDesc(const Location* loc) const {
+        auto e_d = exp_desc.find(LocKey(loc));
+        if ( e_d == exp_desc.end() )
+            return LocWithFunc(loc);
+        else
+            return e_d->second;
+    }
+
+    // Whether we've created a description for the given location. This
+    // should always be true other than for certain functions with empty
+    // bodies that are created post-parsing. Available for debugging so
+    // we can assert we have these.
+    bool HaveExpDesc(const Location* loc) const { return exp_desc.count(LocKey(loc)) > 0; }
+
+private:
+    // Construct the full expanded description associated with the given
+    // location (if not already cached) and return it. This is the "static"
+    // view; if we reach the location via a non-inlined call, we will
+    // prepend that expansion when reporting the corresponding profile.
+    std::string BuildExpandedDescription(const Location* loc);
+
+    // Return the key used to associate a Location object with its full
+    // descriptiion.
+    std::string LocKey(const Location* loc) const {
+        return std::string(loc->filename) + ":" + std::to_string(loc->first_line) + "-" +
+               std::to_string(loc->last_line);
+    }
+
+    // Return the description of a location including its the function
+    // in which it's embedded.
+    std::string LocWithFunc(const Location* loc) const {
+        auto res = func_name_prefix + std::to_string(loc->first_line);
+
+        if ( loc->first_line != loc->last_line )
+            res += "-" + std::to_string(loc->last_line);
+
+        return res;
+    }
+
+    // The function whose body we are analyzing, in a form convenient
+    // for adding it as a prefix (i.e., with a trailing ':').
+    std::string func_name_prefix;
+
+    // Stack of expanded descriptions of parent blocks. Each entry is
+    // a pair of the parent's own description plus the full descriptor
+    // up to that point.
+    std::vector<std::pair<std::string, std::string>> parents;
+
+    // Maps a statement's location key to its expanded description.
+    std::unordered_map<std::string, std::string> exp_desc;
+};
+
+// If we're profiling, this provides the analysis of how low-level location
+// information relates to higher-level statement blocks.
+extern std::unique_ptr<ASTBlockAnalyzer> AST_blocks;
+
+// Returns the full name of a function at a given location, including its
+// associated module (even for event handlers that don't actually have
+// modules in their names), so we can track overall per-module resource
+// usage.
+extern std::string func_name_at_loc(std::string fname, const Location* loc);
+
 } // namespace zeek::detail

src/script_opt/ScriptOpt.cc

@@ -17,6 +17,7 @@
 #include "zeek/script_opt/UsageAnalyzer.h"
 #include "zeek/script_opt/UseDefs.h"
 #include "zeek/script_opt/ZAM/Compile.h"
+#include "zeek/script_opt/ZAM/Profile.h"
 
 namespace zeek::detail {
 
@@ -310,6 +311,22 @@ static void init_options() {
             add_file_analysis_pattern(analysis_options, zo);
     }
 
+    if ( analysis_options.profile_ZAM ) {
+        auto zsamp = getenv("ZEEK_ZAM_PROF_SAMPLING_RATE");
+        if ( zsamp ) {
+            analysis_options.profile_sampling_rate = atoi(zsamp);
+            if ( analysis_options.profile_sampling_rate == 0 ) {
+                fprintf(stderr, "bad ZAM sampling profile rate from $ZEEK_ZAM_PROF_SAMPLING_RATE: %s\n", zsamp);
+                analysis_options.profile_ZAM = false;
+            }
+        }
+
+        // If no ZAM generation options have been specified, default to
+        // the usual "-O ZAM" profile. But if they have, honor those.
+        if ( ! analysis_options.gen_ZAM_code )
+            analysis_options.gen_ZAM = true;
+    }
+
     if ( analysis_options.gen_ZAM ) {
         analysis_options.gen_ZAM_code = true;
         analysis_options.inliner = true;
@@ -437,6 +454,19 @@ static void analyze_scripts_for_ZAM() {
 
     auto pfs = std::make_shared<ProfileFuncs>(funcs, nullptr, true);
 
+    if ( analysis_options.profile_ZAM ) {
+#ifdef ENABLE_ZAM_PROFILE
+        AST_blocks = std::make_unique<ASTBlockAnalyzer>(funcs);
+        const auto prof_filename = "zprof.out";
+        analysis_options.profile_file = fopen(prof_filename, "w");
+        if ( ! analysis_options.profile_file )
+            reporter->FatalError("cannot create ZAM profiling log %s", prof_filename);
+#else
+        fprintf(stderr, "warning: zeek was not built with --enable-ZAM-profiling\n");
+        analysis_options.profile_ZAM = false;
+#endif
+    }
+
     bool report_recursive = analysis_options.report_recursive;
     std::unique_ptr<Inliner> inl;
     if ( analysis_options.inliner )
@@ -599,11 +629,20 @@ void profile_script_execution() {
     if ( analysis_options.profile_ZAM ) {
         report_ZOP_profile();
 
+        ProfMap module_prof;
+
         for ( auto& f : funcs ) {
-            if ( f.Body()->Tag() == STMT_ZAM )
-                cast_intrusive<ZBody>(f.Body())->ProfileExecution();
+            if ( f.Body()->Tag() == STMT_ZAM ) {
+                auto zb = cast_intrusive<ZBody>(f.Body());
+                zb->ReportExecutionProfile(module_prof);
             }
         }
+
+        for ( auto& mp : module_prof )
+            if ( mp.second.num_samples > 0 )
+                fprintf(analysis_options.profile_file, "module %s sampled CPU time %.06f, %d sampled instructions\n",
+                        mp.first.c_str(), mp.second.CPU_time, static_cast<int>(mp.second.num_samples));
+    }
 }
 
 void finish_script_execution() { profile_script_execution(); }

src/script_opt/ScriptOpt.h

@@ -75,6 +75,12 @@ struct AnalyOpt {
     // Produce a profile of ZAM execution.
     bool profile_ZAM = false;
 
+    // ZAM profiling sampling rate. Set via ZEEK_ZAM_PROF_SAMPLING_RATE.
+    int profile_sampling_rate = 100;
+
+    // An associated file to which to write the profile.
+    FILE* profile_file = nullptr;
+
     // If true, dump out transformed code: the results of reducing
     // interpreted scripts, and, if optimize is set, of then optimizing
     // them.
@@ -217,6 +223,10 @@ extern void analyze_global_stmts(Stmt* stmts);
 // Returns the body and scope for the previously analyzed global statements.
 extern std::pair<StmtPtr, ScopePtr> get_global_stmts();
 
+// Informs script optimization that parsing is switching to the given module.
+// Used to associate module names with profiling information.
+extern void switch_to_module(const char* module);
+
 // Add a pattern to the "only_funcs" list.
 extern void add_func_analysis_pattern(AnalyOpt& opts, const char* pat);
 

src/script_opt/ZAM/AM-Opt.cc

@@ -577,7 +577,7 @@ void ZAMCompiler::ReMapFrame() {
 
                     if ( new_slot < 0 ) {
                         ODesc d;
-                        inst->stmt->GetLocationInfo()->Describe(&d);
+                        inst->loc->Loc()->Describe(&d);
                         reporter->Error("%s: value used but not set: %s", d.Description(),
                                         frame_denizens[slot]->Name());
                     }
@@ -748,7 +748,7 @@ void ZAMCompiler::CheckSlotUse(int slot, const ZInstI* inst) {
 
     if ( denizen_beginning.count(slot) == 0 ) {
         ODesc d;
-        inst->stmt->GetLocationInfo()->Describe(&d);
+        inst->loc->Loc()->Describe(&d);
         reporter->Error("%s: value used but not set: %s", d.Description(), frame_denizens[slot]->Name());
     }
 

src/script_opt/ZAM/Compile.h

@@ -228,6 +228,7 @@ private:
     const ZAMStmt Call(const ExprStmt* e);
     const ZAMStmt AssignToCall(const ExprStmt* e);
     const ZAMStmt DoCall(const CallExpr* c, const NameExpr* n);
+    bool CheckForBuiltIn(const ExprPtr& e, CallExprPtr c);
 
     const ZAMStmt AssignVecElems(const Expr* e);
     const ZAMStmt AssignTableElem(const Expr* e);

src/script_opt/ZAM/Driver.cc

@@ -24,12 +24,17 @@ ZAMCompiler::ZAMCompiler(ScriptFuncPtr f, std::shared_ptr<ProfileFuncs> _pfs, st
     reducer = std::move(_rd);
     frame_sizeI = 0;
 
+    auto loc = body->GetLocationInfo();
+    ASSERT(loc->first_line != 0 || body->Tag() == STMT_NULL);
+    auto loc_copy =
+        std::make_shared<Location>(loc->filename, loc->first_line, loc->last_line, loc->first_column, loc->last_column);
+    ZAM::curr_func = func->Name();
+    ZAM::curr_loc = std::make_shared<ZAMLocInfo>(ZAM::curr_func, std::move(loc_copy), nullptr);
+
     Init();
 }
 
 ZAMCompiler::~ZAMCompiler() {
-    curr_stmt = nullptr;
-
     for ( auto i : insts1 )
         delete i;
 }
@@ -117,8 +122,6 @@ void ZAMCompiler::TrackMemoryManagement() {
 }
 
 StmtPtr ZAMCompiler::CompileBody() {
-    curr_stmt = nullptr;
-
     if ( func->Flavor() == FUNC_FLAVOR_HOOK )
         PushBreaks();
 
@@ -193,12 +196,17 @@ StmtPtr ZAMCompiler::CompileBody() {
 
     ConcretizeSwitches();
 
+    std::string fname = func->Name();
+
+    if ( func->Flavor() == FUNC_FLAVOR_FUNCTION )
+        fname = func_name_at_loc(fname, body->GetLocationInfo());
+
+    auto zb = make_intrusive<ZBody>(fname, this);
+    zb->SetInsts(insts2);
+
     // Could erase insts1 here to recover memory, but it's handy
     // for debugging.
 
-    auto zb = make_intrusive<ZBody>(func->Name(), this);
-    zb->SetInsts(insts2);
-
     return zb;
 }
 
@@ -388,7 +396,7 @@ void ZAMCompiler::Dump() {
 
         printf("%d %s%s: ", i, liveness.c_str(), depth.c_str());
 
-        inst->Dump(&frame_denizens, remappings);
+        inst->Dump(stdout, &frame_denizens, remappings);
     }
 
     if ( ! insts2.empty() )
@@ -396,8 +404,9 @@ void ZAMCompiler::Dump() {
 
     for ( auto i = 0U; i < insts2.size(); ++i ) {
         auto& inst = insts2[i];
+        // printf("%s:%d\n", inst->loc->filename, inst->loc->first_line);
         printf("%d: ", i);
-        inst->Dump(&frame_denizens, remappings);
+        inst->Dump(stdout, &frame_denizens, remappings);
     }
 
     DumpCases(int_cases, "int");
@@ -445,7 +454,7 @@ void ZAMCompiler::DumpInsts1(const FrameReMap* remappings) {
 
         printf("%d %s%s: ", i, liveness.c_str(), depth.c_str());
 
-        inst->Dump(&frame_denizens, remappings);
+        inst->Dump(stdout, &frame_denizens, remappings);
     }
 }
 

src/script_opt/ZAM/Expr.cc

@@ -315,6 +315,7 @@ const ZAMStmt ZAMCompiler::CompileSchedule(const NameExpr* n, const ConstExpr* c
     if ( len == 0 ) {
         z = n ? ZInstI(OP_SCHEDULE0_ViH, FrameSlot(n), is_interval) : ZInstI(OP_SCHEDULE0_CiH, is_interval, c);
         z.op_type = n ? OP_VV_I2 : OP_VC_I1;
+        z.aux = new ZInstAux(0);
     }
 
     else {
@@ -330,7 +331,7 @@ const ZAMStmt ZAMCompiler::CompileSchedule(const NameExpr* n, const ConstExpr* c
         z.aux = InternalBuildVals(l);
     }
 
-    z.event_handler = h;
+    z.aux->event_handler = h;
 
     return AddInst(z);
 }
@@ -349,12 +350,11 @@ const ZAMStmt ZAMCompiler::CompileEvent(EventHandler* h, const ListExpr* l) {
     if ( n > 4 || ! all_vars ) { // do generic form
         ZInstI z(OP_EVENT_HL);
         z.aux = InternalBuildVals(l);
-        z.event_handler = h;
+        z.aux->event_handler = h;
         return AddInst(z);
     }
 
     ZInstI z;
-    z.event_handler = h;
 
     if ( n == 0 ) {
         z.op = OP_EVENT0_X;
@@ -403,6 +403,11 @@ const ZAMStmt ZAMCompiler::CompileEvent(EventHandler* h, const ListExpr* l) {
         }
     }
 
+    if ( ! z.aux )
+        z.aux = new ZInstAux(0);
+
+    z.aux->event_handler = h;
+
     return AddInst(z);
 }
 
@@ -872,11 +877,8 @@ const ZAMStmt ZAMCompiler::AssignTableElem(const Expr* e) {
 const ZAMStmt ZAMCompiler::Call(const ExprStmt* e) {
     auto c = cast_intrusive<CallExpr>(e->StmtExprPtr());
 
-    if ( IsZAM_BuiltIn(c.get()) ) {
-        auto ret = LastInst();
-        insts1.back()->call_expr = std::move(c);
-        return ret;
-    }
+    if ( CheckForBuiltIn(c, c) )
+        return LastInst();
 
     return DoCall(e->StmtExpr()->AsCallExpr(), nullptr);
 }
@@ -885,26 +887,37 @@ const ZAMStmt ZAMCompiler::AssignToCall(const ExprStmt* e) {
     auto assign = e->StmtExpr()->AsAssignExpr();
     auto call = cast_intrusive<CallExpr>(assign->GetOp2());
 
-    if ( IsZAM_BuiltIn(e->StmtExpr()) ) {
-        auto ret = LastInst();
-        insts1.back()->call_expr = call;
-        return ret;
-    }
+    if ( CheckForBuiltIn(e->StmtExprPtr(), call) )
+        return LastInst();
 
     auto n = assign->GetOp1()->AsRefExpr()->GetOp1()->AsNameExpr();
 
     return DoCall(call.get(), n);
 }
 
+bool ZAMCompiler::CheckForBuiltIn(const ExprPtr& e, CallExprPtr c) {
+    if ( ! IsZAM_BuiltIn(e.get()) )
+        return false;
+
+    auto ret = LastInst();
+    auto& i = insts1.back();
+    if ( ! i->aux )
+        i->aux = new ZInstAux(0);
+    i->aux->call_expr = c;
+
+    return true;
+}
+
 const ZAMStmt ZAMCompiler::DoCall(const CallExpr* c, const NameExpr* n) {
     auto func = c->Func()->AsNameExpr();
     auto func_id = func->IdPtr();
+    auto func_val = func_id->GetVal();
     auto& args = c->Args()->Exprs();
 
     int nargs = args.length();
     int call_case = nargs;
 
-    bool indirect = ! func_id->IsGlobal() || ! func_id->GetVal();
+    bool indirect = ! func_id->IsGlobal() || ! func_val;
     bool in_when = c->IsInWhen();
 
     if ( indirect || in_when )
@@ -1041,7 +1054,7 @@ const ZAMStmt ZAMCompiler::DoCall(const CallExpr* c, const NameExpr* n) {
             z.aux->can_change_non_locals = true;
     }
 
-    z.call_expr = {NewRef{}, const_cast<CallExpr*>(c)};
+    z.aux->call_expr = {NewRef{}, const_cast<CallExpr*>(c)};
 
     if ( in_when )
         z.SetType(n->GetType());
@@ -1049,8 +1062,11 @@ const ZAMStmt ZAMCompiler::DoCall(const CallExpr* c, const NameExpr* n) {
     if ( ! indirect || func_id->IsGlobal() ) {
         z.aux->id_val = func_id;
 
-        if ( ! indirect )
-            z.func = func_id->GetVal()->AsFunc();
+        if ( ! indirect ) {
+            z.aux->func = func_id->GetVal()->AsFunc();
+            if ( z.aux->func->GetKind() == Func::BUILTIN_FUNC )
+                z.aux->is_BiF_call = true;
+        }
     }
 
     return AddInst(z);
@@ -1064,11 +1080,11 @@ const ZAMStmt ZAMCompiler::ConstructTable(const NameExpr* n, const Expr* e) {
     auto z = GenInst(OP_CONSTRUCT_TABLE_VV, n, width);
     z.aux = InternalBuildVals(con, width + 1);
     z.t = tt;
-    z.attrs = e->AsTableConstructorExpr()->GetAttrs();
+    z.aux->attrs = e->AsTableConstructorExpr()->GetAttrs();
 
     auto zstmt = AddInst(z);
 
-    auto def_attr = z.attrs ? z.attrs->Find(ATTR_DEFAULT) : nullptr;
+    auto def_attr = z.aux->attrs ? z.aux->attrs->Find(ATTR_DEFAULT) : nullptr;
     if ( ! def_attr || def_attr->GetExpr()->Tag() != EXPR_LAMBDA )
         return zstmt;
 
@@ -1102,7 +1118,7 @@ const ZAMStmt ZAMCompiler::ConstructSet(const NameExpr* n, const Expr* e) {
     auto z = GenInst(OP_CONSTRUCT_SET_VV, n, width);
     z.aux = InternalBuildVals(con, width);
     z.t = e->GetType();
-    z.attrs = e->AsSetConstructorExpr()->GetAttrs();
+    z.aux->attrs = e->AsSetConstructorExpr()->GetAttrs();
 
     return AddInst(z);
 }

src/script_opt/ZAM/IterInfo.h

@@ -18,7 +18,7 @@ public:
     // No constructor needed, as all of our member variables are
     // instead instantiated via BeginLoop().  This allows us to
     // reuse TableIterInfo objects to lower the overhead associated
-    // with executing ZBody::DoExec for non-recursive functions.
+    // with executing ZBody::Exec for non-recursive functions.
 
     // We do, however, want to make sure that when we go out of scope,
     // if we have any pending iterators we clear them.

src/script_opt/ZAM/Ops.in

@@ -273,7 +273,7 @@ macro AssignV1T(v, t) {
 # the instruction.
 macro AssignV1(v) AssignV1T(v, z.t)
 
-macro BRANCH(target_slot) { pc = z.target_slot; continue; }
+macro BRANCH(target_slot) { DO_ZAM_PROFILE; pc = z.target_slot; continue; }
 
 ########## Unary Ops ##########
 
@@ -1153,7 +1153,7 @@ direct-unary-op Table-Constructor ConstructTable
 
 macro ConstructTableOrSetPre()
 	auto tt = cast_intrusive<TableType>(z.t);
-	auto new_t = new TableVal(tt, z.attrs);
+	auto new_t = new TableVal(tt, z.aux->attrs);
 	auto aux = z.aux;
 	auto n = aux->n;
 	auto ind_width = z.v2;
@@ -1389,7 +1389,7 @@ eval	if ( frame[z.v2].vector_val->Size() > 0 )
 unary-expr-op To-Any-Coerce
 op-type X
 set-type $1
-eval	AssignV1(ZVal(frame[z.v2].ToVal(z.t), any_base_type))
+eval	AssignV1(ZVal(frame[z.v2].ToVal(z.t), ZAM::any_base_type))
 
 unary-expr-op From-Any-Coerce
 op-type X
@@ -1654,7 +1654,7 @@ macro WhenCall(func)
 		throw ZAMDelayedCallException();
 	auto& lhs = frame[z.v1];
 	auto trigger = f->GetTrigger();
-	Val* v = trigger ? trigger->Lookup(z.call_expr.get()) : nullptr;
+	Val* v = trigger ? trigger->Lookup(z.aux->call_expr.get()) : nullptr;
 	ValPtr vp;
 	if ( v )
 		vp = {NewRef{}, v};
@@ -1666,7 +1666,7 @@ macro WhenCall(func)
 		std::vector<ValPtr> args;
 		for ( auto i = 0; i < n; ++i )
 			args.push_back(aux->ToVal(frame, i));
-		f->SetCall(z.call_expr.get());
+		f->SetCall(z.aux->call_expr.get());
 		/* It's possible that this function will call another that
 		 * itself returns null because *it* is the actual blocker.
 		 * That will set ZAM_error, which we need to ignore.
@@ -1685,7 +1685,7 @@ macro WhenCall(func)
 internal-op WhenCallN
 type V
 side-effects
-eval	WhenCall(z.func)
+eval	WhenCall(z.aux->func)
 
 internal-op WhenIndCallN
 type VV
@@ -1703,7 +1703,7 @@ macro EvalScheduleArgs(time, is_delta, build_args)
 	double dt = time.double_val;
 	if ( is_delta )
 		dt += run_state::network_time;
-	auto handler = EventHandlerPtr(z.event_handler);
+	auto handler = EventHandlerPtr(z.aux->event_handler);
 	ValVec args;
 	build_args
 	auto timer = new ScheduleTimer(handler, std::move(args), dt);
@@ -1744,19 +1744,19 @@ op1-read
 custom-method return CompileEvent(h, l);
 eval	ValVec args;
 	z.aux->FillValVec(args, frame);
-	QueueEvent(z.event_handler, args);
+	QueueEvent(z.aux->event_handler, args);
 
 internal-op Event0
 type X
 eval	ValVec args(0);
-	QueueEvent(z.event_handler, args);
+	QueueEvent(z.aux->event_handler, args);
 
 internal-op Event1
 type V
 op1-read
 eval	ValVec args(1);
 	args[0] = frame[z.v1].ToVal(z.t);
-	QueueEvent(z.event_handler, args);
+	QueueEvent(z.aux->event_handler, args);
 
 internal-op Event2
 type VV
@@ -1764,7 +1764,7 @@ op1-read
 eval	ValVec args(2);
 	args[0] = frame[z.v1].ToVal(z.t);
 	args[1] = frame[z.v2].ToVal(z.t2);
-	QueueEvent(z.event_handler, args);
+	QueueEvent(z.aux->event_handler, args);
 
 internal-op Event3
 type VVV
@@ -1774,7 +1774,7 @@ eval	ValVec args(3);
 	args[0] = frame[z.v1].ToVal(z.t);
 	args[1] = frame[z.v2].ToVal(z.t2);
 	args[2] = frame[z.v3].ToVal(aux->elems[2].GetType());
-	QueueEvent(z.event_handler, args);
+	QueueEvent(z.aux->event_handler, args);
 
 internal-op Event4
 type VVVV
@@ -1785,7 +1785,7 @@ eval	ValVec args(4);
 	args[1] = frame[z.v2].ToVal(z.t2);
 	args[2] = frame[z.v3].ToVal(aux->elems[2].GetType());
 	args[3] = frame[z.v4].ToVal(aux->elems[3].GetType());
-	QueueEvent(z.event_handler, args);
+	QueueEvent(z.aux->event_handler, args);
 
 
 op Return
@@ -1795,6 +1795,7 @@ eval	EvalReturn(nullptr,)
 macro EvalReturn(val, type)
 	ret_u = val;
 	type
+	DO_ZAM_PROFILE
 	pc = end_pc;
 	continue;
 
@@ -1819,6 +1820,7 @@ macro EvalSwitchBody(cases, postscript)
 	else
 		pc = t[v];
 	postscript
+	DO_ZAM_PROFILE
 	continue;
 	}
 
@@ -2130,7 +2132,7 @@ eval	auto vt = cast_intrusive<VectorType>(z.t);
 internal-op Init-Table
 type V
 eval	auto tt = cast_intrusive<TableType>(z.t);
-	auto t = new TableVal(tt, z.attrs);
+	auto t = new TableVal(tt, z.aux->attrs);
 	Unref(frame[z.v1].table_val);
 	frame[z.v1].table_val = t;
 
@@ -2162,7 +2164,7 @@ macro BuildWhen(timeout)
 		if ( v )
 			local_aggrs.push_back(v);
 		}
-	(void)make_intrusive<trigger::Trigger>(wi, wi->WhenExprGlobals(), local_aggrs, timeout, f, z.loc.get());
+	(void)make_intrusive<trigger::Trigger>(wi, wi->WhenExprGlobals(), local_aggrs, timeout, f, z.loc->Loc());
 
 ########################################
 # Internal
@@ -2263,6 +2265,7 @@ internal-op Hook-Break
 type X
 eval	flow = FLOW_BREAK;
 	pc = end_pc;
+	DO_ZAM_PROFILE
 	continue;
 
 # Slot 2 gives frame size.
@@ -2373,7 +2376,7 @@ macro LogWriteNoResPost()
 internal-op Log-Write
 side-effects OP_LOG_WRITE_VV OP_VV
 type VVV
-eval	LogWritePre(frame[z.v2].ToVal(log_ID_enum_type), v3)
+eval	LogWritePre(frame[z.v2].ToVal(ZAM::log_ID_enum_type), v3)
 	LogWriteResPost()
 
 internal-op Log-WriteC
@@ -2387,7 +2390,7 @@ internal-op Log-Write
 side-effects
 op1-read
 type VV
-eval	LogWritePre(frame[z.v1].ToVal(log_ID_enum_type), v2)
+eval	LogWritePre(frame[z.v1].ToVal(ZAM::log_ID_enum_type), v2)
 	LogWriteNoResPost()
 
 internal-op Log-WriteC

src/script_opt/ZAM/Profile.cc

@@ -0,0 +1,55 @@
+// See the file "COPYING" in the main distribution directory for copyright.
+
+#include "zeek/script_opt/ZAM/Profile.h"
+
+#include <unordered_map>
+#include <unordered_set>
+
+#include "zeek/Obj.h"
+#include "zeek/script_opt/ProfileFunc.h"
+#include "zeek/script_opt/ZAM/ZBody.h"
+
+namespace zeek::detail {
+
+ZAMLocInfo::ZAMLocInfo(std::string _func_name, std::shared_ptr<Location> _loc, std::shared_ptr<ZAMLocInfo> _parent)
+    : loc(std::move(_loc)), parent(std::move(_parent)) {
+    func_name = func_name_at_loc(_func_name, loc.get());
+
+    auto main_module = func_name.find("::");
+    if ( main_module != std::string::npos )
+        modules.insert(func_name.substr(0, main_module));
+
+    if ( parent ) {
+        auto& m = parent->GetModules();
+        modules.insert(m.begin(), m.end());
+    }
+}
+
+std::string ZAMLocInfo::Describe(bool include_lines) const {
+    std::string desc;
+
+    if ( AST_blocks ) {
+        desc = AST_blocks->GetDesc(loc.get());
+        if ( parent )
+            desc = parent->Describe(false) + ";" + desc;
+    }
+    else {
+        if ( parent ) {
+            desc = parent->Describe(false);
+            if ( func_name != parent->FuncName() )
+                desc += ";" + func_name;
+        }
+        else
+            desc = func_name;
+
+        if ( include_lines ) {
+            desc += ";" + func_name + ":" + std::to_string(loc->first_line);
+            if ( loc->last_line > loc->first_line )
+                desc += "-" + std::to_string(loc->last_line);
+        }
+    }
+
+    return desc;
+}
+
+} // namespace zeek::detail

src/script_opt/ZAM/Profile.h

@@ -0,0 +1,42 @@
+// See the file "COPYING" in the main distribution directory for copyright.
+
+// Classes for profiling ZAM execution.
+
+#pragma once
+
+#include "zeek/script_opt/ProfileFunc.h"
+#include "zeek/util.h"
+
+namespace zeek::detail {
+
+class ZAMLocInfo {
+public:
+    // A generalization of the notion of "Location" that includes associating
+    // with the location a function name, a static parent (i.e., one we can
+    // determine at compile time, reflecting an outer block or inlining), and
+    // a group of modules. It's a group of modules rather than a single one
+    // because of event handler coalescence.
+    ZAMLocInfo(std::string _func_name, std::shared_ptr<Location> _loc, std::shared_ptr<ZAMLocInfo> _parent);
+
+    const std::string& FuncName() const { return func_name; }
+    const Location* Loc() const { return loc.get(); }
+    std::shared_ptr<Location> LocPtr() const { return loc; }
+    std::shared_ptr<ZAMLocInfo> Parent() { return parent; }
+    const auto& GetModules() const { return modules; }
+
+    // If include_lines is true, then in the description we include line
+    // number information, otherwise we omit them.
+    std::string Describe(bool include_lines) const;
+
+private:
+    std::string func_name;
+    std::set<std::string> modules;
+    std::shared_ptr<Location> loc;
+    std::shared_ptr<ZAMLocInfo> parent;
+};
+
+// Reports a profile of the different ZAM operations (instructions)
+// that executed.
+extern void report_ZOP_profile();
+
+} // namespace zeek::detail

src/script_opt/ZAM/README.md

@@ -7,12 +7,14 @@ ZAM Optimization: User's Guide
 [_Overview_](#overview) -
 [_Known Issues_](#known-issues) -
 [_Optimization Options_](#script-optimization-options) -
+[_ZAM Profiling_](#ZAM-profiling) -
 
 </h4>
 
 
 <br>
 
+<a name="overview"></a>
 ## Overview
 
 Zeek's _ZAM optimization_ is an experimental feature that changes the
@@ -22,8 +24,9 @@ that are then executed by recursively interpreting each node in a given
 tree.  With script optimization, Zeek compiles the trees into a low-level
 form that can generally be executed more efficiently.
 
-You specify use of this feature by including `-O ZAM` on the command
-line.  (Note that this option takes a few seconds to generate the ZAM code, unless you're using `-b` _bare mode_.)
+You specify use of this feature by including `-O ZAM` on the command line.
+(Note that this option takes a few seconds to generate the ZAM code, unless
+you're using `-b` _bare mode_.)
 
 How much faster will your scripts run?  There's no simple answer to that.
 It depends heavily on several factors:
@@ -43,6 +46,7 @@ rather than something a lot more dramatic.
 
 <br>
 
+<a name="known-issues"></a>
 ## Known Issues
 
 
@@ -54,9 +58,6 @@ of script interpretation).
 
 ### Deficiencies:
 
-* Run-time error messages in compiled scripts have diminished identifying
-information.
-
 * The optimizer assumes you have ensured initialization of your variables.
 If your script uses a variable that hasn't been set, the compiled code may
 crash or behave aberrantly. You can use the `-u` command-line flag to find such potential usage issues.
@@ -76,6 +77,7 @@ different.
 
 <br>
 
+<a name="script-optimization-options"></a>
 ## Script Optimization Options
 
 Users will generally simply use `-O ZAM` to invoke the script optimizer.
@@ -88,16 +90,119 @@ issues:
 |`dump-uds`	|	Dump use-defs to _stdout_.|
 |`dump-xform`	|	Dump transformed scripts to _stdout_.|
 |`dump-ZAM`	|	Dump generated ZAM code to _stdout_.|
+|`gen-ZAM-code`		|	Generate ZAM without additional optimizations.|
 |`help`		|	Print this list.|
 |`inline`		|	Inline function calls.|
+|`no-inline`		|	Suppress inlining even if another option implies it.|
 |`no-ZAM-opt`	|	Turn off low-level ZAM optimization.|
 |`optimize-all`	|	Optimize all scripts, even inlined ones. You need to separately specify which optimizations you want to apply, e.g., `-O inline -O xform`.|
 |`optimize-AST`	|	Optimize the (transform) AST; implies `xform`.|
-|`profile-ZAM`	|	Generate to _stdout_ a ZAM execution profile. (Requires configuring with `--enable-debug`.)|
+|`profile-ZAM`	|	Generate to "zprof.out" a ZAM execution profile. (Requires configuring with `--enable-ZAM-profiling` or `--enable-debug`.)|
 |`report-recursive`	|	Report on recursive functions and exit.|
 |`report-uncompilable`	|	Report on uncompilable functions and exit. For ZAM, all functions should be compilable.|
 |`xform`		|	Transform scripts to "reduced" form.|
 
+<a name="ZAM-profiling"></a>
+## ZAM Profiling
+
+ZAM supports detailed script execution profiling, activated using `-O
+profile-ZAM`. (This option implies `-O ZAM` unless you've already specified
+some ZAM optimization options.) Profiles are written to `zprof.out`. These
+profiles have a number of components, and are intended to be subsetted
+(such as by using `grep`) and then further processed, such as by using
+`sort` to pick out instances with large values.
+
+When profiling, ZAM gathers for each function body its total number of
+calls, total CPU time (including time spent in any script functions or
+BiFs it calls), an estimate of total memory allocations, and the number
+of sampled ZAM instructions (see below). Memory impact is done by comparing
+Zeek's total memory usage when a function body starts with its total usage
+when the body finishes. Any increase is charged against the function body;
+decreases however are not (because it's not as clear whether they are
+meaningful). This approach only approximates actual memory usage because
+often allocations can be met by memory currently available at user level,
+not requiring any kernel allocations; and if they _do_ require kernel
+allocations, those can be significantly larger than the immediate need.
+That said, experience finds that the resulting values (reported in bytes)
+do generally reflect the execution's state-holding impact.
+
+Often the report will state that a function body "did not execute" when
+in fact you're sure it did. This arises due to ZAM's heavy use of _inlining_:
+while the code of the function body did indeed execute, it did so only in
+the context of _other_ function bodies, and that's where the CPU & memory
+impact are charged. (You can suppress this by using `-O no-inline` to turn
+off ZAM's inlining, although with a significant performance impact.)
+
+In addition to per-function profiling, ZAM also profiles individual ZAM
+instructions. Because fine-grained profiling of every instruction execution
+imposes a significant performance penalty,
+ZAM does instruction-level profiling using _sampling_.  The default sampling
+rate is 1-in-100. (You can control it via the `ZEEK_ZAM_PROF_SAMPLING_RATE`
+environment variable, and setting that variable to `1` effectively turns
+off sampling). More frequent sampling rates slow down execution further but
+provide more accurate information. With the default rate, the slowdown is
+about 2x, so not something to use in production in its present form.
+
+At the top of `zprof.out`, ZAM reports the sampling rate and also its
+estimate of the cost to profiling a single ZAM instruction, and of assessing
+memory impact. When reporting CPU times, ZAM subtracts off these costs.
+(If the resulting value is negative, it's rounded up to 0.) Reported CPU
+times do _not_ factor in the sampling rate, so for example if you want to
+estimate the full impact of executing an instruction, when using the default
+sampling rate you would multiple the reported value by 100.
+
+For each profiled instruction, ZAM associates a _call tree_ reflecting
+each function body and "statement block" leading up to the specific point
+in the scripts for which the instruction executes. The call tree appears
+after a `//` delimiter, such as this:
+
+`
+Config::config_option_changed 4 2 0.000009 load-val-VV-S 2 (Config::location), interpreter frame[2] // Site::zeek_init;Site::zeek_init:315-336;Site::zeek_init:326-329;Site::zeek_init:329;Site::update_private_address_space;Site::update_private_address_space:283-312;Site::update_private_address_space:310;Config::config_option_changed;Config::config_option_changed:142-151
+`
+
+This line is reporting a single ZAM `load-val-VV-S` instruction corresponding
+to the `Config::config_option_changed` function body. The value of `4`
+reflects the position of this instruction in the fully compiled body (the
+instruction right above it will be numbered `3`). The `2` and `0.000009`
+indicate that the instruction's execution was sampled two times, for a
+total of 9 microseconds of CPU time. The text after `load-val-VV-S` up
+through the `//` delimiter give some particulars of the instruction's
+operands. What follows is then an accounting for the scripting leading to
+the instruction's execution: it's coming from a `zeek_init` handler,
+including a number of statement blocks (such as lines `315-336`), with the
+final `zeek_init` statement being line `329`. At that point,
+`Site::update_private_address_space` was called, and it in turn called
+`Config::config_option_changed`. (The `Config::config_option_change` call
+was not inlined; if it had been, then the label in the first column would
+have been either `zeek_init` or `Site::update_private_address_space`.)
+
+A key point about the format used here is that it's the same as used by
+`flamegraph.pl` to generate _Flame Graphs_. Thus, you can generate a flame
+graph of ZAM-compiled script execution using the following:
+
+`
+grep // zprof.out | awk '{ printf "%s %d\n", $NF, $4 * 1e8 }' | flamegraph.pl >my-flame-graph.svg
+`
+
+Here the `awk` invocation is printing out the call tree (`$NF`) followed
+by the sampled CPU time multiplied by 100,000,000 to convert it to
+microseconds and to expand it by the default sampling rate of 100.
+
+The profile also computes per-module sampling statistics, which you can
+examine using `grep ^module zprof.out`. These include lines like:
+
+`
+module Weird sampled CPU time 0.095283, 157523 sampled instructions
+`
+
+This summary is derived from all sampled instructions whose call tree
+included some function from the `Weird` module.  As usual, you would
+multiply the sampled values by the sampling rate to get the full estimated
+values.
+
+Finally, note that using ZAM profiling with its default sampling rate slows
+down execution by 30-50%.
+
 <br>
 <br>
 

src/script_opt/ZAM/Stmt.cc

@@ -10,8 +10,13 @@
 namespace zeek::detail {
 
 const ZAMStmt ZAMCompiler::CompileStmt(const Stmt* s) {
-    curr_stmt = const_cast<Stmt*>(s)->ThisPtr();
-    ASSERT(curr_stmt->Tag() == STMT_NULL || curr_stmt->GetLocationInfo()->first_line != 0);
+    auto loc = s->GetLocationInfo();
+    ASSERT(loc->first_line != 0 || s->Tag() == STMT_NULL);
+    auto loc_copy =
+        std::make_shared<Location>(loc->filename, loc->first_line, loc->last_line, loc->first_column, loc->last_column);
+    ASSERT(! AST_blocks || s->Tag() == STMT_NULL || AST_blocks->HaveExpDesc(loc_copy.get()));
+    auto loc_parent = ZAM::curr_loc->Parent();
+    ZAM::curr_loc = std::make_shared<ZAMLocInfo>(ZAM::curr_func, std::move(loc_copy), ZAM::curr_loc->Parent());
 
     switch ( s->Tag() ) {
         case STMT_PRINT: return CompilePrint(static_cast<const PrintStmt*>(s));
@@ -902,6 +907,16 @@ const ZAMStmt ZAMCompiler::CompileReturn(const ReturnStmt* r) {
 const ZAMStmt ZAMCompiler::CompileCatchReturn(const CatchReturnStmt* cr) {
     retvars.push_back(cr->RetVar());
 
+    auto hold_func = ZAM::curr_func;
+    auto hold_loc = ZAM::curr_loc;
+
+    ZAM::curr_func = cr->Func()->Name();
+
+    bool is_event_inline = (hold_func == ZAM::curr_func);
+
+    if ( ! is_event_inline )
+        ZAM::curr_loc = std::make_shared<ZAMLocInfo>(ZAM::curr_func, ZAM::curr_loc->LocPtr(), hold_loc);
+
     PushCatchReturns();
 
     auto block = cr->Block();
@@ -910,6 +925,14 @@ const ZAMStmt ZAMCompiler::CompileCatchReturn(const CatchReturnStmt* cr) {
 
     ResolveCatchReturns(GoToTargetBeyond(block_end));
 
+    if ( ! is_event_inline ) {
+        // Strictly speaking, we could do this even if is_event_inline
+        // is true, because the values won't have changed. However, that
+        // just looks weird, so we condition this to match the above.
+        ZAM::curr_func = hold_func;
+        ZAM::curr_loc = hold_loc;
+    }
+
     return block_end;
 }
 
@@ -1008,7 +1031,8 @@ const ZAMStmt ZAMCompiler::InitVector(IDPtr id, VectorType* vt) {
 const ZAMStmt ZAMCompiler::InitTable(IDPtr id, TableType* tt, Attributes* attrs) {
     auto z = ZInstI(OP_INIT_TABLE_V, FrameSlot(id));
     z.SetType({NewRef{}, tt});
-    z.attrs = {NewRef{}, attrs};
+    z.aux = new ZInstAux(0);
+    z.aux->attrs = {NewRef{}, attrs};
     return AddInst(z);
 }
 

src/script_opt/ZAM/Support.cc

@@ -12,9 +12,13 @@
 
 namespace zeek::detail {
 
-StmtPtr curr_stmt;
+namespace ZAM {
+std::string curr_func;
+std::shared_ptr<ZAMLocInfo> curr_loc;
 TypePtr log_ID_enum_type;
 TypePtr any_base_type;
+} // namespace ZAM
+
 bool ZAM_error = false;
 
 bool is_ZAM_compilable(const ProfileFunc* pf, const char** reason) {
@@ -77,8 +81,8 @@ void ZAM_run_time_error(const char* msg) {
     ZAM_error = true;
 }
 
-void ZAM_run_time_error(std::shared_ptr<Location> loc, const char* msg) {
-    reporter->RuntimeError(loc.get(), "%s", msg);
+void ZAM_run_time_error(std::shared_ptr<ZAMLocInfo> loc, const char* msg) {
+    reporter->RuntimeError(loc->Loc(), "%s", msg);
     ZAM_error = true;
 }
 
@@ -87,14 +91,14 @@ void ZAM_run_time_error(const char* msg, const Obj* o) {
     ZAM_error = true;
 }
 
-void ZAM_run_time_error(std::shared_ptr<Location> loc, const char* msg, const Obj* o) {
-    reporter->RuntimeError(loc.get(), "%s (%s)", msg, obj_desc(o).c_str());
+void ZAM_run_time_error(std::shared_ptr<ZAMLocInfo> loc, const char* msg, const Obj* o) {
+    reporter->RuntimeError(loc->Loc(), "%s (%s)", msg, obj_desc(o).c_str());
     ZAM_error = true;
 }
 
-void ZAM_run_time_warning(std::shared_ptr<Location> loc, const char* msg) {
+void ZAM_run_time_warning(std::shared_ptr<ZAMLocInfo> loc, const char* msg) {
     ODesc d;
-    loc->Describe(&d);
+    loc->Loc()->Describe(&d);
 
     reporter->Warning("%s: %s", d.Description(), msg);
 }

src/script_opt/ZAM/Support.h

@@ -6,14 +6,29 @@
 
 #include "zeek/Expr.h"
 #include "zeek/Stmt.h"
+#include "zeek/script_opt/ZAM/Profile.h"
 
 namespace zeek::detail {
 
 using ValVec = std::vector<ValPtr>;
 
-// The (reduced) statement currently being compiled.  Used for both
-// tracking "use" and "reaching" definitions, and for error messages.
-extern StmtPtr curr_stmt;
+namespace ZAM {
+
+// The name of the current function being compiled. For inlined functions,
+// this is the name of the inlinee, not the inliner.
+extern std::string curr_func;
+
+// The location corresponding to the current statement being compiled.
+extern std::shared_ptr<ZAMLocInfo> curr_loc;
+
+// Needed for the logging built-in.  Exported so that ZAM can make sure it's
+// defined when compiling.
+extern TypePtr log_ID_enum_type;
+
+// Needed for a slight performance gain when dealing with "any" types.
+extern TypePtr any_base_type;
+
+} // namespace ZAM
 
 // True if a function with the given profile can be compiled to ZAM.
 // If not, returns the reason in *reason, if non-nil.
@@ -27,22 +42,15 @@ extern bool IsAny(const Type* t);
 inline bool IsAny(const TypePtr& t) { return IsAny(t.get()); }
 inline bool IsAny(const Expr* e) { return IsAny(e->GetType()); }
 
-// Needed for the logging built-in.  Exported so that ZAM can make sure it's
-// defined when compiling.
-extern TypePtr log_ID_enum_type;
-
-// Needed for a slight performance gain when dealing with "any" types.
-extern TypePtr any_base_type;
-
 extern void ZAM_run_time_error(const char* msg);
-extern void ZAM_run_time_error(std::shared_ptr<Location> loc, const char* msg);
-extern void ZAM_run_time_error(std::shared_ptr<Location> loc, const char* msg, const Obj* o);
+extern void ZAM_run_time_error(std::shared_ptr<ZAMLocInfo> loc, const char* msg);
+extern void ZAM_run_time_error(std::shared_ptr<ZAMLocInfo> loc, const char* msg, const Obj* o);
 extern void ZAM_run_time_error(const Stmt* stmt, const char* msg);
 extern void ZAM_run_time_error(const char* msg, const Obj* o);
 
 extern bool ZAM_error;
 
-extern void ZAM_run_time_warning(std::shared_ptr<Location> loc, const char* msg);
+extern void ZAM_run_time_warning(std::shared_ptr<ZAMLocInfo> loc, const char* msg);
 
 extern StringVal* ZAM_to_lower(const StringVal* sv);
 extern StringVal* ZAM_sub_bytes(const StringVal* s, zeek_uint_t start, zeek_int_t n);

src/script_opt/ZAM/ZBody.cc

@@ -1,5 +1,7 @@
 // See the file "COPYING" in the main distribution directory for copyright.
 
+#include "zeek/script_opt/ZAM/ZBody.h"
+
 #include "zeek/Desc.h"
 #include "zeek/EventHandler.h"
 #include "zeek/Frame.h"
@@ -28,6 +30,74 @@
 
 namespace zeek::detail {
 
+#ifdef ENABLE_ZAM_PROFILE
+
+static std::vector<const ZAMLocInfo*> caller_locs;
+
+static double compute_CPU_prof_overhead() {
+    double start = util::curr_CPU_time();
+    double CPU = 0.0;
+    const int n = 100000;
+    for ( int i = 0; i < n; ++i )
+        CPU = std::max(CPU, util::curr_CPU_time());
+
+    return 2.0 * (CPU - start) / n;
+}
+
+static double compute_mem_prof_overhead() {
+    double start = util::curr_CPU_time();
+    uint64_t m;
+    util::get_memory_usage(&m, nullptr);
+    const int n = 20000;
+    for ( int i = 0; i < n; ++i ) {
+        uint64_t m2;
+        util::get_memory_usage(&m2, nullptr);
+    }
+
+    return 2.0 * (util::curr_CPU_time() - start) / n;
+}
+
+static double CPU_prof_overhead = compute_CPU_prof_overhead();
+static double mem_prof_overhead = compute_mem_prof_overhead();
+
+#define DO_ZAM_PROFILE                                                                                                 \
+    if ( do_profile ) {                                                                                                \
+        double dt = util::curr_CPU_time() - profile_CPU;                                                               \
+        auto& prof_info = (*curr_prof_vec)[profile_pc];                                                                \
+        ++prof_info.num_samples;                                                                                       \
+        prof_info.CPU_time += dt;                                                                                      \
+        ZOP_CPU[z.op] += dt;                                                                                           \
+    }
+
+// These next two macros appear in code generated by gen-zam.
+#define ZAM_PROFILE_PRE_CALL                                                                                           \
+    if ( do_profile ) {                                                                                                \
+        caller_locs.push_back(z.loc.get());                                                                            \
+        if ( ! z.aux->is_BiF_call ) { /* For non-BiFs we don't include the callee's execution time as part of our own  \
+                                       */                                                                              \
+            DO_ZAM_PROFILE                                                                                             \
+        }                                                                                                              \
+    }
+
+#define ZAM_PROFILE_POST_CALL                                                                                          \
+    if ( do_profile ) {                                                                                                \
+        caller_locs.pop_back();                                                                                        \
+        if ( ! z.aux->is_BiF_call ) { /* We already did the profiling, move on to next instruction */                  \
+            ++pc;                                                                                                      \
+            continue;                                                                                                  \
+        }                                                                                                              \
+    }
+
+#else
+
+#define DO_ZAM_PROFILE
+#define ZAM_PROFILE_PRE_CALL
+#define ZAM_PROFILE_POST_CALL
+static double CPU_prof_overhead = 0.0;
+static double mem_prof_overhead = 0.0;
+
+#endif
+
 using std::vector;
 
 // Thrown when a call inside a "when" delays.
@@ -41,9 +111,22 @@ int ZOP_count[OP_NOP + 1];
 double ZOP_CPU[OP_NOP + 1];
 
 void report_ZOP_profile() {
+    static bool did_overhead_report = false;
+
+    if ( ! did_overhead_report ) {
+        fprintf(analysis_options.profile_file, "Profile sampled every %d instructions; all calls profiled\n",
+                analysis_options.profile_sampling_rate);
+        fprintf(analysis_options.profile_file,
+                "Profiling overhead = %.0f nsec/instruction, memory profiling overhead = %.0f nsec/call\n",
+                CPU_prof_overhead * 1e9, mem_prof_overhead * 1e9);
+        did_overhead_report = true;
+    }
+
     for ( int i = 1; i <= OP_NOP; ++i )
-        if ( ZOP_count[i] > 0 )
-            printf("%s\t%d\t%.06f\n", ZOP_name(ZOp(i)), ZOP_count[i], ZOP_CPU[i]);
+        if ( ZOP_count[i] > 0 ) {
+            auto CPU = std::max(ZOP_CPU[i] - ZOP_count[i] * CPU_prof_overhead, 0.0);
+            fprintf(analysis_options.profile_file, "%s\t%d\t%.06f\n", ZOP_name(ZOp(i)), ZOP_count[i], CPU);
+        }
 }
 
 // Sets the given element to a copy of an existing (not newly constructed)
@@ -120,8 +203,8 @@ VEC_COERCE(IU, TYPE_INT, zeek_int_t, AsCount(), count_to_int_would_overflow, "un
 VEC_COERCE(UD, TYPE_COUNT, zeek_uint_t, AsDouble(), double_to_count_would_overflow, "double to unsigned")
 VEC_COERCE(UI, TYPE_COUNT, zeek_int_t, AsInt(), int_to_count_would_overflow, "signed to unsigned")
 
-ZBody::ZBody(const char* _func_name, const ZAMCompiler* zc) : Stmt(STMT_ZAM) {
-    func_name = _func_name;
+ZBody::ZBody(std::string _func_name, const ZAMCompiler* zc) : Stmt(STMT_ZAM) {
+    func_name = std::move(_func_name);
 
     frame_denizens = zc->FrameDenizens();
     frame_size = frame_denizens.size();
@@ -157,12 +240,9 @@ ZBody::ZBody(const char* _func_name, const ZAMCompiler* zc) : Stmt(STMT_ZAM) {
     if ( ! did_init ) {
         auto log_ID_type = lookup_ID("ID", "Log");
         ASSERT(log_ID_type);
-        log_ID_enum_type = log_ID_type->GetType<EnumType>();
-
-        any_base_type = base_type(TYPE_ANY);
-
+        ZAM::log_ID_enum_type = log_ID_type->GetType<EnumType>();
+        ZAM::any_base_type = base_type(TYPE_ANY);
         ZVal::SetZValNilStatusAddr(&ZAM_error);
-
         did_init = false;
     }
 }
@@ -170,9 +250,6 @@ ZBody::ZBody(const char* _func_name, const ZAMCompiler* zc) : Stmt(STMT_ZAM) {
 ZBody::~ZBody() {
     delete[] fixed_frame;
     delete[] insts;
-    delete inst_count;
-    delete inst_CPU;
-    delete CPU_time;
 }
 
 void ZBody::SetInsts(vector<ZInst*>& _insts) {
@@ -194,12 +271,6 @@ void ZBody::SetInsts(vector<ZInstI*>& instsI) {
     for ( auto i = 0U; i < end_pc; ++i ) {
         auto& iI = *instsI[i];
         insts_copy[i] = iI;
-        if ( iI.stmt ) {
-            auto l = iI.stmt->GetLocationInfo();
-            if ( l != &no_location )
-                insts_copy[i].loc = std::make_shared<Location>(l->filename, l->first_line, l->last_line,
-                                                               l->first_column, l->last_column);
-        }
     }
 
     insts = insts_copy;
@@ -209,34 +280,22 @@ void ZBody::SetInsts(vector<ZInstI*>& instsI) {
 
 void ZBody::InitProfile() {
     if ( analysis_options.profile_ZAM ) {
-        inst_count = new vector<int>;
-        inst_CPU = new vector<double>;
-        for ( auto i = 0U; i < end_pc; ++i ) {
-            inst_count->push_back(0);
-            inst_CPU->push_back(0.0);
+        default_prof_vec = BuildProfVec();
+        curr_prof_vec = default_prof_vec.get();
+    }
 }
 
-        CPU_time = new double;
-        *CPU_time = 0.0;
-    }
+std::shared_ptr<ProfVec> ZBody::BuildProfVec() const {
+    auto pv = std::make_shared<ProfVec>();
+    pv->resize(end_pc);
+
+    for ( auto i = 0U; i < end_pc; ++i )
+        (*pv)[i] = {0, 0.0};
+
+    return pv;
 }
 
 ValPtr ZBody::Exec(Frame* f, StmtFlowType& flow) {
-#ifdef DEBUG
-    double t = analysis_options.profile_ZAM ? util::curr_CPU_time() : 0.0;
-#endif
-
-    auto val = DoExec(f, flow);
-
-#ifdef DEBUG
-    if ( analysis_options.profile_ZAM )
-        *CPU_time += util::curr_CPU_time() - t;
-#endif
-
-    return val;
-}
-
-ValPtr ZBody::DoExec(Frame* f, StmtFlowType& flow) {
     unsigned int pc = 0;
 
     // Return value, or nil if none.
@@ -245,8 +304,27 @@ ValPtr ZBody::DoExec(Frame* f, StmtFlowType& flow) {
     // Type of the return value.  If nil, then we don't have a value.
     TypePtr ret_type;
 
-#ifdef DEBUG
-    bool do_profile = analysis_options.profile_ZAM;
+#ifdef ENABLE_ZAM_PROFILE
+    static bool profiling_active = analysis_options.profile_ZAM;
+    static int sampling_rate = analysis_options.profile_sampling_rate;
+
+    double start_CPU_time = 0.0;
+    uint64_t start_mem = 0;
+
+    if ( profiling_active ) {
+        ++ncall;
+        start_CPU_time = util::curr_CPU_time();
+        util::get_memory_usage(&start_mem, nullptr);
+
+        if ( caller_locs.empty() )
+            curr_prof_vec = default_prof_vec.get();
+        else {
+            auto pv = prof_vecs.find(caller_locs);
+            if ( pv == prof_vecs.end() )
+                pv = prof_vecs.insert({caller_locs, BuildProfVec()}).first;
+            curr_prof_vec = pv->second.get();
+        }
+    }
 #endif
 
     ZVal* frame;
@@ -276,17 +354,24 @@ ValPtr ZBody::DoExec(Frame* f, StmtFlowType& flow) {
     while ( pc < end_pc && ! ZAM_error ) {
         auto& z = insts[pc];
 
-#ifdef DEBUG
+#ifdef ENABLE_ZAM_PROFILE
+        bool do_profile = false;
         int profile_pc = 0;
         double profile_CPU = 0.0;
 
+        if ( profiling_active ) {
+            static auto seed = util::detail::random_number();
+            seed = util::detail::prng(seed);
+            do_profile = seed % sampling_rate == 0;
+
             if ( do_profile ) {
                 ++ZOP_count[z.op];
-            ++(*inst_count)[pc];
+                ++ninst;
 
                 profile_pc = pc;
                 profile_CPU = util::curr_CPU_time();
             }
+        }
 #endif
 
         switch ( z.op ) {
@@ -302,13 +387,7 @@ ValPtr ZBody::DoExec(Frame* f, StmtFlowType& flow) {
             default: reporter->InternalError("bad ZAM opcode");
         }
 
-#ifdef DEBUG
-        if ( do_profile ) {
-            double dt = util::curr_CPU_time() - profile_CPU;
-            inst_CPU->at(profile_pc) += dt;
-            ZOP_CPU[z.op] += dt;
-        }
-#endif
+        DO_ZAM_PROFILE
 
         ++pc;
     }
@@ -340,30 +419,86 @@ ValPtr ZBody::DoExec(Frame* f, StmtFlowType& flow) {
         delete[] frame;
     }
 
+#ifdef ENABLE_ZAM_PROFILE
+    if ( profiling_active ) {
+        tot_CPU_time += util::curr_CPU_time() - start_CPU_time;
+        uint64_t final_mem;
+        util::get_memory_usage(&final_mem, nullptr);
+        if ( final_mem > start_mem )
+            tot_mem += final_mem - start_mem;
+    }
+#endif
+
     return result;
 }
 
-void ZBody::ProfileExecution() const {
-    if ( inst_count->empty() ) {
-        printf("%s has an empty body\n", func_name);
+void ZBody::ReportExecutionProfile(ProfMap& pm) {
+    static bool did_overhead_report = false;
+
+    if ( end_pc == 0 ) {
+        fprintf(analysis_options.profile_file, "%s has an empty body\n", func_name.c_str());
         return;
     }
 
-    if ( (*inst_count)[0] == 0 ) {
-        printf("%s did not execute\n", func_name);
+    auto& dpv = *default_prof_vec;
+
+    if ( dpv[0].num_samples == 0 && prof_vecs.empty() ) {
+        fprintf(analysis_options.profile_file, "%s did not execute\n", func_name.c_str());
         return;
     }
 
-    printf("%s CPU time: %.06f\n", func_name, *CPU_time);
+    int total_samples = ncall + ninst;
+    double adj_CPU_time = tot_CPU_time;
+    adj_CPU_time -= ncall * (mem_prof_overhead + CPU_prof_overhead);
+    adj_CPU_time -= ninst * CPU_prof_overhead;
+    adj_CPU_time = std::max(adj_CPU_time, 0.0);
 
-    for ( auto i = 0U; i < inst_count->size(); ++i ) {
-        printf("%s %d %d %.06f ", func_name, i, (*inst_count)[i], (*inst_CPU)[i]);
-        insts[i].Dump(i, &frame_denizens);
+    fprintf(analysis_options.profile_file, "%s CPU time %.06f, %" PRIu64 " memory, %d calls, %d sampled instructions\n",
+            func_name.c_str(), adj_CPU_time, tot_mem, ncall, ninst);
+
+    if ( dpv[0].num_samples != 0 )
+        ReportProfile(pm, dpv, "", {});
+
+    for ( auto& pv : prof_vecs ) {
+        std::string prefix;
+        std::set<std::string> modules;
+        for ( auto& caller : pv.first ) {
+            prefix += caller->Describe(true) + ";";
+            auto& m = caller->GetModules();
+            modules.insert(m.begin(), m.end());
+        }
+
+        ReportProfile(pm, *pv.second, prefix, std::move(modules));
+    }
+}
+
+void ZBody::ReportProfile(ProfMap& pm, const ProfVec& pv, const std::string& prefix,
+                          std::set<std::string> caller_modules) const {
+    for ( auto i = 0U; i < pv.size(); ++i ) {
+        auto ninst = pv[i].num_samples;
+        auto CPU = pv[i].CPU_time;
+        CPU = std::max(CPU - ninst * CPU_prof_overhead, 0.0);
+        fprintf(analysis_options.profile_file, "%s %d %" PRId64 " %.06f ", func_name.c_str(), i, ninst, CPU);
+        insts[i].Dump(analysis_options.profile_file, i, &frame_denizens, prefix);
+
+        auto modules = caller_modules;
+        auto& m = insts[i].loc->GetModules();
+        modules.insert(m.begin(), m.end());
+
+        for ( auto& m : modules ) {
+            auto mod_prof = pm.find(m);
+            if ( mod_prof == pm.end() )
+                pm[m] = {ninst, CPU};
+            else {
+                mod_prof->second.num_samples += ninst;
+                mod_prof->second.CPU_time += CPU;
+            }
+        }
     }
 }
 
 bool ZBody::CheckAnyType(const TypePtr& any_type, const TypePtr& expected_type,
-                         const std::shared_ptr<Location>& loc) const {
+                         const std::shared_ptr<ZAMLocInfo>& loc) const {
     if ( IsAny(expected_type) )
         return true;
 
@@ -382,7 +517,7 @@ bool ZBody::CheckAnyType(const TypePtr& any_type, const TypePtr& expected_type,
         char buf[8192];
         snprintf(buf, sizeof buf, "run-time type clash (%s/%s)", type_name(at), type_name(et));
 
-        reporter->RuntimeError(loc.get(), "%s", buf);
+        reporter->RuntimeError(loc->Loc(), "%s", buf);
         return false;
     }
 
@@ -411,13 +546,13 @@ void ZBody::Dump() const {
     for ( unsigned i = 0; i < end_pc; ++i ) {
         auto& inst = insts[i];
         printf("%d: ", i);
-        inst.Dump(i, &frame_denizens);
+        inst.Dump(stdout, i, &frame_denizens, "");
     }
 }
 
 void ZBody::StmtDescribe(ODesc* d) const {
     d->AddSP("ZAM-code");
-    d->AddSP(func_name);
+    d->Add(func_name.c_str());
 }
 
 TraversalCode ZBody::Traverse(TraversalCallback* cb) const {

src/script_opt/ZAM/ZBody.h

@@ -5,6 +5,7 @@
 #pragma once
 
 #include "zeek/script_opt/ZAM/IterInfo.h"
+#include "zeek/script_opt/ZAM/Profile.h"
 #include "zeek/script_opt/ZAM/Support.h"
 
 namespace zeek::detail {
@@ -26,9 +27,18 @@ using CaseMaps = std::vector<CaseMap<T>>;
 
 using TableIterVec = std::vector<TableIterInfo>;
 
+struct ProfVal {
+    zeek_uint_t num_samples = 0;
+    double CPU_time = 0.0;
+};
+
+using ProfVec = std::vector<ProfVal>;
+using ProfMap = std::unordered_map<std::string, ProfVal>;
+using CallStack = std::vector<const ZAMLocInfo*>;
+
 class ZBody : public Stmt {
 public:
-    ZBody(const char* _func_name, const ZAMCompiler* zc);
+    ZBody(std::string _func_name, const ZAMCompiler* zc);
 
     ~ZBody() override;
 
@@ -48,26 +58,29 @@ public:
 
     void Dump() const;
 
-    void ProfileExecution() const;
+    void ReportExecutionProfile(ProfMap& pm);
 
-protected:
+    const std::string& FuncName() const { return func_name; }
+
+private:
     // Initializes profiling information, if needed.
     void InitProfile();
+    std::shared_ptr<ProfVec> BuildProfVec() const;
 
-    ValPtr DoExec(Frame* f, StmtFlowType& flow);
+    void ReportProfile(ProfMap& pm, const ProfVec& pv, const std::string& prefix,
+                       std::set<std::string> caller_modules) const;
 
     // Run-time checking for "any" type being consistent with
     // expected typed.  Returns true if the type match is okay.
     bool CheckAnyType(const TypePtr& any_type, const TypePtr& expected_type,
-                      const std::shared_ptr<Location>& loc) const;
+                      const std::shared_ptr<ZAMLocInfo>& loc) const;
 
     StmtPtr Duplicate() override { return {NewRef{}, this}; }
 
     void StmtDescribe(ODesc* d) const override;
     TraversalCode Traverse(TraversalCallback* cb) const override;
 
-private:
-    const char* func_name = nullptr;
+    std::string func_name;
 
     const ZInst* insts = nullptr;
     unsigned int end_pc = 0;
@@ -100,21 +113,19 @@ private:
     std::vector<GlobalInfo> globals;
     int num_globals;
 
-    // The following are only maintained if we're doing profiling.
-    //
-    // These need to be pointers so we can manipulate them in a
-    // const method.
-    std::vector<int>* inst_count = nullptr;  // for profiling
-    double* CPU_time = nullptr;              // cumulative CPU time for the program
-    std::vector<double>* inst_CPU = nullptr; // per-instruction CPU time.
-
     CaseMaps<zeek_int_t> int_cases;
     CaseMaps<zeek_uint_t> uint_cases;
     CaseMaps<double> double_cases;
     CaseMaps<std::string> str_cases;
+
+    // The following are only maintained if we're doing profiling.
+    int ninst = 0;
+    int ncall = 0;
+    double tot_CPU_time = 0.0;
+    uint64_t tot_mem = 0;
+    std::map<CallStack, std::shared_ptr<ProfVec>> prof_vecs;
+    std::shared_ptr<ProfVec> default_prof_vec;
+    ProfVec* curr_prof_vec;
 };
 
-// Prints the execution profile.
-extern void report_ZOP_profile();
-
 } // namespace zeek::detail

src/script_opt/ZAM/ZInst.cc

@@ -10,75 +10,87 @@ using std::string;
 
 namespace zeek::detail {
 
-void ZInst::Dump(zeek_uint_t inst_num, const FrameReMap* mappings) const {
-    // printf("v%d ", n);
+void ZInst::Dump(FILE* f, zeek_uint_t inst_num, const FrameReMap* mappings, const string& prefix) const {
+    // fprintf(f, "v%d ", n);
 
     auto id1 = VName(1, inst_num, mappings);
     auto id2 = VName(2, inst_num, mappings);
     auto id3 = VName(3, inst_num, mappings);
     auto id4 = VName(4, inst_num, mappings);
 
-    Dump(id1, id2, id3, id4);
+    Dump(f, prefix, id1, id2, id3, id4);
 }
 
-void ZInst::Dump(const string& id1, const string& id2, const string& id3, const string& id4) const {
-    printf("%s ", ZOP_name(op));
-    // printf("(%s) ", op_type_name(op_type));
+void ZInst::Dump(FILE* f, const string& prefix, const string& id1, const string& id2, const string& id3,
+                 const string& id4) const {
+    fprintf(f, "%s ", ZOP_name(op));
+    // fprintf(f, "(%s) ", op_type_name(op_type));
     if ( t && 0 )
-        printf("(%s) ", type_name(t->Tag()));
+        fprintf(f, "(%s) ", type_name(t->Tag()));
 
     switch ( op_type ) {
         case OP_X: break;
 
-        case OP_V: printf("%s", id1.c_str()); break;
+        case OP_V: fprintf(f, "%s", id1.c_str()); break;
 
-        case OP_VV: printf("%s, %s", id1.c_str(), id2.c_str()); break;
+        case OP_VV: fprintf(f, "%s, %s", id1.c_str(), id2.c_str()); break;
 
-        case OP_VVV: printf("%s, %s, %s", id1.c_str(), id2.c_str(), id3.c_str()); break;
+        case OP_VVV: fprintf(f, "%s, %s, %s", id1.c_str(), id2.c_str(), id3.c_str()); break;
 
-        case OP_VVVV: printf("%s, %s, %s, %s", id1.c_str(), id2.c_str(), id3.c_str(), id4.c_str()); break;
+        case OP_VVVV: fprintf(f, "%s, %s, %s, %s", id1.c_str(), id2.c_str(), id3.c_str(), id4.c_str()); break;
 
-        case OP_VVVC: printf("%s, %s, %s, %s", id1.c_str(), id2.c_str(), id3.c_str(), ConstDump().c_str()); break;
+        case OP_VVVC: fprintf(f, "%s, %s, %s, %s", id1.c_str(), id2.c_str(), id3.c_str(), ConstDump().c_str()); break;
 
-        case OP_C: printf("%s", ConstDump().c_str()); break;
+        case OP_C: fprintf(f, "%s", ConstDump().c_str()); break;
 
-        case OP_VC: printf("%s, %s", id1.c_str(), ConstDump().c_str()); break;
+        case OP_VC: fprintf(f, "%s, %s", id1.c_str(), ConstDump().c_str()); break;
 
-        case OP_VVC: printf("%s, %s, %s", id1.c_str(), id2.c_str(), ConstDump().c_str()); break;
+        case OP_VVC: fprintf(f, "%s, %s, %s", id1.c_str(), id2.c_str(), ConstDump().c_str()); break;
 
-        case OP_V_I1: printf("%d", v1); break;
+        case OP_V_I1: fprintf(f, "%d", v1); break;
 
-        case OP_VC_I1: printf("%d %s", v1, ConstDump().c_str()); break;
+        case OP_VC_I1: fprintf(f, "%d %s", v1, ConstDump().c_str()); break;
 
-        case OP_VV_FRAME: printf("%s, interpreter frame[%d]", id1.c_str(), v2); break;
+        case OP_VV_FRAME: fprintf(f, "%s, interpreter frame[%d]", id1.c_str(), v2); break;
 
-        case OP_VV_I2: printf("%s, %d", id1.c_str(), v2); break;
+        case OP_VV_I2: fprintf(f, "%s, %d", id1.c_str(), v2); break;
 
-        case OP_VV_I1_I2: printf("%d, %d", v1, v2); break;
+        case OP_VV_I1_I2: fprintf(f, "%d, %d", v1, v2); break;
 
-        case OP_VVC_I2: printf("%s, %d, %s", id1.c_str(), v2, ConstDump().c_str()); break;
+        case OP_VVC_I2: fprintf(f, "%s, %d, %s", id1.c_str(), v2, ConstDump().c_str()); break;
 
-        case OP_VVV_I3: printf("%s, %s, %d", id1.c_str(), id2.c_str(), v3); break;
+        case OP_VVV_I3: fprintf(f, "%s, %s, %d", id1.c_str(), id2.c_str(), v3); break;
 
-        case OP_VVV_I2_I3: printf("%s, %d, %d", id1.c_str(), v2, v3); break;
+        case OP_VVV_I2_I3: fprintf(f, "%s, %d, %d", id1.c_str(), v2, v3); break;
 
-        case OP_VVVV_I4: printf("%s, %s, %s, %d", id1.c_str(), id2.c_str(), id3.c_str(), v4); break;
+        case OP_VVVV_I4: fprintf(f, "%s, %s, %s, %d", id1.c_str(), id2.c_str(), id3.c_str(), v4); break;
 
-        case OP_VVVV_I3_I4: printf("%s, %s, %d, %d", id1.c_str(), id2.c_str(), v3, v4); break;
+        case OP_VVVV_I3_I4: fprintf(f, "%s, %s, %d, %d", id1.c_str(), id2.c_str(), v3, v4); break;
 
-        case OP_VVVV_I2_I3_I4: printf("%s, %d, %d, %d", id1.c_str(), v2, v3, v4); break;
+        case OP_VVVV_I2_I3_I4: fprintf(f, "%s, %d, %d, %d", id1.c_str(), v2, v3, v4); break;
 
-        case OP_VVVC_I3: printf("%s, %s, %d, %s", id1.c_str(), id2.c_str(), v3, ConstDump().c_str()); break;
+        case OP_VVVC_I3: fprintf(f, "%s, %s, %d, %s", id1.c_str(), id2.c_str(), v3, ConstDump().c_str()); break;
 
-        case OP_VVVC_I2_I3: printf("%s, %d, %d, %s", id1.c_str(), v2, v3, ConstDump().c_str()); break;
+        case OP_VVVC_I2_I3: fprintf(f, "%s, %d, %d, %s", id1.c_str(), v2, v3, ConstDump().c_str()); break;
 
-        case OP_VVVC_I1_I2_I3: printf("%d, %d, %d, %s", v1, v2, v3, ConstDump().c_str()); break;
+        case OP_VVVC_I1_I2_I3: fprintf(f, "%d, %d, %d, %s", v1, v2, v3, ConstDump().c_str()); break;
     }
 
-    if ( func )
-        printf(" (func %s)", func->Name());
+    auto func = aux ? aux->func : nullptr;
 
-    printf("\n");
+    if ( func )
+        fprintf(f, " (func %s)", func->Name());
+
+    if ( loc ) {
+        auto l = loc->Describe(true);
+        if ( func && (func->GetBodies().empty() || func->GetBodies()[0].stmts->Tag() != STMT_ZAM) )
+            l = l + ";" + func->Name();
+        if ( ! prefix.empty() )
+            l = prefix + l;
+        fprintf(f, " // %s", l.c_str());
+    }
+
+    fprintf(f, "\n");
 }
 
 int ZInst::NumFrameSlots() const {
@@ -286,16 +298,16 @@ string ZInst::ConstDump() const {
     return d.Description();
 }
 
-void ZInstI::Dump(const FrameMap* frame_ids, const FrameReMap* remappings) const {
+void ZInstI::Dump(FILE* f, const FrameMap* frame_ids, const FrameReMap* remappings) const {
     int n = NumFrameSlots();
-    // printf("v%d ", n);
+    // fprintf(f, "v%d ", n);
 
     auto id1 = VName(1, frame_ids, remappings);
     auto id2 = VName(2, frame_ids, remappings);
     auto id3 = VName(3, frame_ids, remappings);
     auto id4 = VName(4, frame_ids, remappings);
 
-    ZInst::Dump(id1, id2, id3, id4);
+    ZInst::Dump(f, "", id1, id2, id3, id4);
 }
 
 string ZInstI::VName(int n, const FrameMap* frame_ids, const FrameReMap* remappings) const {

src/script_opt/ZAM/ZInst.h

@@ -60,16 +60,22 @@ public:
     ZInst(ZOp _op, ZAMOpType _op_type) {
         op = _op;
         op_type = _op_type;
+        ASSERT(ZAM::curr_loc);
+        loc = ZAM::curr_loc;
     }
 
     // Create a stub instruction that will be populated later.
-    ZInst() = default;
+    ZInst() {
+        ASSERT(ZAM::curr_loc);
+        loc = ZAM::curr_loc;
+    }
 
     virtual ~ZInst() = default;
 
-    // Methods for printing out the instruction for debugging/maintenance.
-    void Dump(zeek_uint_t inst_num, const FrameReMap* mappings) const;
-    void Dump(const std::string& id1, const std::string& id2, const std::string& id3, const std::string& id4) const;
+    // Methods for printing out the instruction for debugging/profiling.
+    void Dump(FILE* f, zeek_uint_t inst_num, const FrameReMap* mappings, const std::string& prefix) const;
+    void Dump(FILE* f, const std::string& prefix, const std::string& id1, const std::string& id2,
+              const std::string& id3, const std::string& id4) const;
 
     // Returns the name to use in identifying one of the slots/integer
     // values (designated by "n").  "inst_num" identifies the instruction
@@ -121,10 +127,6 @@ public:
     // Type, usually for interpreting the constant.
     TypePtr t = nullptr;
     TypePtr t2 = nullptr; // just a few ops need two types
-    const Expr* e = nullptr;               // only needed for "when" expressions
-    Func* func = nullptr;                  // used for calls
-    EventHandler* event_handler = nullptr; // used for referring to events
-    AttributesPtr attrs = nullptr;         // used for things like constructors
 
     // Auxiliary information.  We could in principle use this to
     // consolidate a bunch of the above, though at the cost of
@@ -132,12 +134,9 @@ public:
     // which is why we bundle these separately.
     ZInstAux* aux = nullptr;
 
-    // Location associated with this instruction, for error reporting.
-    std::shared_ptr<Location> loc;
-
-    // Interpreter call expression associated with this instruction,
-    // for error reporting and stack backtraces.
-    CallExprPtr call_expr = nullptr;
+    // Location associated with this instruction, for error reporting
+    // and profiling.
+    std::shared_ptr<ZAMLocInfo> loc;
 
     // Whether v1 represents a frame slot type for which we
     // explicitly manage the memory.
@@ -201,7 +200,7 @@ public:
     ZInstI() {}
 
     // If "remappings" is non-nil, then it is used instead of frame_ids.
-    void Dump(const FrameMap* frame_ids, const FrameReMap* remappings) const;
+    void Dump(FILE* f, const FrameMap* frame_ids, const FrameReMap* remappings) const;
 
     // Note that this is *not* an override of the base class's VName
     // but instead a method with similar functionality but somewhat
@@ -294,9 +293,6 @@ public:
     // a branch target).
     int num_labels = 0;
 
-    // Used for debugging.  Transformed into the ZInst "loc" field.
-    StmtPtr stmt = curr_stmt;
-
 private:
     // Initialize 'c' from the given ConstExpr.
     void InitConst(const ConstExpr* ce);
@@ -467,6 +463,22 @@ public:
     // Used for accessing function names.
     IDPtr id_val = nullptr;
 
+    // Interpreter call expression associated with this instruction,
+    // for error reporting and stack backtraces.
+    CallExprPtr call_expr = nullptr;
+
+    // Used for direct calls.
+    Func* func = nullptr;
+
+    // Whether we know that we're calling a BiF.
+    bool is_BiF_call = false;
+
+    // Used for referring to events.
+    EventHandler* event_handler = nullptr;
+
+    // Used for things like constructors.
+    AttributesPtr attrs = nullptr;
+
     // Whether the instruction can lead to globals/captures changing.
     // Currently only needed by the optimizer, but convenient to
     // store here.

src/util.cc

@@ -2182,13 +2182,14 @@ void get_memory_usage(uint64_t* total, uint64_t* malloced) {
     uint64_t ret_total;
 
 #if defined(HAVE_MALLINFO2) || defined(HAVE_MALLINFO)
+    if ( malloced ) {
 #ifdef HAVE_MALLINFO2
         struct mallinfo2 mi = mallinfo2();
 #else
         struct mallinfo mi = mallinfo();
 #endif
-    if ( malloced )
         *malloced = mi.uordblks;
+    }
 #endif
 
 #ifdef HAVE_DARWIN
@@ -2207,6 +2208,8 @@ void get_memory_usage(uint64_t* total, uint64_t* malloced) {
     ret_total = r.ru_maxrss * 1024;
 
     if ( malloced )
+        // This will overwrite any mallinfo[2] value from above, should
+        // be restructured to avoid unnecessary work.
         *malloced = r.ru_ixrss * 1024;
 #endif
 

testing/btest/Baseline.zam/broker.remote_log_types/recv.test.log

@@ -7,5 +7,5 @@
 #open XXXX-XX-XX-XX-XX-XX
 #fields	b	i	e	c	p	sn	a	d	t	iv	s	sc	ss	se	vc	ve	f
 #types	bool	int	enum	count	port	subnet	addr	double	time	interval	string	set[count]	set[string]	set[string]	vector[count]	vector[string]	func
-T	-42	Test::LOG	21	123	10.0.0.0/24	1.2.3.4	3.14	XXXXXXXXXX.XXXXXX	100.000000	hurz	1	AA	(empty)	10,20,30	(empty)	foo\x0aZAM-code foo 
+T	-42	Test::LOG	21	123	10.0.0.0/24	1.2.3.4	3.14	XXXXXXXXXX.XXXXXX	100.000000	hurz	1	AA	(empty)	10,20,30	(empty)	foo\x0aZAM-code Broker::foo
 #close XXXX-XX-XX-XX-XX-XX

testing/btest/Baseline.zam/broker.remote_log_types/send.test.log

@@ -7,5 +7,5 @@
 #open XXXX-XX-XX-XX-XX-XX
 #fields	b	i	e	c	p	sn	a	d	t	iv	s	sc	ss	se	vc	ve	f
 #types	bool	int	enum	count	port	subnet	addr	double	time	interval	string	set[count]	set[string]	set[string]	vector[count]	vector[string]	func
-T	-42	Test::LOG	21	123	10.0.0.0/24	1.2.3.4	3.14	XXXXXXXXXX.XXXXXX	100.000000	hurz	1	AA	(empty)	10,20,30	(empty)	foo\x0aZAM-code foo 
+T	-42	Test::LOG	21	123	10.0.0.0/24	1.2.3.4	3.14	XXXXXXXXXX.XXXXXX	100.000000	hurz	1	AA	(empty)	10,20,30	(empty)	foo\x0aZAM-code Broker::foo
 #close XXXX-XX-XX-XX-XX-XX