use fr_time_tracking for the time tracking.

if it's good enough for modules, it's good enough for the interpreter

Which now lets it track yielded time, too.

We still have some @todo, which is to track parent frames, so
that when a child yields, we mark the parent as yielded too

diff --git a/src/lib/unlang/compile.c b/src/lib/unlang/compile.c
index e282b8cb972d4e21e1872f53940aa932230a7f79..00f028d8702949e8d399dbd33b163cc0b458479b 100644 (file)
--- a/src/lib/unlang/compile.c
+++ b/src/lib/unlang/compile.c
@@ -4428,6 +4428,7 @@ int unlang_thread_instantiate(TALLOC_CTX *ctx)
 void unlang_frame_perf_init(unlang_t const *instruction)
 {
        unlang_thread_t *t;
+       fr_time_t now;
 
        if (!instruction->number || !unlang_thread_array) return;
 
@@ -4436,8 +4437,36 @@ void unlang_frame_perf_init(unlang_t const *instruction)
        t = &unlang_thread_array[instruction->number];
 
        t->use_count++;
+       now = fr_time();
 
-       t->enter = fr_time();
+       fr_time_tracking_start(NULL, &t->tracking, now);
+       fr_time_tracking_yield(&t->tracking, now);
+}
+
+void unlang_frame_perf_yield(unlang_t const *instruction)
+{
+       unlang_thread_t *t;
+
+       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());
+}
+
+void unlang_frame_perf_resume(unlang_t const *instruction)
+{
+       unlang_thread_t *t;
+
+       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());
 }
 
 void unlang_frame_perf_cleanup(unlang_t const *instruction)
@@ -4450,7 +4479,7 @@ void unlang_frame_perf_cleanup(unlang_t const *instruction)
 
        t = &unlang_thread_array[instruction->number];
 
-       t->cpu_time = fr_time_add(t->cpu_time, fr_time_sub(fr_time(), t->enter));
+       fr_time_tracking_end(NULL, &t->tracking, fr_time());
 }
 
 
@@ -4490,8 +4519,8 @@ static void unlang_perf_dump(fr_log_t *log, unlang_t const *instruction, int dep
 
        t = &unlang_thread_array[instruction->number];
 
-       fr_log(log, L_DBG, file, line, "count=%" PRIu64 " cpu_time=%" PRIu64,
-              t->use_count, fr_time_delta_unwrap(t->cpu_time));
+       fr_log(log, L_DBG, file, line, "count=%" PRIu64 " cpu_time=%" PRIu64 " yielded_time=%" PRIu64 ,
+              t->use_count, fr_time_delta_unwrap(t->tracking.running_total), fr_time_delta_unwrap(t->tracking.waiting_total));
 
        if (g->children) {
                unlang_t *child;

diff --git a/src/lib/unlang/interpret.c b/src/lib/unlang/interpret.c
index 9faa338cfacf5e34a00c17803e0050b4984b319f..eccaac2bd9000a0ff588902749ed6a98b6b77078 100644 (file)
--- a/src/lib/unlang/interpret.c
+++ b/src/lib/unlang/interpret.c
@@ -486,6 +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);
                fr_assert(frame->process != NULL);
 
                /*
@@ -498,6 +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);
                ua = frame->process(result, request, frame);
 
                /*
@@ -559,6 +561,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);
                        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 d12c2e343c89e77e927b36af1cbaec6e7720ec94..58e476ade6d32a1664018754f8e9ac4642842e52 100644 (file)
--- a/src/lib/unlang/unlang_priv.h
+++ b/src/lib/unlang/unlang_priv.h
@@ -230,18 +230,18 @@ typedef struct {
        void                    *thread_inst;                   //!< thread-specific instance data
 #ifdef WITH_PERF
        uint64_t                use_count;
-       fr_time_t               enter;
-
-       fr_time_delta_t         cpu_time;
+       fr_time_tracking_t      tracking;                       //!< tracking cpu time
 #endif
 } 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);
 #else
 #define                unlang_frame_perf_init(_x)
+#define                unlang_frame_perf_resume(_x)
 #define                unlang_frame_perf_cleanup(_x)
 #endif