Added cf-profile.py script for processing profiling output

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()

libpromises/eval_context.c

@@ -127,8 +127,13 @@
 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);
@@ -340,7 +345,7 @@
     for (size_t i = 0; i < SeqLength(ctx->stack); i++)
     {
         StackFrame *frame = LastStackFrame(ctx, i);
         if (frame->type == type)
         {
             return frame;
         }
@@ -349,6 +354,20 @@
     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 @@
     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 @@
 
     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 @@
     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 @@
     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 @@
     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 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 @@
     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,19 +4058,16 @@
 
     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);
 
     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 @@
     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 @@
     // 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);
-}
+}

libpromises/eval_context.h

@@ -47,6 +47,7 @@ typedef struct {
     char *filename;
     SourceOffset offset;
     int64_t elapsed;
+    char *stacktrace;
 } EventFrame;
 
 typedef enum