diff --git a/cf-agent/cf-agent.c b/cf-agent/cf-agent.c index a5b7e73da1..f95956c61e 100644 --- a/cf-agent/cf-agent.c +++ b/cf-agent/cf-agent.c @@ -327,7 +327,7 @@ int main(int argc, char *argv[]) EvalContextProfilingStart(ctx); KeepPromises(ctx, policy, config); - EvalContextProfilingEnd(ctx, policy); + EvalContextProfilingEnd(ctx); if (EvalAborted(ctx)) { diff --git a/contrib/cf-profile/cf-profile.py b/contrib/cf-profile/cf-profile.py new file mode 100644 index 0000000000..78e7c7a70b --- /dev/null +++ b/contrib/cf-profile/cf-profile.py @@ -0,0 +1,149 @@ +from argparse import ArgumentParser +import sys +import json +import re +from collections import defaultdict + +""" +This script parses profiling output from cf-agent and lists policy bundles, promises, and functions sorted by execution time. + +Usage: + $ sudo /var/cfengine/cf-agent -Kp > profiling_output.json + $ cat profiling_output.json | python3 cf-profile.py --bundles --promises --functions + +To generate a flamegraph: + $ cat profiling_output.json | python3 cf-profile.py --flamegraph callstack.txt + $ ./flamegraph.pl callstack.txt > flamegraph.svg +""" + + +def parse_args(): + parser = ArgumentParser() + + parser.add_argument("--top", type=int, default=10) + parser.add_argument("--bundles", action="store_true") + parser.add_argument("--promises", action="store_true") + parser.add_argument("--functions", action="store_true") + parser.add_argument("--flamegraph", type=str, default="callstack.txt") + + return parser.parse_args() + + +def format_elapsed_time(elapsed_ns): + elapsed_ms = float(elapsed_ns) / 1e6 + + if elapsed_ms < 1000: + return "%.2f ms" % elapsed_ms + elif elapsed_ms < 60000: + elapsed_s = elapsed_ms / 1000.0 + return "%.2fs" % elapsed_s + else: + elapsed_s = elapsed_ms / 1000.0 + minutes = int(elapsed_s // 60) + seconds = int(elapsed_s % 60) + return "%dm%ds" % (minutes, seconds) + + +def format_label(component, event_type, ns, name): + if component == "function": + return "%s %s" % (component, name) + elif event_type == "methods": + return "bundle invocation" + elif component == "promise": + return "%s %s" % (component, event_type) + else: + return "%s %s %s:%s" % (component, event_type, ns, name) + + +def format_columns(events, top): + + labels = [] + + for event in events[:top]: + label = format_label( + event["component"], event["type"], event["namespace"], event["name"] + ) + location = "%s:%s" % (event["source"], event["offset"]["line"]) + time = format_elapsed_time(event["elapsed"]) + + labels.append((label, location, time)) + + return labels + + +def get_max_column_lengths(lines, indent=4): + + max_type, max_location, max_time = 0, 0, 0 + + for label, location, time_ms in lines: + max_type = max(max_type, len(label)) + max_location = max(max_location, len(location)) + max_time = max(max_time, len(time_ms)) + + return max_type + indent, max_location + indent, max_time + indent + + +def profile(events, args): + + filter = defaultdict(list) + + if args.bundles: + filter["component"].append("bundle") + filter["type"].append("methods") + + if args.promises: + filter["type"] += list( + set( + event["type"] + for event in events + if event["component"] == "promise" and event["type"] != "methods" + ) + ) + + if args.functions: + filter["component"].append("function") + + print(filter) + + # filter events + if filter is not None: + events = [ + event + for field in filter.keys() + for event in events + if event[field] in filter[field] + ] + + # sort events + events = sorted(events, key=lambda x: x["elapsed"], reverse=True) + + lines = format_columns(events, args.top) + line_format = "%-{}s %-{}s %{}s".format(*get_max_column_lengths(lines)) + + # print top k filtered events + print(line_format % ("Type", "Location", "Time")) + for label, location, time_ms in lines: + print(line_format % (label, location, time_ms)) + + +def generate_callstacks(data, stack_path): + + with open(stack_path, "w") as f: + for event in data: + f.write("%s %d\n" % (event["callstack"], event["elapsed"])) + + +def main(): + args = parse_args() + m = re.search(r"\[[.\s\S]*\]", sys.stdin.read()) + data = json.loads(m.group(0)) + + if any([args.bundles, args.functions, args.promises]): + profile(data, args) + + if args.flamegraph: + generate_callstacks(data, args.flamegraph) + + +if __name__ == "__main__": + main() diff --git a/libpromises/eval_context.c b/libpromises/eval_context.c index a611e28c09..acd851491d 100644 --- a/libpromises/eval_context.c +++ b/libpromises/eval_context.c @@ -127,11 +127,7 @@ static bool EvalContextClassPut(EvalContext *ctx, const char *ns, const char *na static const char *EvalContextCurrentNamespace(const EvalContext *ctx); static ClassRef IDRefQualify(const EvalContext *ctx, const char *id); -static EventFrame *EventFrameCreate(char *type, const char *name, const char *source, SourceOffset offset); static void EventFrameDestroy(EventFrame *event); -static EventFrame *BundleToEventFrame(const Bundle *bp); -static EventFrame *PromiseToEventFrame(const Promise *pp); -static EventFrame *FunctionToEventFrame(const FnCall *fp); /** * Every agent has only one EvalContext from process start to finish. @@ -201,11 +197,8 @@ struct EvalContext_ /* These are needed for policy profiling */ bool profiling; - - struct { - int64_t elapsed; - Seq *events; - } profiler; + int64_t elapsed; + Seq *events; EvalOrder common_eval_order; EvalOrder agent_eval_order; @@ -349,6 +342,21 @@ static StackFrame *LastStackFrameByType(const EvalContext *ctx, StackFrameType t return NULL; } +static StackFrame *LastStackFrameByEvent(const EvalContext *ctx) +{ + assert(ctx != NULL); + for (size_t i = 0; i < SeqLength(ctx->stack); i++) + { + StackFrame *frame = LastStackFrame(ctx, i); + if (frame->event != NULL) + { + return frame; + } + } + + return NULL; +} + static LogLevel AdjustLogLevel(LogLevel base, LogLevel adjust) { if (adjust == -1) @@ -1110,8 +1118,8 @@ EvalContext *EvalContextNew(void) ctx->dump_reports = false; - ctx->profiler.events = SeqNew(20, EventFrameDestroy); - ctx->profiler.elapsed = 0; + ctx->events = SeqNew(20, EventFrameDestroy); + ctx->elapsed = 0; // evaluation order ctx->common_eval_order = EVAL_ORDER_UNDEFINED; @@ -1164,7 +1172,7 @@ void EvalContextDestroy(EvalContext *ctx) ctx->remote_var_promises = NULL; } - SeqDestroy(ctx->profiler.events); + SeqDestroy(ctx->events); free(ctx); } } @@ -1349,20 +1357,19 @@ static StackFrame *StackFrameNew(StackFrameType type, bool inherit_previous) frame->inherits_previous = inherit_previous; frame->path = NULL; frame->override_immutable = false; - frame->start = EvalContextEventStart(); frame->event = NULL; return frame; } -static StackFrame *StackFrameNewBundle(const Bundle *owner, bool inherit_previous, bool profiling) +static StackFrame *StackFrameNewBundle(const Bundle *owner, bool inherit_previous, bool profiling, EventFrame *prev_event) { StackFrame *frame = StackFrameNew(STACK_FRAME_TYPE_BUNDLE, inherit_previous); frame->data.bundle.owner = owner; frame->data.bundle.classes = ClassTableNew(); frame->data.bundle.vars = VariableTableNew(); - frame->event = (profiling) ? BundleToEventFrame(owner) : NULL; + frame->event = (profiling) ? BundleToEventFrame(owner, prev_event) : NULL; return frame; } @@ -1386,12 +1393,12 @@ static StackFrame *StackFrameNewBundleSection(const BundleSection *owner) return frame; } -static StackFrame *StackFrameNewPromise(const Promise *owner, bool profiling) +static StackFrame *StackFrameNewPromise(const Promise *owner, bool profiling, EventFrame *prev_event) { StackFrame *frame = StackFrameNew(STACK_FRAME_TYPE_PROMISE, true); frame->data.promise.owner = owner; - frame->event = (profiling) ? PromiseToEventFrame(owner) : NULL; + frame->event = (profiling) ? PromiseToEventFrame(owner, prev_event) : NULL; return frame; } @@ -1443,7 +1450,8 @@ void EvalContextStackPushBundleFrame(EvalContext *ctx, const Bundle *owner, cons assert(ctx != NULL); assert(!LastStackFrame(ctx, 0) || LastStackFrame(ctx, 0)->type == STACK_FRAME_TYPE_PROMISE_ITERATION); - EvalContextStackPushFrame(ctx, StackFrameNewBundle(owner, inherits_previous, ctx->profiling)); + StackFrame *frame = StackFrameNewBundle(owner, inherits_previous, ctx->profiling, EvalContextGetLastEventFrame(ctx)); + EvalContextStackPushFrame(ctx, frame); if (RlistLen(args) > 0) { @@ -1523,8 +1531,7 @@ void EvalContextStackPushPromiseFrame(EvalContext *ctx, const Promise *owner) EvalContextVariableClearMatch(ctx); - StackFrame *frame = StackFrameNewPromise(owner, ctx->profiling); - + StackFrame *frame = StackFrameNewPromise(owner, ctx->profiling, EvalContextGetLastEventFrame(ctx)); EvalContextStackPushFrame(ctx, frame); // create an empty table @@ -1615,15 +1622,11 @@ void EvalContextStackPopFrame(EvalContext *ctx) StackFrame *last_frame = LastStackFrame(ctx, 0); StackFrameType last_frame_type = last_frame->type; - int64_t start = last_frame->start; - int64_t end = EvalContextEventStart(); EventFrame *last_event = last_frame->event; if (last_event != NULL) { - assert(end >= start); /* sanity check */ - last_event->elapsed = end - start; - SeqAppend(ctx->profiler.events, last_event); + EvalContextAppendEventFrame(ctx, last_event); } switch (last_frame_type) @@ -3892,22 +3895,40 @@ bool EvalContextOverrideImmutableGet(EvalContext *ctx) // ############################################################## -void EvalContextSetProfiling(EvalContext *ctx, bool profiling) +static int64_t EvalContextEventStart() { - assert(ctx != NULL); - ctx->profiling = profiling; + struct timespec ts; +#ifdef CLOCK_MONOTONIC + clock_gettime(CLOCK_MONOTONIC, &ts); +#else +// As in libcfnet/net.c some OS-es don't have monotonic clock, realtime clock is best we can do. + clock_gettime(CLOCK_REALTIME, &ts); +#endif + return ts.tv_sec * 1000000000LL + ts.tv_nsec; } -static EventFrame *EventFrameCreate(char *type, const char *name, const char *source, SourceOffset offset) +static EventFrame *EventFrameCreate(const char *source, + char *component, + char *type, + const char *ns, + const char *name, + SourceOffset offset, + EventFrame *prev, + char *id + ) { EventFrame *event = (EventFrame *) xmalloc(sizeof(EventFrame)); + event->elapsed = EvalContextEventStart(); + event->source = GetAbsolutePath(source); + event->component = component; event->type = type; + event->ns = SafeStringDuplicate(ns); event->name = SafeStringDuplicate(name); - event->filename = GetAbsolutePath(source); - event->elapsed = 0; event->offset = offset; - event->id = StringFormat("%s_%s_%s_%ld_%ld", type, name, source, offset.start, offset.line); + + event->id = id; + event->callstack = (prev != NULL) ? StringFormat("%s;%s", prev->callstack, event->id) : SafeStringDuplicate(event->id); return event; } @@ -3916,9 +3937,12 @@ static void EventFrameDestroy(EventFrame *event) { if (event != NULL) { - free(event->filename); - free(event->id); + free(event->source); + free(event->ns); free(event->name); + + free(event->id); + free(event->callstack); free(event); } } @@ -3928,11 +3952,14 @@ static JsonElement *EventToJson(EventFrame *event) assert(event != NULL); JsonElement *json_event = JsonObjectCreate(10); + JsonObjectAppendString(json_event, "component", event->component); JsonObjectAppendString(json_event, "type", event->type); JsonObjectAppendString(json_event, "name", event->name); - JsonObjectAppendString(json_event, "filename", event->filename); + JsonObjectAppendString(json_event, "namespace", event->ns); + JsonObjectAppendString(json_event, "source", event->source); JsonObjectAppendString(json_event, "id", event->id); JsonObjectAppendInteger64(json_event, "elapsed", event->elapsed); + JsonObjectAppendString(json_event, "callstack", event->callstack); JsonElement *offset = JsonObjectCreate(4); JsonObjectAppendInteger(offset, "start", event->offset.start); @@ -3945,81 +3972,46 @@ static JsonElement *EventToJson(EventFrame *event) return json_event; } -static EventFrame *BundleToEventFrame(const Bundle *bp) +EventFrame *BundleToEventFrame(const Bundle *bp, EventFrame *prev_frame) { assert(bp != NULL); - return EventFrameCreate("bundle", bp->name, bp->source_path, bp->offset); + char *id = StringFormat("%s:%ld/%s_%s_%s:%s", GetAbsolutePath(bp->source_path), bp->offset.line, "bundle", bp->type, bp->ns, bp->name); + return EventFrameCreate(bp->source_path, "bundle", bp->type, bp->ns, bp->name, bp->offset, prev_frame, id); } -static EventFrame *PromiseToEventFrame(const Promise *pp) +EventFrame *PromiseToEventFrame(const Promise *pp, EventFrame *prev_frame) { assert(pp != NULL); - return EventFrameCreate("promise", PromiseGetPromiseType(pp), PromiseGetBundle(pp)->source_path, pp->offset); + char *id = StringFormat("%s:%ld/%s_%s", PromiseGetBundle(pp)->source_path, pp->offset.line, "promise", pp->parent_section->promise_type); + return EventFrameCreate(PromiseGetBundle(pp)->source_path, "promise", pp->parent_section->promise_type, "x", "x", pp->offset, prev_frame, id); } -static EventFrame *FunctionToEventFrame(const FnCall *fp) +EventFrame *FunctionToEventFrame(const FnCall *fp, EventFrame *prev_frame) { assert(fp != NULL); - return EventFrameCreate("function", fp->name, PromiseGetBundle(fp->caller)->source_path, fp->caller->offset); + char *id = StringFormat("%s:%ld/%s_%s", PromiseGetBundle(fp->caller)->source_path, fp->caller->offset.line, "function", fp->name); + return EventFrameCreate(PromiseGetBundle(fp->caller)->source_path, "function", "x", "x", fp->name, fp->caller->offset, prev_frame, id); } -void EvalContextAddFunctionEvent(EvalContext *ctx, const FnCall *fp, int64_t start) +void EvalContextSetProfiling(EvalContext *ctx, bool profiling) { assert(ctx != NULL); - if (ctx->profiling) - { - EventFrame *event = FunctionToEventFrame(fp); - int64_t end = EvalContextEventStart(); - assert(end >= start); /* sanity check */ - event->elapsed = end - start; - SeqAppend(ctx->profiler.events, event); - } + ctx->profiling = profiling; } -int64_t EvalContextEventStart() +bool EvalContextGetProfiling(EvalContext *ctx) { - struct timespec ts; -#ifdef CLOCK_MONOTONIC - clock_gettime(CLOCK_MONOTONIC, &ts); -#else -// As in libcfnet/net.c some OS-es don't have monotonic clock, realtime clock is best we can do. - clock_gettime(CLOCK_REALTIME, &ts); -#endif - return ts.tv_sec * 1000000000LL + ts.tv_nsec; + assert(ctx != NULL); + return ctx->profiling; } void EvalContextProfilingStart(EvalContext *ctx) { assert(ctx != NULL); - ctx->profiler.elapsed = EvalContextEventStart(); -} - -static HashMap *SumEventFrames(Seq *events) -{ - HashMap *map = HashMapNew((MapHashFn) StringHash, (MapKeyEqualFn) StringEqual, NULL, NULL, 10); - - size_t length = SeqLength(events); - EventFrame *curr; - EventFrame *prev; - MapKeyValue *mkv; - for (int i = 0; i < length; i++) - { - curr = SeqAt(events, i); - mkv = HashMapGet(map, curr->id); - - if (mkv == NULL) - { - HashMapInsert(map, curr->id, curr); - continue; - } - prev = mkv->value; - prev->elapsed += curr->elapsed; - } - - return map; + ctx->elapsed = EvalContextEventStart(); } -void EvalContextProfilingEnd(EvalContext *ctx, const Policy *policy) +void EvalContextProfilingEnd(EvalContext *ctx) { assert(ctx != NULL); @@ -4029,35 +4021,51 @@ void EvalContextProfilingEnd(EvalContext *ctx, const Policy *policy) } int64_t end = EvalContextEventStart(); - int64_t start = ctx->profiler.elapsed; + int64_t start = ctx->elapsed; assert(end >= start); /* sanity check */ - ctx->profiler.elapsed = end - start; - - HashMap *map = SumEventFrames(ctx->profiler.events); - JsonElement *profiling = JsonObjectCreate(2); - - JsonElement *json_policy = PolicyToJson(policy); - JsonObjectAppendObject(profiling, "policy", json_policy); + ctx->elapsed = end - start; JsonElement *events = JsonArrayCreate(10); { - HashMapIterator iter = HashMapIteratorInit(map); - MapKeyValue *mkv; - while ((mkv = HashMapIteratorNext(&iter)) != NULL) + for (size_t i = 0; i < SeqLength(ctx->events); i++) { - EventFrame *event = mkv->value; + EventFrame *event = SeqAt(ctx->events, i); JsonArrayAppendObject(events, EventToJson(event)); } } - JsonObjectAppendArray(profiling, "events", events); - // write Writer *writer = FileWriter(stdout); - JsonWrite(writer, profiling, 2); + JsonWrite(writer, events, 2); WriterClose(writer); - JsonDestroy(profiling); + JsonDestroy(events); +} + +EventFrame *EvalContextGetLastEventFrame(EvalContext *ctx) +{ + StackFrame *frame = LastStackFrameByEvent(ctx); + + if (frame == NULL) + { + return NULL; + } + + return frame->event; +} + +void EvalContextAppendEventFrame(EvalContext *ctx, EventFrame *event) +{ + assert(ctx != NULL); + assert(event != NULL); + + int64_t start = event->elapsed; + int64_t end = EvalContextEventStart(); + assert(end >= start); /* sanity check */ + + event->elapsed = end - start; + + SeqAppend(ctx->events, event); } // ############################################################## @@ -4127,4 +4135,4 @@ bool EvalContextIsClassicOrder(EvalContext *ctx, const Bundle *bp) // The fallback is to use what is defined in body common control, // or if not defined there either, default to true (normal order) return (ctx->common_eval_order != EVAL_ORDER_TOP_DOWN); -} +} \ No newline at end of file diff --git a/libpromises/eval_context.h b/libpromises/eval_context.h index 5ddff4fa76..c42bc8a8a3 100644 --- a/libpromises/eval_context.h +++ b/libpromises/eval_context.h @@ -41,12 +41,17 @@ #include typedef struct { - char *id; + char *source; char *type; + char *component; + char *ns; char *name; - char *filename; - SourceOffset offset; + + char *id; + char *callstack; + int64_t elapsed; + SourceOffset offset; } EventFrame; typedef enum @@ -110,7 +115,6 @@ typedef struct char *path; bool override_immutable; - int64_t start; EventFrame *event; } StackFrame; @@ -444,13 +448,15 @@ void EvalContextSetDumpReports(EvalContext *ctx, bool dump_reports); bool EvalContextGetDumpReports(EvalContext *ctx); void EvalContextUpdateDumpReports(EvalContext *ctx); -int64_t EvalContextEventStart(); -void EvalContextAddFunctionEvent(EvalContext *ctx, const FnCall *fp, int64_t start); - void EvalContextSetProfiling(EvalContext *ctx, bool profiling); - +bool EvalContextGetProfiling(EvalContext *ctx); void EvalContextProfilingStart(EvalContext *ctx); -void EvalContextProfilingEnd(EvalContext *ctx, const Policy *policy); +void EvalContextProfilingEnd(EvalContext *ctx); +EventFrame *BundleToEventFrame(const Bundle *bp, EventFrame *prev_frame); +EventFrame *PromiseToEventFrame(const Promise *pp, EventFrame *prev_frame); +EventFrame *FunctionToEventFrame(const FnCall *fp, EventFrame *prev_frame); +EventFrame *EvalContextGetLastEventFrame(EvalContext *ctx); +void EvalContextAppendEventFrame(EvalContext *ctx, EventFrame *event); void EvalContextSetCommonEvalOrder(EvalContext *ctx, EvalOrder eval_order); void EvalContextSetAgentEvalOrder(EvalContext *ctx, EvalOrder eval_order); diff --git a/libpromises/fncall.c b/libpromises/fncall.c index 3bb3969837..c1b32b5f96 100644 --- a/libpromises/fncall.c +++ b/libpromises/fncall.c @@ -419,9 +419,12 @@ FnCallResult FnCallEvaluate(EvalContext *ctx, const Policy *policy, FnCall *fp, WriterClose(fncall_writer); } - int64_t start = EvalContextEventStart(); + EventFrame *event = (EvalContextGetProfiling(ctx)) ? FunctionToEventFrame(fp, EvalContextGetLastEventFrame(ctx)) : NULL; FnCallResult result = CallFunction(ctx, policy, fp, expargs); - EvalContextAddFunctionEvent(ctx, fp, start); + if (event != NULL) + { + EvalContextAppendEventFrame(ctx, event); + } if (result.status == FNCALL_FAILURE) {