diff --git a/contrib/cf-profile/cf-profile.py b/contrib/cf-profile/cf-profile.py new file mode 100644 index 0000000000..ff98c40f23 --- /dev/null +++ b/contrib/cf-profile/cf-profile.py @@ -0,0 +1,143 @@ +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 + $ python3 cf-profile.py profiling_output.json --bundles --promises --functions +""" + + +def parse_args(): + parser = ArgumentParser() + + # parser.add_argument("profiling_output") + 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", str="", default="stack.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(event_type, name): + if event_type == "function": + return "%s() %s call" % (name, event_type) + elif name == "methods": + return "bundle invocation" + else: + return "%s %s" % (name, event_type) + + +def format_columns(events, top): + + labels = [] + + for event in events[:top]: + label = format_label(event["type"], event["name"]) + location = "%s:%s" % (event["filename"], 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(data, args): + + events = data["events"] + filter = defaultdict(list) + + if args.bundles: + filter["type"].append("bundle") + filter["name"].append("methods") + + if args.promises: + filter["name"] += list( + set( + event["name"] + for event in events + if event["type"] == "promise" and event["name"] != "methods" + ) + ) + + if args.functions: + filter["type"].append("function") + + # 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): + events = data["events"] + + with open(stack_path, "w") as f: + for event in events: + f.write("%s %d\n" % (event["callstack"], event["elapsed"])) + +def main(): + args = parse_args() + m = re.search(r"\{[.\s\S]*\}", sys.stdin.read()) + # with open(args.profiling_output, "r") as f: + # data = json.load(f) + data = json.loads(m.group(0)) + + + if args.flamegraph: + generate_callstacks(data, args.flamegraph) + else: + profile(data, args) + + + +if __name__ == "__main__": + main() diff --git a/libpromises/eval_context.c b/libpromises/eval_context.c index f498df4a49..a7d957fb86 100644 --- a/libpromises/eval_context.c +++ b/libpromises/eval_context.c @@ -127,8 +127,13 @@ 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 EventFrame *EventFrameCreate(char *type, const char *name, const char *source, SourceOffset offset, char *id); static void EventFrameDestroy(EventFrame *event); + +static char *BundleGetCallStackID(const Bundle *bp); +static char *PromiseGetCallStackID(const Promise *pp); +static char *FunctionGetCallStackID(const FnCall *fp); + static EventFrame *BundleToEventFrame(const Bundle *bp); static EventFrame *PromiseToEventFrame(const Promise *pp); static EventFrame *FunctionToEventFrame(const FnCall *fp); @@ -349,6 +354,20 @@ static StackFrame *LastStackFrameByType(const EvalContext *ctx, StackFrameType t return NULL; } +static StackFrame *LastStackFrameByEvent(const EvalContext *ctx) +{ + 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) @@ -1443,7 +1462,22 @@ 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 *prev_frame = LastStackFrameByEvent(ctx); + StackFrame *frame = StackFrameNewBundle(owner, inherits_previous, ctx->profiling); + + EventFrame *pushed_event = frame->event; + EvalContextStackPushFrame(ctx, frame); + if (pushed_event != NULL) + { + if (prev_frame == NULL || prev_frame->event == NULL) + { + pushed_event->stacktrace = SafeStringDuplicate(pushed_event->id); + } + else + { + pushed_event->stacktrace = StringFormat("%s;%s", prev_frame->event->stacktrace, pushed_event->id); + } + } if (RlistLen(args) > 0) { @@ -1523,9 +1557,22 @@ void EvalContextStackPushPromiseFrame(EvalContext *ctx, const Promise *owner) EvalContextVariableClearMatch(ctx); + StackFrame *prev_frame = LastStackFrameByEvent(ctx); StackFrame *frame = StackFrameNewPromise(owner, ctx->profiling); EvalContextStackPushFrame(ctx, frame); + EventFrame *pushed_event = frame->event; + if (pushed_event != NULL) + { + if (prev_frame == NULL || prev_frame->event == NULL) + { + pushed_event->stacktrace = SafeStringDuplicate(pushed_event->id); + } + else + { + pushed_event->stacktrace = StringFormat("%s;%s", prev_frame->event->stacktrace, pushed_event->id); + } + } // create an empty table frame->data.promise.vars = VariableTableNew(); @@ -3898,7 +3945,7 @@ void EvalContextSetProfiling(EvalContext *ctx, bool profiling) ctx->profiling = profiling; } -static EventFrame *EventFrameCreate(char *type, const char *name, const char *source, SourceOffset offset) +static EventFrame *EventFrameCreate(char *type, const char *name, const char *source, SourceOffset offset, char *id) { EventFrame *event = (EventFrame *) xmalloc(sizeof(EventFrame)); @@ -3907,7 +3954,8 @@ static EventFrame *EventFrameCreate(char *type, const char *name, const char *so 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->stacktrace = ""; return event; } @@ -3933,6 +3981,7 @@ static JsonElement *EventToJson(EventFrame *event) JsonObjectAppendString(json_event, "filename", event->filename); JsonObjectAppendString(json_event, "id", event->id); JsonObjectAppendInteger64(json_event, "elapsed", event->elapsed); + JsonObjectAppendString(json_event, "callstack", event->stacktrace); JsonElement *offset = JsonObjectCreate(4); JsonObjectAppendInteger(offset, "start", event->offset.start); @@ -3948,19 +3997,19 @@ static JsonElement *EventToJson(EventFrame *event) static EventFrame *BundleToEventFrame(const Bundle *bp) { assert(bp != NULL); - return EventFrameCreate("bundle", bp->name, bp->source_path, bp->offset); + return EventFrameCreate("bundle", bp->name, bp->source_path, bp->offset, BundleGetCallStackID(bp)); } static EventFrame *PromiseToEventFrame(const Promise *pp) { assert(pp != NULL); - return EventFrameCreate("promise", PromiseGetPromiseType(pp), PromiseGetBundle(pp)->source_path, pp->offset); + return EventFrameCreate("promise", PromiseGetPromiseType(pp), PromiseGetBundle(pp)->source_path, pp->offset, PromiseGetCallStackID(pp)); } static EventFrame *FunctionToEventFrame(const FnCall *fp) { assert(fp != NULL); - return EventFrameCreate("function", fp->name, PromiseGetBundle(fp->caller)->source_path, fp->caller->offset); + return EventFrameCreate("function", fp->name, PromiseGetBundle(fp->caller)->source_path, fp->caller->offset, FunctionGetCallStackID(fp)); } void EvalContextAddFunctionEvent(EvalContext *ctx, const FnCall *fp, int64_t start) @@ -3994,31 +4043,6 @@ void EvalContextProfilingStart(EvalContext *ctx) 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; -} - void EvalContextProfilingEnd(EvalContext *ctx, const Policy *policy) { assert(ctx != NULL); @@ -4034,7 +4058,6 @@ void EvalContextProfilingEnd(EvalContext *ctx, const Policy *policy) ctx->profiler.elapsed = end - start; - HashMap *map = SumEventFrames(ctx->profiler.events); JsonElement *profiling = JsonObjectCreate(2); JsonElement *json_policy = PolicyToJson(policy); @@ -4042,11 +4065,9 @@ void EvalContextProfilingEnd(EvalContext *ctx, const Policy *policy) JsonElement *events = JsonArrayCreate(10); { - HashMapIterator iter = HashMapIteratorInit(map); - MapKeyValue *mkv; - while ((mkv = HashMapIteratorNext(&iter)) != NULL) + for (size_t i = 0; i < SeqLength(ctx->profiler.events); i++) { - EventFrame *event = mkv->value; + EventFrame *event = SeqAt(ctx->profiler.events, i); JsonArrayAppendObject(events, EventToJson(event)); } } @@ -4060,6 +4081,24 @@ void EvalContextProfilingEnd(EvalContext *ctx, const Policy *policy) JsonDestroy(profiling); } +static char *BundleGetCallStackID(const Bundle *bp) +{ + assert(bp != NULL); + return StringFormat("bundle_%s_%s:%s_%s:%ld_%ld-%ld", bp->type, bp->ns, bp->name, bp->source_path, bp->offset.line, bp->offset.start, bp->offset.end); +} + +static char *PromiseGetCallStackID(const Promise *pp) +{ + assert(pp != NULL); + return StringFormat("promise_%s_%ld_%ld-%ld", PromiseGetPromiseType(pp), pp->offset.line, pp->offset.start, pp->offset.end); +} + +static char *FunctionGetCallStackID(const FnCall *fp) +{ + assert(fp != NULL); + return StringFormat("function_%s_%ld_%ld-%ld", fp->name, fp->caller->offset.line, fp->caller->offset.start, fp->caller->offset.end); +} + // ############################################################## void EvalContextSetCommonEvalOrder(EvalContext *ctx, EvalContextEvalOrder eval_order) @@ -4094,4 +4133,4 @@ bool EvalContextIsClassicOrder(EvalContext *ctx) // 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 63b30e7611..36241da19b 100644 --- a/libpromises/eval_context.h +++ b/libpromises/eval_context.h @@ -47,6 +47,7 @@ typedef struct { char *filename; SourceOffset offset; int64_t elapsed; + char *stacktrace; } EventFrame; typedef enum