mirror of
https://github.com/zeek/zeek.git
synced 2025-10-14 04:28:20 +00:00
Merge remote-tracking branch 'origin/topic/vern/script-profiling'
* origin/topic/vern/script-profiling: tidy up after generating profile test suite updates for refined script coverage, use of new BiF to speed startup fix for coverage reporting for functions that use "when" statements new global_options() BiF to speed up startup, plus a micro-preen hooks for new --profile-scripts option classes for managing script profiles address some holes in script coverage fix for script coverage missing on-exit activity memory management fixes for loggers make curr_CPU_time() broadly available rather than just isolated to ZAM
This commit is contained in:
Tim Wojtulewicz
commit
8b0263cb39
22 changed files with 505 additions and 76 deletions
26
CHANGES
26
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)
|
||||
|
|
|
|||
2
VERSION
2
VERSION
|
|
@ -1 +1 @@
|
|||
5.0.0-dev.368
|
||||
5.0.0-dev.382
|
||||
|
|
|
|||
|
|
@ -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
|
||||
}
|
||||
|
|
|
|||
|
|
@ -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;
|
||||
|
||||
}
|
||||
|
|
|
|||
|
|
@ -330,6 +330,7 @@ set(MAIN_SRCS
|
|||
ScannedFile.cc
|
||||
Scope.cc
|
||||
ScriptCoverageManager.cc
|
||||
ScriptProfile.cc
|
||||
SerializationFormat.cc
|
||||
SmithWaterman.cc
|
||||
Stats.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);
|
||||
|
||||
|
|
|
|||
36
src/Func.cc
36
src/Func.cc
|
|
@ -5,18 +5,6 @@
|
|||
|
||||
#include "zeek/zeek-config.h"
|
||||
|
||||
#include <sys/stat.h>
|
||||
#include <sys/types.h>
|
||||
#ifdef TIME_WITH_SYS_TIME
|
||||
#include <sys/time.h>
|
||||
#include <time.h>
|
||||
#else
|
||||
#ifdef HAVE_SYS_TIME_H
|
||||
#include <sys/time.h>
|
||||
#else
|
||||
#include <time.h>
|
||||
#endif
|
||||
#endif
|
||||
#include <broker/error.hh>
|
||||
#include <ctype.h>
|
||||
#include <errno.h>
|
||||
|
|
@ -25,7 +13,6 @@
|
|||
#include <signal.h>
|
||||
#include <stdlib.h>
|
||||
#include <sys/param.h>
|
||||
#include <sys/resource.h>
|
||||
#include <unistd.h>
|
||||
#include <algorithm>
|
||||
|
||||
|
|
@ -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;
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -6,6 +6,7 @@
|
|||
|
||||
#include <unistd.h>
|
||||
|
||||
#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[=<speedup>] | 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 '?':
|
||||
|
|
|
|||
|
|
@ -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<zeek::detail::SampleLogger>();
|
||||
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;
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -127,27 +127,27 @@ bool ScriptCoverageManager::WriteStats()
|
|||
return false;
|
||||
}
|
||||
|
||||
for ( list<Stmt*>::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<string, string> 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<pair<string, string>, 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);
|
||||
|
|
|
|||
188
src/ScriptProfile.cc
Normal file
188
src/ScriptProfile.cc
Normal file
|
|
@ -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 = "<no-location>";
|
||||
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<const Func*, ScriptProfileStats> 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<no-location>\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<Obj*>(body.get()) : f;
|
||||
auto associated_prof = profiles.find(o);
|
||||
ScriptProfile* ep;
|
||||
|
||||
if ( associated_prof == profiles.end() )
|
||||
{
|
||||
auto new_ep = std::make_unique<ScriptProfile>(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<ScriptProfileMgr> 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<detail::ScriptProfileMgr>(f);
|
||||
}
|
||||
|
||||
} // namespace zeek
|
||||
184
src/ScriptProfile.h
Normal file
184
src/ScriptProfile.h
Normal file
|
|
@ -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 <string>
|
||||
|
||||
#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<ScriptProfile*> call_stack;
|
||||
|
||||
// Maps a given object (either a function body, for scripts, or the
|
||||
// function itself, for BiFs) to its profile.
|
||||
std::unordered_map<const Obj*, std::unique_ptr<ScriptProfile>> profiles;
|
||||
|
||||
// Maps script bodies to their function - used for functions with
|
||||
// multiple bodies.
|
||||
std::unordered_map<const Obj*, const Func*> body_to_func;
|
||||
|
||||
// Tracks the objects encountered. Used to generate a consistent
|
||||
// and more natural printing order.
|
||||
std::vector<const Obj*> objs;
|
||||
};
|
||||
|
||||
// If non-nil, script profiling is active.
|
||||
extern std::unique_ptr<ScriptProfileMgr> 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
|
||||
17
src/Stats.h
17
src/Stats.h
|
|
@ -8,6 +8,7 @@
|
|||
#include <sys/resource.h>
|
||||
#include <sys/time.h>
|
||||
#include <sys/types.h>
|
||||
#include <memory>
|
||||
|
||||
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<SegmentStatsReporter> 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<SegmentStatsReporter> 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<SegmentStatsReporter> 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<ProfileLogger> profiling_logger;
|
||||
extern std::shared_ptr<ProfileLogger> segment_logger;
|
||||
extern std::shared_ptr<SampleLogger> sample_logger;
|
||||
|
||||
// Connection statistics.
|
||||
extern uint64_t killed_by_inactivity;
|
||||
|
|
|
|||
|
|
@ -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<ValPtr>& vals)
|
|||
|
||||
ValPtr PrintStmt::DoExec(std::vector<ValPtr> vals, StmtFlowType& /* flow */)
|
||||
{
|
||||
RegisterAccess();
|
||||
do_print_stmt(vals);
|
||||
return nullptr;
|
||||
}
|
||||
|
|
|
|||
|
|
@ -1665,28 +1665,33 @@ stmt:
|
|||
{
|
||||
set_location(@1, @4);
|
||||
$$ = new IfStmt({AdoptRef{}, $3}, {AdoptRef{}, $5}, make_intrusive<NullStmt>());
|
||||
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
|
||||
|
|
|
|||
|
|
@ -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;
|
||||
}
|
||||
|
|
|
|||
|
|
@ -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) { }
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -193,9 +193,9 @@ zeek::detail::trigger::Manager* zeek::detail::trigger_mgr = nullptr;
|
|||
std::vector<std::string> 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::ProfileLogger> zeek::detail::profiling_logger;
|
||||
std::shared_ptr<zeek::detail::ProfileLogger> zeek::detail::segment_logger;
|
||||
std::shared_ptr<zeek::detail::SampleLogger> 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<ProfileLogger>(profiling_file->AsFile(),
|
||||
profiling_interval);
|
||||
|
||||
if ( segment_profiling )
|
||||
segment_logger = profiling_logger;
|
||||
|
|
|
|||
19
src/zeek.bif
19
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::TableVal>(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<zeek::StringVal>(id->Name());
|
||||
options->Assign(std::move(id_name), nullptr);
|
||||
}
|
||||
|
||||
return options;
|
||||
%}
|
||||
|
||||
## Returns the value of a global identifier.
|
||||
##
|
||||
## id: The global identifier.
|
||||
|
|
|
|||
|
|
@ -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; }
|
||||
|
|
|
|||
|
|
@ -679,7 +679,7 @@
|
|||
0.000000 MetaHookPost CallFunction(filter_change_tracking, <null>, ()) -> <no result>
|
||||
0.000000 MetaHookPost CallFunction(getenv, <null>, (CLUSTER_NODE)) -> <no result>
|
||||
0.000000 MetaHookPost CallFunction(getenv, <null>, (ZEEK_DEFAULT_LISTEN_ADDRESS)) -> <no result>
|
||||
0.000000 MetaHookPost CallFunction(global_ids, <frame>, ()) -> <no result>
|
||||
0.000000 MetaHookPost CallFunction(global_options, <frame>, ()) -> <no result>
|
||||
0.000000 MetaHookPost CallFunction(network_time, <frame>, ()) -> <no result>
|
||||
0.000000 MetaHookPost CallFunction(port_to_count, <frame>, (2123/udp)) -> <no result>
|
||||
0.000000 MetaHookPost CallFunction(port_to_count, <frame>, (2152/udp)) -> <no result>
|
||||
|
|
@ -2136,7 +2136,7 @@
|
|||
0.000000 MetaHookPre CallFunction(filter_change_tracking, <null>, ())
|
||||
0.000000 MetaHookPre CallFunction(getenv, <null>, (CLUSTER_NODE))
|
||||
0.000000 MetaHookPre CallFunction(getenv, <null>, (ZEEK_DEFAULT_LISTEN_ADDRESS))
|
||||
0.000000 MetaHookPre CallFunction(global_ids, <frame>, ())
|
||||
0.000000 MetaHookPre CallFunction(global_options, <frame>, ())
|
||||
0.000000 MetaHookPre CallFunction(network_time, <frame>, ())
|
||||
0.000000 MetaHookPre CallFunction(port_to_count, <frame>, (2123/udp))
|
||||
0.000000 MetaHookPre CallFunction(port_to_count, <frame>, (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)
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue