diff --git a/CHANGES b/CHANGES index 08b7e5b0aa..048e879a86 100644 --- a/CHANGES +++ b/CHANGES @@ -1,3 +1,29 @@ +5.0.0-dev.382 | 2022-05-11 12:56:13 -0700 + + * tidy up after generating profile (Vern Paxson, Corelight) + + * fix for coverage reporting for functions that use "when" statements (Vern Paxson, Corelight) + + * new global_options() BiF to speed up startup, plus a micro-preen (Vern Paxson, Corelight) + + * hooks for new --profile-scripts option (Vern Paxson, Corelight) + + * classes for managing script profiles (Vern Paxson, Corelight) + + * address some holes in script coverage (Vern Paxson, Corelight) + + * fix for script coverage missing on-exit activity (Vern Paxson, Corelight) + + * memory management fixes for loggers (Vern Paxson, Corelight) + + * make curr_CPU_time() broadly available rather than just isolated to ZAM (Vern Paxson, Corelight) + + * Add exact name of the Top-k algorithm. (Johanna Amann) + + I needed to figure out which exact algorithm we use for our + probabilistic top-k measurements. It turns out that we do not mention + this in our source tree at all so far. + 5.0.0-dev.368 | 2022-05-09 10:37:44 +0100 * when printing a description of a type, use its name if available (Vern Paxson, Corelight) diff --git a/VERSION b/VERSION index ac04acb93e..96ef4adae7 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -5.0.0-dev.368 +5.0.0-dev.382 diff --git a/scripts/base/frameworks/config/main.zeek b/scripts/base/frameworks/config/main.zeek index 2d87e3c09e..47525ee7b7 100644 --- a/scripts/base/frameworks/config/main.zeek +++ b/scripts/base/frameworks/config/main.zeek @@ -162,13 +162,7 @@ event zeek_init() &priority=10 @if ( !Cluster::is_enabled() || Cluster::local_node_type() == Cluster::MANAGER ) # Iterate over all existing options and add ourselves as change handlers # with a low priority so that we can log the changes. - local gids = global_ids(); - for ( i, gid in gids ) - { - if ( ! gid$option_value ) - next; - - Option::set_change_handler(i, config_option_changed, -100); - } + for ( opt in global_options() ) + Option::set_change_handler(opt, config_option_changed, -100); @endif } diff --git a/scripts/base/utils/site.zeek b/scripts/base/utils/site.zeek index 7843bcf31a..7745d7b2c8 100644 --- a/scripts/base/utils/site.zeek +++ b/scripts/base/utils/site.zeek @@ -243,5 +243,4 @@ event zeek_init() &priority=10 # Create the local_nets mapping table. for ( cidr in Site::local_nets ) local_nets_table[cidr] = cidr; - } diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index f5158bcb50..81834cf7d2 100644 --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -330,6 +330,7 @@ set(MAIN_SRCS ScannedFile.cc Scope.cc ScriptCoverageManager.cc + ScriptProfile.cc SerializationFormat.cc SmithWaterman.cc Stats.cc diff --git a/src/EventHandler.cc b/src/EventHandler.cc index 1196ae8ec8..09ba72c27d 100644 --- a/src/EventHandler.cc +++ b/src/EventHandler.cc @@ -52,10 +52,6 @@ void EventHandler::SetFunc(FuncPtr f) void EventHandler::Call(Args* vl, bool no_remote) { -#ifdef PROFILE_BRO_FUNCTIONS - DEBUG_MSG("Event: %s\n", Name()); -#endif - if ( new_event ) NewEvent(vl); diff --git a/src/Func.cc b/src/Func.cc index 600c9aaabd..3c44d247c5 100644 --- a/src/Func.cc +++ b/src/Func.cc @@ -5,18 +5,6 @@ #include "zeek/zeek-config.h" -#include -#include -#ifdef TIME_WITH_SYS_TIME -#include -#include -#else -#ifdef HAVE_SYS_TIME_H -#include -#else -#include -#endif -#endif #include #include #include @@ -25,7 +13,6 @@ #include #include #include -#include #include #include @@ -42,6 +29,7 @@ #include "zeek/Reporter.h" #include "zeek/RunState.h" #include "zeek/Scope.h" +#include "zeek/ScriptProfile.h" #include "zeek/Stmt.h" #include "zeek/Traverse.h" #include "zeek/Var.h" @@ -348,9 +336,6 @@ bool ScriptFunc::IsPure() const ValPtr ScriptFunc::Invoke(zeek::Args* args, Frame* parent) const { -#ifdef PROFILE_BRO_FUNCTIONS - DEBUG_MSG("Function: %s\n", Name()); -#endif SegmentProfiler prof(segment_logger, location); if ( sample_logger ) @@ -417,6 +402,9 @@ ValPtr ScriptFunc::Invoke(zeek::Args* args, Frame* parent) const f->SetElement(j, arg); } + if ( spm ) + spm->StartInvocation(this, body.stmts); + f->Reset(args->size()); try @@ -439,6 +427,9 @@ ValPtr ScriptFunc::Invoke(zeek::Args* args, Frame* parent) const continue; } + if ( spm ) + spm->EndInvocation(); + if ( f->HasDelayed() ) { assert(! result); @@ -758,9 +749,9 @@ bool BuiltinFunc::IsPure() const ValPtr BuiltinFunc::Invoke(Args* args, Frame* parent) const { -#ifdef PROFILE_BRO_FUNCTIONS - DEBUG_MSG("Function: %s\n", Name()); -#endif + if ( spm ) + spm->StartInvocation(this); + SegmentProfiler prof(segment_logger, Name()); if ( sample_logger ) @@ -772,7 +763,11 @@ ValPtr BuiltinFunc::Invoke(Args* args, Frame* parent) const CheckPluginResult(handled, hook_result, FUNC_FLAVOR_FUNCTION); if ( handled ) + { + if ( spm ) + spm->EndInvocation(); return hook_result; + } if ( g_trace_state.DoTrace() ) { @@ -795,6 +790,9 @@ ValPtr BuiltinFunc::Invoke(Args* args, Frame* parent) const g_trace_state.LogTrace("\tFunction return: %s\n", d.Description()); } + if ( spm ) + spm->EndInvocation(); + return result; } diff --git a/src/Options.cc b/src/Options.cc index 0cf23a4fd6..b9938bbb12 100644 --- a/src/Options.cc +++ b/src/Options.cc @@ -6,6 +6,7 @@ #include +#include "zeek/ScriptProfile.h" #include "zeek/script_opt/ScriptOpt.h" #ifdef HAVE_GETOPT_H @@ -142,6 +143,9 @@ void usage(const char* prog, int code) fprintf(stderr, " -m|--mem-leaks | show leaks [perftools]\n"); fprintf(stderr, " -M|--mem-profile | record heap [perftools]\n"); #endif + fprintf( + stderr, + " --profile-scripts[=file] | profile scripts to given file (default stdout)\n"); fprintf(stderr, " --pseudo-realtime[=] | enable pseudo-realtime for performance " "evaluation (default 1)\n"); fprintf(stderr, " -j|--jobs | enable supervisor mode\n"); @@ -362,7 +366,9 @@ Options parse_cmdline(int argc, char** argv) } } - constexpr struct option long_opts[] = { + int profile_scripts = 0; + + struct option long_opts[] = { {"parse-only", no_argument, nullptr, 'a'}, {"bare-mode", no_argument, nullptr, 'b'}, {"capture-unprocessed", required_argument, nullptr, 'c'}, @@ -403,6 +409,7 @@ Options parse_cmdline(int argc, char** argv) {"mem-profile", no_argument, nullptr, 'M'}, #endif + {"profile-scripts", optional_argument, &profile_scripts, 1}, {"pseudo-realtime", optional_argument, nullptr, '~'}, {"jobs", optional_argument, nullptr, 'j'}, {"test", no_argument, nullptr, '#'}, @@ -601,6 +608,11 @@ Options parse_cmdline(int argc, char** argv) case 0: // This happens for long options that don't have // a short-option equivalent. + if ( profile_scripts ) + { + activate_script_profiling(optarg); + profile_scripts = 0; + } break; case '?': diff --git a/src/RunState.cc b/src/RunState.cc index 76ac99e79d..7c24ee18c4 100644 --- a/src/RunState.cc +++ b/src/RunState.cc @@ -251,7 +251,7 @@ void dispatch_packet(Packet* pkt, iosource::PktSrc* pkt_src) // charged against this sample. event_mgr.Drain(); - zeek::detail::sample_logger = new zeek::detail::SampleLogger(); + zeek::detail::sample_logger = std::make_shared(); sp = new zeek::detail::SegmentProfiler(zeek::detail::sample_logger, "load-samp"); } } @@ -262,7 +262,6 @@ void dispatch_packet(Packet* pkt, iosource::PktSrc* pkt_src) if ( sp ) { delete sp; - delete zeek::detail::sample_logger; zeek::detail::sample_logger = nullptr; } diff --git a/src/ScriptCoverageManager.cc b/src/ScriptCoverageManager.cc index 552f3970c0..ab56f3b793 100644 --- a/src/ScriptCoverageManager.cc +++ b/src/ScriptCoverageManager.cc @@ -127,27 +127,27 @@ bool ScriptCoverageManager::WriteStats() return false; } - for ( list::const_iterator it = stmts.begin(); it != stmts.end(); ++it ) + for ( auto s : stmts ) { ODesc location_info; - (*it)->GetLocationInfo()->Describe(&location_info); + s->GetLocationInfo()->Describe(&location_info); ODesc desc_info; - (*it)->Describe(&desc_info); + s->Describe(&desc_info); string desc(desc_info.Description()); canonicalize_desc cd{delim}; for_each(desc.begin(), desc.end(), cd); pair location_desc(location_info.Description(), desc); if ( usage_map.find(location_desc) != usage_map.end() ) - usage_map[location_desc] += (*it)->GetAccessCount(); + usage_map[location_desc] += s->GetAccessCount(); else - usage_map[location_desc] = (*it)->GetAccessCount(); + usage_map[location_desc] = s->GetAccessCount(); } map, uint64_t>::const_iterator it; - for ( it = usage_map.begin(); it != usage_map.end(); ++it ) + for ( auto& um : usage_map ) { - fprintf(f, "%" PRIu64 "%c%s%c%s\n", it->second, delim, it->first.first.c_str(), delim, - it->first.second.c_str()); + fprintf(f, "%" PRIu64 "%c%s%c%s\n", um.second, delim, um.first.first.c_str(), delim, + um.first.second.c_str()); } fclose(f); diff --git a/src/ScriptProfile.cc b/src/ScriptProfile.cc new file mode 100644 index 0000000000..a08071e5be --- /dev/null +++ b/src/ScriptProfile.cc @@ -0,0 +1,188 @@ +// See the file "COPYING" in the main distribution directory for copyright. + +#include "zeek/ScriptProfile.h" + +namespace zeek + { + +namespace detail + { + +void ScriptProfile::StartActivation() + { + NewCall(); + + uint64_t start_memory; + util::get_memory_usage(&start_memory, nullptr); + start_stats.SetStats(util::curr_CPU_time(), start_memory); + } + +void ScriptProfile::EndActivation() + { + uint64_t end_memory; + util::get_memory_usage(&end_memory, nullptr); + + delta_stats.SetStats(util::curr_CPU_time() - start_stats.CPUTime(), + end_memory - start_stats.Memory()); + + AddIn(&delta_stats, false); + } + +void ScriptProfile::ChildFinished(const ScriptProfile* child) + { + child_stats.AddIn(child->DeltaCPUTime(), child->DeltaMemory()); + } + +void ScriptProfile::Report(FILE* f) const + { + std::string l; + + if ( loc.first_line == 0 ) + // Rather than just formatting the no-location loc, we'd like + // a version that doesn't have a funky "line 0" in it, nor + // an embedded blank. + l = ""; + else + l = std::string(loc.filename) + ":" + std::to_string(loc.first_line); + + std::string ftype = is_BiF ? "BiF" : func->GetType()->FlavorString(); + + fprintf(f, "%s\t%s\t%s\t%d\t%.06f\t%.06f\t%lld\t%lld\n", Name().c_str(), l.c_str(), + ftype.c_str(), NumCalls(), CPUTime(), child_stats.CPUTime(), Memory(), + child_stats.Memory()); + } + +ScriptProfileMgr::ScriptProfileMgr(FILE* _f) : f(_f), non_scripts() + { + non_scripts.StartActivation(); + } + +ScriptProfileMgr::~ScriptProfileMgr() + { + ASSERT(call_stack.empty()); + + non_scripts.EndActivation(); + + ScriptProfileStats total_stats; + ScriptProfileStats BiF_stats; + std::unordered_map func_stats; + + fprintf(f, + "#fields\tfunction\tlocation\ttype\tncall\ttot_CPU\tchild_CPU\ttot_Mem\tchild_Mem\n"); + fprintf(f, "#types\tstring\tstring\tstring\tcount\tinterval\tinterval\tcount\tcount\n"); + + for ( auto o : objs ) + { + auto p = profiles[o].get(); + profiles[o]->Report(f); + + total_stats.AddInstance(); + total_stats.AddIn(p); + + if ( p->IsBiF() ) + { + BiF_stats.AddInstance(); + BiF_stats.AddIn(p); + } + else + { + ASSERT(body_to_func.count(o) > 0); + auto func = body_to_func[o]; + + if ( func_stats.count(func) == 0 ) + func_stats[func] = ScriptProfileStats(func->Name()); + + func_stats[func].AddIn(p); + } + } + + for ( auto& fs : func_stats ) + { + auto func = fs.first; + auto& fp = fs.second; + auto n = func->GetBodies().size(); + if ( n > 1 ) + fprintf(f, "%s\t%lu-locations\t%s\t%d\t%.06f\t%0.6f\t%lld\t%lld\n", fp.Name().c_str(), + n, func->GetType()->FlavorString().c_str(), fp.NumCalls(), fp.CPUTime(), 0.0, + fp.Memory(), 0LL); + } + + fprintf(f, "all-BiFs\t%d-locations\tBiF\t%d\t%.06f\t%.06f\t%lld\t%lld\n", + BiF_stats.NumInstances(), BiF_stats.NumCalls(), BiF_stats.CPUTime(), 0.0, + BiF_stats.Memory(), 0LL); + + fprintf(f, "total\t%d-locations\tTOTAL\t%d\t%.06f\t%.06f\t%lld\t%lld\n", + total_stats.NumInstances(), total_stats.NumCalls(), total_stats.CPUTime(), 0.0, + total_stats.Memory(), 0LL); + + fprintf(f, "non-scripts\t\tTOTAL\t%d\t%.06f\t%.06f\t%lld\t%lld\n", + non_scripts.NumCalls(), non_scripts.CPUTime(), 0.0, non_scripts.Memory(), 0LL); + + if ( f != stdout ) + fclose(f); + } + +void ScriptProfileMgr::StartInvocation(const Func* f, const detail::StmtPtr& body) + { + if ( call_stack.empty() ) + non_scripts.EndActivation(); + + const Obj* o = body ? static_cast(body.get()) : f; + auto associated_prof = profiles.find(o); + ScriptProfile* ep; + + if ( associated_prof == profiles.end() ) + { + auto new_ep = std::make_unique(f, body); + ep = new_ep.get(); + profiles[o] = std::move(new_ep); + objs.push_back(o); + + if ( body ) + body_to_func[o] = f; + } + else + ep = associated_prof->second.get(); + + ep->StartActivation(); + call_stack.push_back(ep); + } + +void ScriptProfileMgr::EndInvocation() + { + ASSERT(! call_stack.empty()); + auto ep = call_stack.back(); + call_stack.pop_back(); + + ep->EndActivation(); + + if ( call_stack.empty() ) + non_scripts.StartActivation(); + else + { + auto parent = call_stack.back(); + parent->ChildFinished(ep); + } + } + +std::unique_ptr spm; + + } // namespace zeek::detail + +void activate_script_profiling(const char* fn) + { + FILE* f; + + if ( fn ) + { + f = fopen(fn, "w"); + if ( ! f ) + reporter->FatalError("can't open %s to record scripting profile", fn); + } + else + f = stdout; + + detail::spm = std::make_unique(f); + } + + } // namespace zeek diff --git a/src/ScriptProfile.h b/src/ScriptProfile.h new file mode 100644 index 0000000000..2ea7de2d7b --- /dev/null +++ b/src/ScriptProfile.h @@ -0,0 +1,184 @@ +// See the file "COPYING" in the main distribution directory for copyright. + +// Classes for profiling CPU & memory usage by scripts. + +#pragma once + +#include + +#include "zeek/Func.h" +#include "zeek/Stmt.h" + +namespace zeek + { + +namespace detail + { + +// Base class for tracking an instance of profile information. The instance +// can be a single function body (equivalently, event handler or hook body), +// or an aggregate that includes multiple function bodies. + +class ScriptProfileStats + { +public: + ScriptProfileStats() { } + ScriptProfileStats(std::string arg_name) : name(std::move(arg_name)) { } + + virtual ~ScriptProfileStats() { } + + const auto Name() const { return name; } + + // Number of instances included in an aggregate (like for "all BiFs"). + // This is 1 for non-aggregates. + int NumInstances() const { return ninstances; } + + // How many calls were profiled for this instance. + int NumCalls() const { return ncalls; } + + // CPU & memory accumulated by the calls. + double CPUTime() const { return CPU_time; } + uint64_t Memory() const { return memory; } + + // Used to count instances in an aggregate. + void AddInstance() { ++ninstances; } + + // Fold into this profile another profile. Second argument controls + // whether the folding should include increasing the number of calls. + void AddIn(const ScriptProfileStats* eps, bool bump_num_calls = true) + { + if ( bump_num_calls ) + ncalls += eps->NumCalls(); + + CPU_time += eps->CPUTime(); + memory += eps->Memory(); + } + + // Accumulate a single instance of CPU & memory usage. + void AddIn(double delta_CPU_time, uint64_t delta_memory) + { + CPU_time += delta_CPU_time; + memory += delta_memory; + } + + // Directly specify the total CPU & memory usage. + void SetStats(double arg_CPU_time, uint64_t arg_memory) + { + CPU_time = arg_CPU_time; + memory = arg_memory; + } + + // Track that the instance has had another call. + void NewCall() { ++ncalls; } + +private: + std::string name; + int ninstances = 0; + int ncalls = 0; + double CPU_time = 0.0; + uint64_t memory = 0; + }; + +// Manages all of the profile instances assocaited with a given script. + +class ScriptProfile : public ScriptProfileStats + { +public: + ScriptProfile(const Func* _func, const detail::StmtPtr& body) + : ScriptProfileStats(_func->Name()) + { + func = _func; + is_BiF = body == nullptr; + + if ( is_BiF ) + loc = *func->GetLocationInfo(); + else + loc = *body->GetLocationInfo(); + } + + // Constructor used for the special case of non-script acocunting. + ScriptProfile() : ScriptProfileStats("non-scripts") + { + func = nullptr; + is_BiF = false; + } + + // Called to register the beginning/end of an execution instance. + void StartActivation(); + void EndActivation(); + + // Called when a child instance finishes. + void ChildFinished(const ScriptProfile* child); + + bool IsBiF() const { return is_BiF; } + double DeltaCPUTime() const { return delta_stats.CPUTime(); } + uint64_t DeltaMemory() const { return delta_stats.Memory(); } + + // Write the profile to the given file. + void Report(FILE* f) const; + +private: + const Func* func; + bool is_BiF; + detail::Location loc; + + // Profile associated with child instances (functions or hooks + // that this instance calls - does not include events that this + // instance generates). + ScriptProfileStats child_stats; + + // These are ephemeral, only relevant between Start and End activations. + ScriptProfileStats start_stats; + + // Defined for the last activation period. + ScriptProfileStats delta_stats; + }; + +// Manages the entire script profiling process. +class ScriptProfileMgr + { +public: + // Argument specifies the file to write the profile to. + ScriptProfileMgr(FILE* f); + + // Destructor generates the actual profile. + ~ScriptProfileMgr(); + + // Mark that the given function body has begun/finished. "body" is + // nil for BiFs. + void StartInvocation(const Func* f, const detail::StmtPtr& body = nullptr); + void EndInvocation(); + +private: + FILE* f; // where to write the profile + + // Separate "script" profile that tracks resource impact of non-script + // execution. + ScriptProfile non_scripts; + + // Currently active instances. + std::vector call_stack; + + // Maps a given object (either a function body, for scripts, or the + // function itself, for BiFs) to its profile. + std::unordered_map> profiles; + + // Maps script bodies to their function - used for functions with + // multiple bodies. + std::unordered_map body_to_func; + + // Tracks the objects encountered. Used to generate a consistent + // and more natural printing order. + std::vector objs; + }; + +// If non-nil, script profiling is active. +extern std::unique_ptr spm; + + } // namespace zeek::detail + +// Called to turn on script profiling to the given file. If nil, writes +// the profile to stdout. +extern void activate_script_profiling(const char* fn); + + } // namespace zeek diff --git a/src/Stats.h b/src/Stats.h index ab3a2f6fa8..dd1d3e7418 100644 --- a/src/Stats.h +++ b/src/Stats.h @@ -8,6 +8,7 @@ #include #include #include +#include namespace zeek { @@ -41,15 +42,15 @@ class SegmentProfiler { public: // The constructor takes some way of identifying the segment. - SegmentProfiler(SegmentStatsReporter* arg_reporter, const char* arg_name) - : reporter(arg_reporter), name(arg_name), loc(), initial_rusage() + SegmentProfiler(std::shared_ptr arg_reporter, const char* arg_name) + : reporter(std::move(arg_reporter)), name(arg_name), loc(), initial_rusage() { if ( reporter ) Init(); } - SegmentProfiler(SegmentStatsReporter* arg_reporter, const Location* arg_loc) - : reporter(arg_reporter), name(), loc(arg_loc), initial_rusage() + SegmentProfiler(std::shared_ptr arg_reporter, const Location* arg_loc) + : reporter(std::move(arg_reporter)), name(), loc(arg_loc), initial_rusage() { if ( reporter ) Init(); @@ -65,7 +66,7 @@ protected: void Init(); void Report(); - SegmentStatsReporter* reporter; + std::shared_ptr reporter; const char* name; const Location* loc; struct rusage initial_rusage; @@ -106,9 +107,9 @@ protected: TableVal* load_samples; }; -extern ProfileLogger* profiling_logger; -extern ProfileLogger* segment_logger; -extern SampleLogger* sample_logger; +extern std::shared_ptr profiling_logger; +extern std::shared_ptr segment_logger; +extern std::shared_ptr sample_logger; // Connection statistics. extern uint64_t killed_by_inactivity; diff --git a/src/Stmt.cc b/src/Stmt.cc index 08470527fb..0edca90435 100644 --- a/src/Stmt.cc +++ b/src/Stmt.cc @@ -258,7 +258,7 @@ ExprListStmt::~ExprListStmt() = default; ValPtr ExprListStmt::Exec(Frame* f, StmtFlowType& flow) { - last_access = run_state::network_time; + RegisterAccess(); flow = FLOW_NEXT; auto vals = eval_list(f, l.get()); @@ -325,7 +325,6 @@ static void print_log(const std::vector& vals) ValPtr PrintStmt::DoExec(std::vector vals, StmtFlowType& /* flow */) { - RegisterAccess(); do_print_stmt(vals); return nullptr; } diff --git a/src/parse.y b/src/parse.y index 240d6017dd..ced76e6269 100644 --- a/src/parse.y +++ b/src/parse.y @@ -1665,28 +1665,33 @@ stmt: { set_location(@1, @4); $$ = new IfStmt({AdoptRef{}, $3}, {AdoptRef{}, $5}, make_intrusive()); + script_coverage_mgr.AddStmt($$); } | TOK_IF '(' expr ')' stmt TOK_ELSE stmt { set_location(@1, @4); $$ = new IfStmt({AdoptRef{}, $3}, {AdoptRef{}, $5}, {AdoptRef{}, $7}); + script_coverage_mgr.AddStmt($$); } | TOK_SWITCH expr '{' case_list '}' { set_location(@1, @2); $$ = new SwitchStmt({AdoptRef{}, $2}, $4); + script_coverage_mgr.AddStmt($$); } | for_head stmt { $1->AsForStmt()->AddBody({AdoptRef{}, $2}); + script_coverage_mgr.AddStmt($1); } | TOK_WHILE '(' expr ')' stmt { $$ = new WhileStmt({AdoptRef{}, $3}, {AdoptRef{}, $5}); + script_coverage_mgr.AddStmt($$); } | TOK_NEXT ';' opt_no_test @@ -1762,6 +1767,7 @@ stmt: | when_clause { $$ = new WhenStmt($1); + script_coverage_mgr.AddStmt($$); } | index_slice '=' expr ';' opt_no_test @@ -1786,6 +1792,7 @@ stmt: { set_location(@1, @1); $$ = new NullStmt; + script_coverage_mgr.AddStmt($$); } | conditional diff --git a/src/script_opt/ZAM/ZBody.cc b/src/script_opt/ZAM/ZBody.cc index d4804f16d7..d011736049 100644 --- a/src/script_opt/ZAM/ZBody.cc +++ b/src/script_opt/ZAM/ZBody.cc @@ -124,13 +124,6 @@ VEC_COERCE(UD, TYPE_COUNT, bro_uint_t, AsDouble(), double_to_count_would_overflo "double to unsigned") VEC_COERCE(UI, TYPE_COUNT, bro_int_t, AsInt(), int_to_count_would_overflow, "signed to unsigned") -double curr_CPU_time() - { - struct timespec ts; - clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &ts); - return double(ts.tv_sec) + double(ts.tv_nsec) / 1e9; - } - ZBody::ZBody(const char* _func_name, const ZAMCompiler* zc) : Stmt(STMT_ZAM) { func_name = _func_name; @@ -240,14 +233,14 @@ void ZBody::InitProfile() ValPtr ZBody::Exec(Frame* f, StmtFlowType& flow) { #ifdef DEBUG - double t = analysis_options.profile_ZAM ? curr_CPU_time() : 0.0; + double t = analysis_options.profile_ZAM ? util::curr_CPU_time() : 0.0; #endif auto val = DoExec(f, 0, flow); #ifdef DEBUG if ( analysis_options.profile_ZAM ) - *CPU_time += curr_CPU_time() - t; + *CPU_time += util::curr_CPU_time() - t; #endif return val; @@ -305,7 +298,7 @@ ValPtr ZBody::DoExec(Frame* f, int start_pc, StmtFlowType& flow) ++(*inst_count)[pc]; profile_pc = pc; - profile_CPU = curr_CPU_time(); + profile_CPU = util::curr_CPU_time(); } #endif @@ -327,7 +320,7 @@ ValPtr ZBody::DoExec(Frame* f, int start_pc, StmtFlowType& flow) #ifdef DEBUG if ( do_profile ) { - double dt = curr_CPU_time() - profile_CPU; + double dt = util::curr_CPU_time() - profile_CPU; inst_CPU->at(profile_pc) += dt; ZOP_CPU[z.op] += dt; } diff --git a/src/util.cc b/src/util.cc index 17fc590886..830ceaf81b 100644 --- a/src/util.cc +++ b/src/util.cc @@ -2058,6 +2058,13 @@ int time_compare(struct timeval* tv_a, struct timeval* tv_b) return tv_a->tv_sec - tv_b->tv_sec; } +double curr_CPU_time() + { + struct timespec ts; + clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &ts); + return double(ts.tv_sec) + double(ts.tv_nsec) / 1e9; + } + struct UIDEntry { UIDEntry() : key(0, 0), needs_init(true) { } diff --git a/src/util.h b/src/util.h index e715a665ec..936f7424d7 100644 --- a/src/util.h +++ b/src/util.h @@ -424,6 +424,9 @@ extern struct timeval double_to_timeval(double t); // Return > 0 if tv_a > tv_b, 0 if equal, < 0 if tv_a < tv_b. extern int time_compare(struct timeval* tv_a, struct timeval* tv_b); +// Returns the CPU time consumed to date. +extern double curr_CPU_time(); + // Returns an integer that's very likely to be unique, even across Zeek // instances. The integer can be drawn from different pools, which is helpful // when the random number generator is seeded to be deterministic. In that diff --git a/src/zeek-setup.cc b/src/zeek-setup.cc index 7a6b048571..226e5c8188 100644 --- a/src/zeek-setup.cc +++ b/src/zeek-setup.cc @@ -193,9 +193,9 @@ zeek::detail::trigger::Manager* zeek::detail::trigger_mgr = nullptr; std::vector zeek::detail::zeek_script_prefixes; zeek::detail::Stmt* zeek::detail::stmts = nullptr; zeek::EventRegistry* zeek::event_registry = nullptr; -zeek::detail::ProfileLogger* zeek::detail::profiling_logger = nullptr; -zeek::detail::ProfileLogger* zeek::detail::segment_logger = nullptr; -zeek::detail::SampleLogger* zeek::detail::sample_logger = nullptr; +std::shared_ptr zeek::detail::profiling_logger; +std::shared_ptr zeek::detail::segment_logger; +std::shared_ptr zeek::detail::sample_logger; zeek::detail::FragmentManager* zeek::detail::fragment_mgr = nullptr; @@ -378,8 +378,6 @@ static void terminate_zeek() // the termination process. file_mgr->Terminate(); - script_coverage_mgr.WriteStats(); - if ( zeek_done ) event_mgr.Enqueue(zeek_done, Args{}); @@ -403,8 +401,6 @@ static void terminate_zeek() // allocation code when killing Zeek. Disabling this for now. if ( ! (signal_val == SIGTERM || signal_val == SIGINT) ) profiling_logger->Log(); - - delete profiling_logger; } event_mgr.Drain(); @@ -421,6 +417,8 @@ static void terminate_zeek() finish_script_execution(); + script_coverage_mgr.WriteStats(); + delete zeekygen_mgr; delete packet_mgr; delete analyzer_mgr; @@ -976,7 +974,8 @@ SetupResult setup(int argc, char** argv, Options* zopts) if ( profiling_interval > 0 ) { const auto& profiling_file = id::find_val("profiling_file"); - profiling_logger = new ProfileLogger(profiling_file->AsFile(), profiling_interval); + profiling_logger = std::make_shared(profiling_file->AsFile(), + profiling_interval); if ( segment_profiling ) segment_logger = profiling_logger; diff --git a/src/zeek.bif b/src/zeek.bif index 07bfdf6e94..a1fc14b26c 100644 --- a/src/zeek.bif +++ b/src/zeek.bif @@ -2064,6 +2064,25 @@ function global_ids%(%): id_table return ids; %} +## Returns a set giving the names of all global options. +function global_options%(%): string_set + %{ + auto options = make_intrusive(zeek::id::string_set); + const auto& globals = zeek::detail::global_scope()->Vars(); + + for ( const auto& global : globals ) + { + const auto& id = global.second; + if ( ! id->IsOption() ) + continue; + + auto id_name = zeek::make_intrusive(id->Name()); + options->Assign(std::move(id_name), nullptr); + } + + return options; + %} + ## Returns the value of a global identifier. ## ## id: The global identifier. diff --git a/testing/btest/Baseline/coverage.coverage-blacklist/output b/testing/btest/Baseline/coverage.coverage-blacklist/output index d2f62a4a6d..c0cb3e558c 100644 --- a/testing/btest/Baseline/coverage.coverage-blacklist/output +++ b/testing/btest/Baseline/coverage.coverage-blacklist/output @@ -1,6 +1,10 @@ ### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. 1 <...>/coverage-blacklist.zeek, line 13 print cover me; +1 <...>/coverage-blacklist.zeek, line 15 if (T) { print always executed; } 1 <...>/coverage-blacklist.zeek, line 17 print always executed; +1 <...>/coverage-blacklist.zeek, line 22 if (0 + 0 == 1) print impossible; +1 <...>/coverage-blacklist.zeek, line 24 if (1 == 0) { print also impossible, but included in code coverage analysis; } 0 <...>/coverage-blacklist.zeek, line 26 print also impossible, but included in code coverage analysis; 1 <...>/coverage-blacklist.zeek, line 29 print success; 1 <...>/coverage-blacklist.zeek, line 5 print first; +1 <...>/coverage-blacklist.zeek, line 7 if (F) { print hello; print world; } diff --git a/testing/btest/Baseline/plugins.hooks/output b/testing/btest/Baseline/plugins.hooks/output index bc783d0971..d396d35ddf 100644 --- a/testing/btest/Baseline/plugins.hooks/output +++ b/testing/btest/Baseline/plugins.hooks/output @@ -679,7 +679,7 @@ 0.000000 MetaHookPost CallFunction(filter_change_tracking, , ()) -> 0.000000 MetaHookPost CallFunction(getenv, , (CLUSTER_NODE)) -> 0.000000 MetaHookPost CallFunction(getenv, , (ZEEK_DEFAULT_LISTEN_ADDRESS)) -> -0.000000 MetaHookPost CallFunction(global_ids, , ()) -> +0.000000 MetaHookPost CallFunction(global_options, , ()) -> 0.000000 MetaHookPost CallFunction(network_time, , ()) -> 0.000000 MetaHookPost CallFunction(port_to_count, , (2123/udp)) -> 0.000000 MetaHookPost CallFunction(port_to_count, , (2152/udp)) -> @@ -2136,7 +2136,7 @@ 0.000000 MetaHookPre CallFunction(filter_change_tracking, , ()) 0.000000 MetaHookPre CallFunction(getenv, , (CLUSTER_NODE)) 0.000000 MetaHookPre CallFunction(getenv, , (ZEEK_DEFAULT_LISTEN_ADDRESS)) -0.000000 MetaHookPre CallFunction(global_ids, , ()) +0.000000 MetaHookPre CallFunction(global_options, , ()) 0.000000 MetaHookPre CallFunction(network_time, , ()) 0.000000 MetaHookPre CallFunction(port_to_count, , (2123/udp)) 0.000000 MetaHookPre CallFunction(port_to_count, , (2152/udp)) @@ -3592,7 +3592,7 @@ 0.000000 | HookCallFunction filter_change_tracking() 0.000000 | HookCallFunction getenv(CLUSTER_NODE) 0.000000 | HookCallFunction getenv(ZEEK_DEFAULT_LISTEN_ADDRESS) -0.000000 | HookCallFunction global_ids() +0.000000 | HookCallFunction global_options() 0.000000 | HookCallFunction network_time() 0.000000 | HookCallFunction port_to_count(2123/udp) 0.000000 | HookCallFunction port_to_count(2152/udp)