diff --git a/cf-agent/cf-agent.c b/cf-agent/cf-agent.c index 861ee18881..0c41cec311 100644 --- a/cf-agent/cf-agent.c +++ b/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,13 @@ int main(int argc, char *argv[]) BeginAudit(); + EvalContextEventStackClear(ctx); + + EvalContextPushEvent(ctx, EventFrameNew("policy", "policy", "null", "null", (SourceOffset) {0})); KeepPromises(ctx, policy, config); + EvalContextPopEvent(ctx); + + EvalContextPrintRoot(ctx); if (EvalAborted(ctx)) { @@ -523,7 +531,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 +697,9 @@ static GenericAgentConfig *CheckOpts(int argc, char **argv) } break; + case 'p': + printf("profiling activated!\n"); + break; /* long options only */ case 0: diff --git a/libpromises/eval_context.c b/libpromises/eval_context.c index 3a8eba5520..0db86bb00b 100644 --- a/libpromises/eval_context.c +++ b/libpromises/eval_context.c @@ -191,6 +191,9 @@ struct EvalContext_ /* ONLY INITIALIZED WHEN NON-EMPTY, OTHERWISE NULL */ RemoteVarPromisesMap *remote_var_promises; + EventFrame *root; + Seq *event_stack; + bool dump_reports; }; @@ -1093,6 +1096,8 @@ EvalContext *EvalContextNew(void) ctx->dump_reports = false; + ctx->event_stack = SeqNew(10, EventFrameDestroy); + return ctx; } @@ -1438,6 +1443,7 @@ void EvalContextStackPushBundleFrame(EvalContext *ctx, const Bundle *owner, cons } VariableTableIteratorDestroy(iter); } + EvalContextPushEvent(ctx, EventFrameNew("bundle", owner->name, owner->ns, GetAbsolutePath(owner->source_path), owner->offset)); } void EvalContextStackPushBodyFrame(EvalContext *ctx, const Promise *caller, const Body *body, const Rlist *args) @@ -1475,6 +1481,7 @@ void EvalContextStackPushBodyFrame(EvalContext *ctx, const Promise *caller, cons { ScopeMapBodyArgs(ctx, body, args); } + EvalContextPushEvent(ctx, NULL); } void EvalContextStackPushBundleSectionFrame(EvalContext *ctx, const BundleSection *owner) @@ -1483,6 +1490,8 @@ void EvalContextStackPushBundleSectionFrame(EvalContext *ctx, const BundleSectio StackFrame *frame = StackFrameNewBundleSection(owner); EvalContextStackPushFrame(ctx, frame); + + EvalContextPushEvent(ctx, NULL); } void EvalContextStackPushPromiseFrame(EvalContext *ctx, const Promise *owner) @@ -1552,6 +1561,8 @@ void EvalContextStackPushPromiseFrame(EvalContext *ctx, const Promise *owner) RvalDestroy(final); } } + + EvalContextPushEvent(ctx, EventFrameNew("promise", PromiseGetPromiseType(owner), PromiseGetNamespace(owner), "null", owner->offset)); } Promise *EvalContextStackPushPromiseIterationFrame(EvalContext *ctx, const PromiseIterator *iter_ctx) @@ -1574,6 +1585,8 @@ Promise *EvalContextStackPushPromiseIterationFrame(EvalContext *ctx, const Promi EvalContextStackPushFrame(ctx, StackFrameNewPromiseIteration(pexp, iter_ctx)); LoggingPrivSetLevels(CalculateLogLevel(pexp), CalculateReportLevel(pexp)); + EvalContextPushEvent(ctx, NULL); + return pexp; } @@ -1623,6 +1636,8 @@ void EvalContextStackPopFrame(EvalContext *ctx) LogDebug(LOG_MOD_EVALCTX, "POPPED FRAME (type %s)", STACK_FRAME_TYPE_STR[last_frame_type]); + + EvalContextPopEvent(ctx); } bool EvalContextClassRemove(EvalContext *ctx, const char *ns, const char *name) @@ -3847,3 +3862,121 @@ bool EvalContextOverrideImmutableGet(EvalContext *ctx) assert(stack_frame != NULL); return stack_frame->override_immutable; } + +// ############################################################## + +static void EventStackPush(EvalContext *ctx, EventFrame *event) +{ + SeqAppend(ctx->event_stack, event); +} + +static EventFrame *EventStackPop(EvalContext *ctx) +{ + size_t last = SeqLength(ctx->event_stack) - 1; + EventFrame *popped = SeqAt(ctx->event_stack, last); + SeqRemove(ctx->event_stack, last); + + return popped; +} + +static EventFrame *EventStackPeek(EvalContext *ctx) +{ + size_t last = SeqLength(ctx->event_stack) - 1; + EventFrame *peeked = SeqAt(ctx->event_stack, last); + + return peeked; +} + +// Event + +void EventFrameDestroy(EventFrame *event) +{ + // SeqDestroy(event->children); + // free(event); +} + +EventFrame *EventFrameNew(const char *id, const char *name, const char *ns, const char *source_path, SourceOffset offset) +{ + EventFrame *event = (EventFrame *) xmalloc(sizeof(EventFrame)); + event->id = id; + event->name = name; + event->ns = ns; + event->source_path = source_path; + event->offset = offset; + event->enlapsed = time(NULL); + + event->children = SeqNew(10, EventFrameDestroy); + + return event; +} + +void EvalContextPushEvent(EvalContext *ctx, EventFrame *event) +{ + if (event == NULL) + { + event = EventFrameNew(NULL, NULL, NULL, NULL, (SourceOffset) {0}); + } + EventStackPush(ctx, event); +} + +void EvalContextPopEvent(EvalContext *ctx) +{ + if (SeqLength(ctx->event_stack) == 0) + return; + + time_t end = time(NULL); + EventFrame *popped = EventStackPop(ctx); + popped->enlapsed = end - popped->enlapsed; // update time + + if (popped->id == NULL) // junk node + { + return; + } + + if (SeqLength(ctx->event_stack) < 1) + { + ctx->root = popped; + return; + } + + EventFrame *parent = EventStackPeek(ctx); + SeqAppend(parent->children, popped); +} + +void EvalContextEventStackClear(EvalContext *ctx) +{ + // SeqClear(ctx->event_stack); + ctx->event_stack = SeqNew(10, NULL); +} + +static void EventFrameTraverse(const EventFrame *node, int depth) +{ + if (node == NULL) + return; + + // Print indentation + for (int i = 0; i < depth; i++) + printf(" "); + + // Print node info + printf("• [%lds] %s:%s (ns=%s, src=%s)\n", + node->enlapsed, + node->id ? node->id : "(no-id)", + node->name ? node->name : "(no-name)", + node->ns ? node->ns : "(no-ns)", + node->source_path ? node->source_path : "(no-src)"); + + // Recurse through children + size_t len = SeqLength(node->children); + for (size_t i = 0; i < len; i++) + { + EventFrame *child = SeqAt(node->children, i); + EventFrameTraverse(child, depth + 1); + } +} + + +void EvalContextPrintRoot(EvalContext *ctx) +{ + EventFrameTraverse(ctx->root, 0); +} \ No newline at end of file diff --git a/libpromises/eval_context.h b/libpromises/eval_context.h index 367dfa5af5..5f31996408 100644 --- a/libpromises/eval_context.h +++ b/libpromises/eval_context.h @@ -114,6 +114,17 @@ typedef enum EVAL_OPTION_FULL = 0xFFFFFFFF } EvalContextOption; +typedef struct { + time_t enlapsed; + char *id; // bundle + char *name; // main + char *ns; // default + char *source_path; // profiler.cf + SourceOffset offset; + + Seq *children; +} EventFrame; + EvalContext *EvalContextNew(void); void EvalContextDestroy(EvalContext *ctx); @@ -434,4 +445,12 @@ void EvalContextSetDumpReports(EvalContext *ctx, bool dump_reports); bool EvalContextGetDumpReports(EvalContext *ctx); void EvalContextUpdateDumpReports(EvalContext *ctx); + +void EventFrameDestroy(EventFrame *event); +EventFrame *EventFrameNew(const char *id, const char *name, const char *ns, const char *source_path, SourceOffset offset); +void EvalContextPushEvent(EvalContext *ctx, EventFrame *event); +void EvalContextPopEvent(EvalContext *ctx); +void EvalContextEventStackClear(EvalContext *ctx); +void EvalContextPrintRoot(EvalContext *ctx); + #endif diff --git a/libpromises/fncall.c b/libpromises/fncall.c index d17264dccc..3b77f9e0ea 100644 --- a/libpromises/fncall.c +++ b/libpromises/fncall.c @@ -419,7 +419,9 @@ FnCallResult FnCallEvaluate(EvalContext *ctx, const Policy *policy, FnCall *fp, WriterClose(fncall_writer); } + EvalContextPushEvent(ctx, EventFrameNew("function", fp->name, PromiseGetNamespace(fp->caller), "null", fp->caller->offset)); FnCallResult result = CallFunction(ctx, policy, fp, expargs); + EvalContextPopEvent(ctx); if (result.status == FNCALL_FAILURE) { diff --git a/libpromises/ignoreme.json b/libpromises/ignoreme.json new file mode 100644 index 0000000000..fa3f21b0b1 --- /dev/null +++ b/libpromises/ignoreme.json @@ -0,0 +1,97 @@ +{ + "type" : "Policy", + "name" : "a38cec43f6896fad9b39595edc122795d0abbb2f", + "file" : "", + "lineno" : 0, + "colno" : 0, + "children" : [ + { + "type" : "Bundle", + "name" : "default:main", + "file" : "/home/vagrant/hello.cf", + "enlapsed" : 4.0, + "lineno" : 1, + "colno" : 13, + "children" : [ + { + "type" : "Promise", + "name" : "classes", + "file" : "/home/vagrant/hello.cf", + "enlapsed" : 0.0, + "lineno" : 4, + "colno" : 59, + "children" : [ + + ] + }, + { + "type" : "Promise", + "name" : "methods", + "file" : "/home/vagrant/hello.cf", + "enlapsed" : 1.0, + "lineno" : 7, + "colno" : 195, + "children" : [ + { + "type" : "Bundle", + "name" : "default:one", + "file" : "/home/vagrant/hello.cf", + "enlapsed" : 1.0, + "lineno" : 12, + "colno" : 315, + "children" : [ + { + "type" : "Promise", + "name" : "commands", + "file" : "/home/vagrant/hello.cf", + "enlapsed" : 1.0, + "lineno" : 15, + "colno" : 368 + } + ] + } + ] + }, + { + "type" : "Promise", + "name" : "methods", + "file" : "/home/vagrant/hello.cf", + "enlapsed" : 1.0, + "lineno" : 8, + "colno" : 216, + "children" : [ + { + "type" : "Bundle", + "name" : "default:two", + "file" : "/home/vagrant/hello.cf", + "enlapsed" : 3.0, + "lineno" : 18, + "colno" : 417, + "children" : [ + { + "type" : "Promise", + "name" : "commands", + "file" : "/home/vagrant/hello.cf", + "enlapsed" : 3.0, + "lineno" : 21, + "colno" : 470 + } + ] + } + ] + }, + { + "type" : "Promise", + "name" : "methods", + "file" : "/home/vagrant/hello.cf", + "enlapsed" : 0.0, + "lineno" : 10, + "colno" : 267, + "children" : [ + + ] + } + ] + } + ] +} \ No newline at end of file