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 <[email protected]>

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();
 
+    int64_t policy_event_start = EvalContextEventStart();
     KeepPromises(ctx, policy, config);
+    EvalContextWriteEventTree(ctx, policy_event_start);
 
     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,14 @@ 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, char *name, char *source, SourceOffset offset);
+static void EventFrameDestroy(EventFrame *event);
+static void EventFrameUpdate(EvalContext *ctx, EventFrame *last_event);
+static EventFrame *BundleToEventFrame(const Bundle *bp);
+static EventFrame *PromiseToEventFrame(const Promise *pp);
+static EventFrame *FunctionToEventFrame(const FnCall *fp);
+static EventFrame *PolicyToEventFrame();
+
 /**
  * Every agent has only one EvalContext from process start to finish.
  */
@@ -192,6 +200,12 @@ struct EvalContext_
     RemoteVarPromisesMap *remote_var_promises;
 
     bool dump_reports;
+
+    /* These are needed for policy profiling */
+    bool profiling;
+    EventFrame *root;
+    HashMap *event_map;
+    Seq *events;
 };
 
 void EvalContextSetConfig(EvalContext *ctx, const GenericAgentConfig *config)
@@ -332,6 +346,19 @@ static StackFrame *LastStackFrameByType(const EvalContext *ctx, StackFrameType t
     return NULL;
 }
 
+static StackFrame *LastStackFrameByNonNullEvent(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)
@@ -1058,6 +1085,11 @@ ENTERPRISE_VOID_FUNC_1ARG_DEFINE_STUB(void, EvalContextSetupMissionPortalLogHook
 {
 }
 
+void DestroyNothing(void *data)
+{
+    assert(data != NULL);
+}
+
 EvalContext *EvalContextNew(void)
 {
     EvalContext *ctx = xcalloc(1, sizeof(EvalContext));
@@ -1093,6 +1125,10 @@ EvalContext *EvalContextNew(void)
 
     ctx->dump_reports = false;
 
+    ctx->root = PolicyToEventFrame();
+    ctx->event_map = HashMapNew((MapHashFn) StringHash, (MapKeyEqualFn) StringEqual, (MapDestroyDataFn) DestroyNothing, (MapDestroyDataFn) DestroyNothing, 10);
+    ctx->events = SeqNew(20, EventFrameDestroy);
+
     return ctx;
 }
 
@@ -1140,6 +1176,10 @@ void EvalContextDestroy(EvalContext *ctx)
             ctx->remote_var_promises = NULL;
         }
 
+        HashMapDestroy(ctx->event_map);
+        EventFrameDestroy(ctx->root);
+        SeqDestroy(ctx->events);
+
         free(ctx);
     }
 }
@@ -1324,17 +1364,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 +1401,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;
 }
@@ -1413,7 +1457,7 @@ void EvalContextStackPushBundleFrame(EvalContext *ctx, const Bundle *owner, cons
 {
     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)
     {
@@ -1492,7 +1536,7 @@ void EvalContextStackPushPromiseFrame(EvalContext *ctx, const Promise *owner)
 
     EvalContextVariableClearMatch(ctx);
 
-    StackFrame *frame = StackFrameNewPromise(owner);
+    StackFrame *frame = StackFrameNewPromise(owner, ctx->profiling);
 
     EvalContextStackPushFrame(ctx, frame);
 
@@ -1583,6 +1627,9 @@ 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;
 
     switch (last_frame_type)
     {
@@ -1608,7 +1655,6 @@ void EvalContextStackPopFrame(EvalContext *ctx)
     default:
         break;
     }
-
     SeqRemove(ctx->stack, SeqLength(ctx->stack) - 1);
 
     last_frame = LastStackFrame(ctx, 0);
@@ -1623,6 +1669,13 @@ void EvalContextStackPopFrame(EvalContext *ctx)
 
     LogDebug(LOG_MOD_EVALCTX, "POPPED FRAME (type %s)",
              STACK_FRAME_TYPE_STR[last_frame_type]);
+
+    // if the last StackFrame has no event, we skip
+    if (last_event != NULL)
+    {
+        last_event->elapsed = end - start;
+        EventFrameUpdate(ctx, last_event);
+    }
 }
 
 bool EvalContextClassRemove(EvalContext *ctx, const char *ns, const char *name)
@@ -3847,3 +3900,178 @@ bool EvalContextOverrideImmutableGet(EvalContext *ctx)
     assert(stack_frame != NULL);
     return stack_frame->override_immutable;
 }
+
+// ##############################################################
+
+static EventFrame *EventFrameCreate(char *type, char *name, char *source, SourceOffset offset)
+{
+    EventFrame *event = (EventFrame *) xmalloc(sizeof(EventFrame));
+
+    event->type = type;
+    event->name = name;
+    event->filename = source;
+    event->elapsed = 0;
+    event->children = SeqNew(10, NULL);
+    event->offset = offset;
+    event->parent = NULL;
+
+    char id[strlen(type) + strlen(name) + strlen(source) + PRINTSIZE(offset.start) + PRINTSIZE(offset.line) + 4];
+    xsnprintf(id, sizeof(id)+1, "%s_%s_%s_%ld_%ld", type, name, source, offset.start, offset.line);
+
+    event->id = SafeStringDuplicate(id);
+    
+    return event;
+}
+
+static void EventFrameDestroy(EventFrame *event)
+{
+    assert(event != NULL);
+    SeqDestroy(event->children);
+    free(event->filename);
+    free(event->id);
+    free(event->name);
+    free(event);
+}
+
+static int EventFrameCompare(const void *event1, const void *event2, void *user_data ARG_UNUSED)
+{
+    const EventFrame *e1 = event1;
+    const EventFrame *e2 = event2;
+    return strcmp(e1->id, e2->id);
+}
+
+static void EventFrameUpdate(EvalContext *ctx, EventFrame *last_event)
+{
+    assert(ctx != NULL);
+    assert(last_event != NULL);
+    SeqAppend(ctx->events, last_event); // keep track of EventFrames for cleanup
+
+    // if the event is already in the map and has shorter elapsed time, then we ignore it
+    // else, we replace the old with the latest one
+    MapKeyValue *mkv = HashMapGet(ctx->event_map, last_event->id);
+    if (mkv != NULL)
+    {
+        EventFrame *previous = mkv->value;
+
+        if (previous->elapsed > last_event->elapsed)
+        {
+            return;
+        }
+        ssize_t i = SeqIndexOf(previous->parent->children, previous, EventFrameCompare);
+        SeqRemove(previous->parent->children, i);
+    }
+
+    // Insert the event in the map and attach the event to its parent
+    HashMapInsert(ctx->event_map, last_event->id, last_event);
+
+    StackFrame *parent_event_frame = LastStackFrameByNonNullEvent(ctx);
+    if (parent_event_frame != NULL)
+    {
+        SeqAppend(parent_event_frame->event->children, last_event);
+        last_event->parent = parent_event_frame->event;
+    }
+    else
+    {
+        SeqAppend(ctx->root->children, last_event);
+        last_event->parent = ctx->root;
+    }
+}
+
+static EventFrame *BundleToEventFrame(const Bundle *bp)
+{
+    assert(bp != NULL);
+    return EventFrameCreate("bundle", SafeStringDuplicate(bp->name), GetAbsolutePath(bp->source_path), bp->offset);
+}
+
+static EventFrame *PromiseToEventFrame(const Promise *pp)
+{
+    assert(pp != NULL);
+    return EventFrameCreate("promise", SafeStringDuplicate(PromiseGetPromiseType(pp)), GetAbsolutePath(PromiseGetBundle(pp)->source_path), pp->offset);
+}
+
+static EventFrame *FunctionToEventFrame(const FnCall *fp)
+{
+    assert(fp != NULL);
+    return EventFrameCreate("function", SafeStringDuplicate(fp->name), GetAbsolutePath(PromiseGetBundle(fp->caller)->source_path), fp->caller->offset);
+}
+
+static EventFrame *PolicyToEventFrame()
+{
+    return EventFrameCreate("policy", SafeStringDuplicate(""), SafeStringDuplicate(""), (SourceOffset) {0});
+}
+
+void EvalContextAddFunctionEvent(EvalContext *ctx, FnCall *fp, int64_t start)
+{
+    assert(ctx != NULL);
+    if (ctx->profiling)
+    {
+        EventFrame *event = FunctionToEventFrame(fp);
+        event->elapsed = EvalContextEventStart() - start;
+        EventFrameUpdate(ctx, event);
+    }
+}
+
+static JsonElement *EventFrameTreeToJson(const EventFrame *node)
+{
+    if (node == NULL)
+    {
+        return NULL;
+    }
+
+    JsonElement *new_element = JsonObjectCreate(6);
+
+    JsonObjectAppendString(new_element, "name", node->name);
+    JsonObjectAppendString(new_element, "type", node->type);
+    JsonObjectAppendString(new_element, "filename", node->filename);
+    JsonObjectAppendInteger64(new_element, "elapsed", node->elapsed);
+    
+    JsonElement *offset = JsonObjectCreate(3);
+    JsonObjectAppendInteger(offset, "lineno", node->offset.line);
+    JsonObjectAppendInteger(offset, "start", node->offset.start);
+    JsonObjectAppendInteger(offset, "end", node->offset.end);
+    JsonObjectAppendObject(new_element, "offset", offset);
+
+    JsonElement *children = JsonArrayCreate(5);
+    for (size_t i = 0; i < SeqLength(node->children); i++)
+    {
+        EventFrame *next = SeqAt(node->children, i);
+        JsonElement *child = EventFrameTreeToJson(next);
+        if (child != NULL)
+        {
+            JsonArrayAppendObject(children, child);
+        }
+    }
+    JsonObjectAppendArray(new_element, "children", children);
+    return new_element;
+}
+
+int64_t EvalContextEventStart()
+{
+    struct timespec ts;
+    clock_gettime(CLOCK_MONOTONIC, &ts);
+    return ts.tv_sec * 1000000000LL + ts.tv_nsec;
+}
+
+void EvalContextWriteEventTree(EvalContext *ctx, int64_t start)
+{
+    assert(ctx != NULL);
+    int64_t end = EvalContextEventStart();
+    ctx->root->elapsed = end - start;
+
+    JsonElement *tree = EventFrameTreeToJson(ctx->root);
+
+    if (ctx->profiling)
+    {
+        Writer *w = FileWriter(stdout);
+        JsonWrite(w, tree, 0);
+        FileWriterDetach(w);
+    }
+
+    JsonDestroy(tree);
+}
+
+void EvalContextSetProfiling(EvalContext *ctx, bool profiling)
+{
+    assert(ctx != NULL);
+    ctx->profiling = profiling;
+}