From: Alan T. DeKok <aland@freeradius.org>
Date: Fri, 23 Sep 2022 16:30:49 +0000 (-0400)
Subject: use fr_time_tracking for the time tracking.
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=968fd7940f31170f1b12105db4e799487b02559b;p=thirdparty%2Ffreeradius-server.git

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 e282b8cb972..00f028d8702 100644
--- 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 9faa338cfac..eccaac2bd90 100644
--- 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 d12c2e343c8..58e476ade6d 100644
--- 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