do time tracking per frame

and only add it to the instruction totals when the frame is done

diff --git a/src/lib/unlang/compile.c b/src/lib/unlang/compile.c
index 00f028d8702949e8d399dbd33b163cc0b458479b..e4caa4acf8563761f26a1a3f032e5925c7de580c 100644 (file)
--- a/src/lib/unlang/compile.c
+++ b/src/lib/unlang/compile.c
@@ -4425,10 +4425,11 @@ int unlang_thread_instantiate(TALLOC_CTX *ctx)
 }
 
 #ifdef WITH_PERF
-void unlang_frame_perf_init(unlang_t const *instruction)
+void unlang_frame_perf_init(unlang_stack_frame_t *frame)
 {
        unlang_thread_t *t;
        fr_time_t now;
+       unlang_t const *instruction = frame->instruction;
 
        if (!instruction->number || !unlang_thread_array) return;
 
@@ -4439,39 +4440,32 @@ void unlang_frame_perf_init(unlang_t const *instruction)
        t->use_count++;
        now = fr_time();
 
-       fr_time_tracking_start(NULL, &t->tracking, now);
-       fr_time_tracking_yield(&t->tracking, now);
+       fr_time_tracking_start(NULL, &frame->tracking, now);
+       fr_time_tracking_yield(&frame->tracking, now);
 }
 
-void unlang_frame_perf_yield(unlang_t const *instruction)
+void unlang_frame_perf_yield(unlang_stack_frame_t *frame)
 {
-       unlang_thread_t *t;
+       unlang_t const *instruction = frame->instruction;
 
        if (!instruction->number || !unlang_thread_array) return;
 
-       fr_assert(instruction->number <= unlang_number);
-
-       t = &unlang_thread_array[instruction->number];
-
-       fr_time_tracking_yield(&t->tracking, fr_time());
+       fr_time_tracking_yield(&frame->tracking, fr_time());
 }
 
-void unlang_frame_perf_resume(unlang_t const *instruction)
+void unlang_frame_perf_resume(unlang_stack_frame_t *frame)
 {
-       unlang_thread_t *t;
+       unlang_t const *instruction = frame->instruction;
 
        if (!instruction->number || !unlang_thread_array) return;
 
-       fr_assert(instruction->number <= unlang_number);
-
-       t = &unlang_thread_array[instruction->number];
-
-       fr_time_tracking_resume(&t->tracking, fr_time());
+       fr_time_tracking_resume(&frame->tracking, fr_time());
 }
 
-void unlang_frame_perf_cleanup(unlang_t const *instruction)
+void unlang_frame_perf_cleanup(unlang_stack_frame_t *frame)
 {
        unlang_thread_t *t;
+       unlang_t const *instruction = frame->instruction;
 
        if (!instruction || !instruction->number || !unlang_thread_array) return;
 
@@ -4479,7 +4473,9 @@ void unlang_frame_perf_cleanup(unlang_t const *instruction)
 
        t = &unlang_thread_array[instruction->number];
 
-       fr_time_tracking_end(NULL, &t->tracking, fr_time());
+       fr_time_tracking_end(NULL, &frame->tracking, fr_time());
+       t->tracking.running_total = fr_time_delta_add(t->tracking.running_total, frame->tracking.running_total);
+       t->tracking.waiting_total = fr_time_delta_add(t->tracking.waiting_total, frame->tracking.waiting_total);
 }
 
 

diff --git a/src/lib/unlang/interpret.c b/src/lib/unlang/interpret.c
index eccaac2bd9000a0ff588902749ed6a98b6b77078..0c75cf9769d9462dff16f3260a6b8b2cff8837a0 100644 (file)
--- a/src/lib/unlang/interpret.c
+++ b/src/lib/unlang/interpret.c
@@ -486,7 +486,7 @@ unlang_frame_action_t frame_eval(request_t *request, unlang_stack_frame_t *frame
                RDEBUG4("** [%i] %s >> %s", stack->depth, __FUNCTION__,
                        unlang_ops[instruction->type].name);
 
-               unlang_frame_perf_resume(instruction);
+               unlang_frame_perf_resume(frame);
                fr_assert(frame->process != NULL);
 
                /*
@@ -499,7 +499,7 @@ unlang_frame_action_t frame_eval(request_t *request, unlang_stack_frame_t *frame
                 *      should be evaluated again.
                 */
                repeatable_clear(frame);
-               unlang_frame_perf_resume(frame->instruction);
+               unlang_frame_perf_resume(frame);
                ua = frame->process(result, request, frame);
 
                /*
@@ -540,6 +540,7 @@ unlang_frame_action_t frame_eval(request_t *request, unlang_stack_frame_t *frame
                 *      now continue at the deepest frame.
                 */
                case UNLANG_ACTION_PUSHED_CHILD:
+                       unlang_frame_perf_yield(frame);
                        fr_assert(&stack->frame[stack->depth] > frame);
                        *result = frame->result;
                        return UNLANG_FRAME_ACTION_NEXT;
@@ -561,7 +562,7 @@ unlang_frame_action_t frame_eval(request_t *request, unlang_stack_frame_t *frame
                 *      called the interpreter.
                 */
                case UNLANG_ACTION_YIELD:
-                       unlang_frame_perf_yield(instruction);
+                       unlang_frame_perf_yield(frame);
                        yielded_set(frame);
                        RDEBUG4("** [%i] %s - yielding with current (%s %d)", stack->depth, __FUNCTION__,
                                fr_table_str_by_value(mod_rcode_table, frame->result, "<invalid>"),

diff --git a/src/lib/unlang/unlang_priv.h b/src/lib/unlang/unlang_priv.h
index 58e476ade6d32a1664018754f8e9ac4642842e52..c0ddbc01094b9e58e6dc60b75c08d9895d32b01f 100644 (file)
--- a/src/lib/unlang/unlang_priv.h
+++ b/src/lib/unlang/unlang_priv.h
@@ -235,12 +235,13 @@ typedef struct {
 } unlang_thread_t;
 
 #ifdef WITH_PERF
-void           unlang_frame_perf_init(unlang_t const *instruction);
-void           unlang_frame_perf_yield(unlang_t const *instruction);
-void           unlang_frame_perf_resume(unlang_t const *instruction);
-void           unlang_frame_perf_cleanup(unlang_t const *instruction);
+void           unlang_frame_perf_init(unlang_stack_frame_t *frame);
+void           unlang_frame_perf_yield(unlang_stack_frame_t *frame);
+void           unlang_frame_perf_resume(unlang_stack_frame_t *frame);
+void           unlang_frame_perf_cleanup(unlang_stack_frame_t *frame);
 #else
 #define                unlang_frame_perf_init(_x)
+#define                unlang_frame_perf_yield(_x)
 #define                unlang_frame_perf_resume(_x)
 #define                unlang_frame_perf_cleanup(_x)
 #endif
@@ -291,8 +292,10 @@ struct unlang_stack_frame_s {
                                                                ///< this priority will be compared with the one of the
                                                                ///< frame lower in the stack to determine if the
                                                                ///< result stored in the lower stack frame should
-                                                               ///< be replaced.
        uint8_t                 uflags;                         //!< Unwind markers
+#ifdef WITH_PERF
+       fr_time_tracking_t      tracking;                       //!< track this instance of this instruction
+#endif
 };
 
 /** An unlang stack associated with a request
@@ -390,7 +393,7 @@ static inline void frame_state_init(unlang_stack_t *stack, unlang_stack_frame_t
        unlang_op_t     *op;
        char const      *name;
 
-       unlang_frame_perf_init(instruction);
+       unlang_frame_perf_init(frame);
 
        op = &unlang_ops[instruction->type];
        name = op->frame_state_type ? op->frame_state_type : __location__;
@@ -443,7 +446,7 @@ static inline void frame_cleanup(unlang_stack_frame_t *frame)
                TALLOC_FREE(frame->state);
        }
 
-       unlang_frame_perf_cleanup(frame->instruction);
+       unlang_frame_perf_cleanup(frame);
 }
 
 /** Advance to the next sibling instruction