Implemented policy profiler in cf-agent

Changelog: The policy profiling logic is now implemented natively within the cf-agent, replacing the previous reliance on cf-agent logs and the cf-profile.pl script for faster execution.
Ticket: ENT-8096
Signed-off-by: Victor Moene <victor.moene@northern.tech>

Author: victormlg

cf-agent/cf-agent.c

@@ -209,6 +209,7 @@ static const struct option OPTIONS[] =
     {"color", optional_argument, 0, 'C'},
     {"no-extensions", no_argument, 0, 'E'},
     {"timestamp", no_argument, 0, 'l'},
+    {"profile", no_argument, 0, 'p'},
     /* Only long option for the rest */
     {"ignore-preferred-augments", no_argument, 0, 0},
     {"log-modules", required_argument, 0, 0},
@@ -245,6 +246,7 @@ static const char *const HINTS[] =
     "Enable colorized output. Possible values: 'always', 'auto', 'never'. If option is used, the default value is 'auto'",
     "Disable extension loading (used while upgrading)",
     "Log timestamps on each line of log output",
+    "Output diagnostic of bundle execution",
     "Ignore def_preferred.json file in favor of def.json",
     "Enable even more detailed debug logging for specific areas of the implementation. Use together with '-d'. Use --log-modules=help for a list of available modules",
     "Do not load augments (def.json)",
@@ -323,7 +325,9 @@ int main(int argc, char *argv[])
 
     BeginAudit();
 
+    EvalContextProfilingStart(ctx);
     KeepPromises(ctx, policy, config);
+    EvalContextProfilingEnd(ctx, policy);
 
     if (EvalAborted(ctx))
     {
@@ -523,7 +527,7 @@ static GenericAgentConfig *CheckOpts(int argc, char **argv)
     FreeFixedStringArray(argc_new, argv_tmp);
 
     int longopt_idx;
-    while ((c = getopt_long(argc_new, argv_new, "tdvnKIf:g:w:D:N:VxMB:b:hC::ElT::",
+    while ((c = getopt_long(argc_new, argv_new, "tdvnKIf:g:w:D:N:VxMB:b:hC::ElT::p",
                             OPTIONS, &longopt_idx))
            != -1)
     {
@@ -689,6 +693,9 @@ static GenericAgentConfig *CheckOpts(int argc, char **argv)
             }
 
             break;
+        case 'p':
+            config->profiling = true;
+            break;
 
         /* long options only */
         case 0:

libpromises/eval_context.c

@@ -127,6 +127,12 @@ 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.
  */
@@ -192,6 +198,14 @@ struct EvalContext_
     RemoteVarPromisesMap *remote_var_promises;
 
     bool dump_reports;
+
+    /* These are needed for policy profiling */
+    bool profiling;
+
+    struct {
+        int64_t elapsed;
+        Seq *events;
+    } profiler;
 };
 
 void EvalContextSetConfig(EvalContext *ctx, const GenericAgentConfig *config)
@@ -1093,6 +1107,9 @@ EvalContext *EvalContextNew(void)
 
     ctx->dump_reports = false;
 
+    ctx->profiler.events = SeqNew(20, EventFrameDestroy);
+    ctx->profiler.elapsed = 0;
+
     return ctx;
 }
 
@@ -1140,6 +1157,8 @@ void EvalContextDestroy(EvalContext *ctx)
             ctx->remote_var_promises = NULL;
         }
 
+        SeqDestroy(ctx->profiler.events);
+
         free(ctx);
     }
 }
@@ -1324,17 +1343,20 @@ 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)
+static StackFrame *StackFrameNewBundle(const Bundle *owner, bool inherit_previous, bool profiling)
 {
     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;
 
     return frame;
 }
@@ -1358,11 +1380,12 @@ static StackFrame *StackFrameNewBundleSection(const BundleSection *owner)
     return frame;
 }
 
-static StackFrame *StackFrameNewPromise(const Promise *owner)
+static StackFrame *StackFrameNewPromise(const Promise *owner, bool profiling)
 {
     StackFrame *frame = StackFrameNew(STACK_FRAME_TYPE_PROMISE, true);
 
     frame->data.promise.owner = owner;
+    frame->event = (profiling) ? PromiseToEventFrame(owner) : NULL;
 
     return frame;
 }
@@ -1411,9 +1434,10 @@ static void EvalContextStackPushFrame(EvalContext *ctx, StackFrame *frame)
 
 void EvalContextStackPushBundleFrame(EvalContext *ctx, const Bundle *owner, const Rlist *args, bool inherits_previous)
 {
+    assert(ctx != NULL);
     assert(!LastStackFrame(ctx, 0) || LastStackFrame(ctx, 0)->type == STACK_FRAME_TYPE_PROMISE_ITERATION);
 
-    EvalContextStackPushFrame(ctx, StackFrameNewBundle(owner, inherits_previous));
+    EvalContextStackPushFrame(ctx, StackFrameNewBundle(owner, inherits_previous, ctx->profiling));
 
     if (RlistLen(args) > 0)
     {
@@ -1487,12 +1511,13 @@ void EvalContextStackPushBundleSectionFrame(EvalContext *ctx, const BundleSectio
 
 void EvalContextStackPushPromiseFrame(EvalContext *ctx, const Promise *owner)
 {
+    assert(ctx != NULL);
     assert(LastStackFrame(ctx, 0));
     assert(LastStackFrame(ctx, 0)->type == STACK_FRAME_TYPE_BUNDLE_SECTION);
 
     EvalContextVariableClearMatch(ctx);
 
-    StackFrame *frame = StackFrameNewPromise(owner);
+    StackFrame *frame = StackFrameNewPromise(owner, ctx->profiling);
 
     EvalContextStackPushFrame(ctx, frame);
 
@@ -1579,10 +1604,21 @@ Promise *EvalContextStackPushPromiseIterationFrame(EvalContext *ctx, const Promi
 
 void EvalContextStackPopFrame(EvalContext *ctx)
 {
+    assert(ctx != NULL);
     assert(SeqLength(ctx->stack) > 0);
 
     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);
+    }
 
     switch (last_frame_type)
     {
@@ -3847,3 +3883,157 @@ bool EvalContextOverrideImmutableGet(EvalContext *ctx)
     assert(stack_frame != NULL);
     return stack_frame->override_immutable;
 }
+
+// ##############################################################
+
+void EvalContextSetProfiling(EvalContext *ctx, bool profiling)
+{
+    assert(ctx != NULL);
+    ctx->profiling = profiling;
+}
+
+static EventFrame *EventFrameCreate(char *type, const char *name, const char *source, SourceOffset offset)
+{
+    EventFrame *event = (EventFrame *) xmalloc(sizeof(EventFrame));
+
+    event->type = type;
+    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);
+
+    return event;
+}
+
+static void EventFrameDestroy(EventFrame *event)
+{
+    assert(event != NULL);
+    free(event->filename);
+    free(event->id);
+    free(event->name);
+    free(event);
+}
+
+static JsonElement *EventToJson(EventFrame *event)
+{
+    JsonElement *json_event = JsonObjectCreate(10);
+
+    JsonObjectAppendString(json_event, "type", event->type);
+    JsonObjectAppendString(json_event, "name", event->name);
+    JsonObjectAppendString(json_event, "filename", event->filename);
+    JsonObjectAppendString(json_event, "id", event->id);
+    JsonObjectAppendInteger64(json_event, "elapsed", event->elapsed);
+
+    JsonElement *offset = JsonObjectCreate(4);
+    JsonObjectAppendInteger(offset, "start", event->offset.start);
+    JsonObjectAppendInteger(offset, "end", event->offset.end);
+    JsonObjectAppendInteger(offset, "context", event->offset.context);
+    JsonObjectAppendInteger(offset, "line", event->offset.line);
+
+    JsonObjectAppendObject(json_event, "offset", offset);
+
+    return json_event;
+}
+
+static EventFrame *BundleToEventFrame(const Bundle *bp)
+{
+    assert(bp != NULL);
+    return EventFrameCreate("bundle", bp->name, bp->source_path, bp->offset);
+}
+
+static EventFrame *PromiseToEventFrame(const Promise *pp)
+{
+    assert(pp != NULL);
+    return EventFrameCreate("promise", PromiseGetPromiseType(pp), PromiseGetBundle(pp)->source_path, pp->offset);
+}
+
+static EventFrame *FunctionToEventFrame(const FnCall *fp)
+{
+    assert(fp != NULL);
+    return EventFrameCreate("function", fp->name, PromiseGetBundle(fp->caller)->source_path, fp->caller->offset);
+}
+
+void EvalContextAddFunctionEvent(EvalContext *ctx, const FnCall *fp, int64_t start)
+{
+    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);
+    }
+}
+
+int64_t EvalContextEventStart()
+{
+    struct timespec ts;
+    clock_gettime(CLOCK_MONOTONIC, &ts);
+    return ts.tv_sec * 1000000000LL + ts.tv_nsec;
+}
+
+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)
+{
+    int64_t end = EvalContextEventStart();
+    int64_t start = ctx->profiler.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);
+
+    JsonElement *events = JsonArrayCreate(10);
+    {
+        HashMapIterator iter = HashMapIteratorInit(map);
+        MapKeyValue *mkv;
+        while ((mkv = HashMapIteratorNext(&iter)) != NULL)
+        {
+            EventFrame *event = mkv->value;
+            JsonArrayAppendObject(events, EventToJson(event));
+        }
+    }
+    JsonObjectAppendArray(profiling, "events", events);
+
+    // write
+    Writer *writer = FileWriter(stdout);
+    JsonWrite(writer, profiling, 2);
+    WriterClose(writer);
+
+    JsonDestroy(profiling);
+}

libpromises/eval_context.h

@@ -40,6 +40,15 @@
 #include <ring_buffer.h>
 #include <generic_agent.h>
 
+typedef struct {
+    char *id;
+    char *type;
+    char *name;
+    char *filename;
+    SourceOffset offset;
+    int64_t elapsed;
+} EventFrame;
+
 typedef enum
 {
     STACK_FRAME_TYPE_BUNDLE,
@@ -101,6 +110,8 @@ typedef struct
 
     char *path;
     bool override_immutable;
+    int64_t start;
+    EventFrame *event;
 } StackFrame;
 
 typedef enum
@@ -434,4 +445,12 @@ 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);
+
+void EvalContextProfilingStart(EvalContext *ctx);
+void EvalContextProfilingEnd(EvalContext *ctx, const Policy *policy);
+
 #endif

libpromises/fncall.c

@@ -419,7 +419,9 @@ FnCallResult FnCallEvaluate(EvalContext *ctx, const Policy *policy, FnCall *fp,
         WriterClose(fncall_writer);
     }
 
+    int64_t start = EvalContextEventStart();
     FnCallResult result = CallFunction(ctx, policy, fp, expargs);
+    EvalContextAddFunctionEvent(ctx, fp, start);
 
     if (result.status == FNCALL_FAILURE)
     {