til: measure til_module_render() durations

This stows the duration (in ticks (which are ms for now)) of a
given module context's most recent, as well as tracking the max,
in til_module_context_t.

For now it's also added to --print-module-contexts output, but
this is still rather primitive and nearly inscrutible in
practice...  that output is a flickery and unsorted mess during
playback.  But this is just a start.

Ticks may need to move up to microseconds if it'll also be the
units for measuring timings.  Right now things are slow enough
that the low-hanging fruit stand out as multiple if not dozens of
milliseconds so it's still useful for now.

3 files changed, 21 insertions, 2 deletions

diff --git a/src/til.c b/src/til.c
index dec18bf..c8133ef 100644
--- a/src/til.c
+++ b/src/til.c
@@ -414,7 +414,14 @@ static void module_render_fragment(til_module_context_t *context, til_stream_t *
  */
 void til_module_render(til_module_context_t *context, til_stream_t *stream, unsigned ticks, til_fb_fragment_t **fragment_ptr)
 {
+	unsigned	start = til_ticks_now();
+
 	module_render_fragment(context, stream, til_threads, ticks, fragment_ptr);
+
+	context->last_render_duration = til_ticks_now() - start;
+	if (context->last_render_duration > context->max_render_duration)
+		context->max_render_duration = context->last_render_duration;
+	context->renders_count++;
 	context->last_ticks = ticks;
 }
 
diff --git a/src/til_module_context.h b/src/til_module_context.h
index e4c0bca..cb607f2 100644
--- a/src/til_module_context.h
+++ b/src/til_module_context.h
@@ -17,6 +17,10 @@ struct til_module_context_t {
 					 */
 
 	unsigned                refcount;
+
+	/* for profiling */
+	unsigned		last_render_duration, max_render_duration;
+	unsigned		renders_count;
 };
 
 void * til_module_context_new(const til_module_t *module, size_t size, til_stream_t *stream, unsigned seed, unsigned ticks, unsigned n_cpus, til_setup_t *setup);
diff --git a/src/til_stream.c b/src/til_stream.c
index a28e138..0ff988c 100644
--- a/src/til_stream.c
+++ b/src/til_stream.c
@@ -696,8 +696,16 @@ static int til_stream_fprint_module_context_cb(void *arg, til_stream_module_cont
 	FILE	*out = arg;
 
 	fprintf(out, " %s: %s[%zu]", contexts[0]->setup->path, contexts[0]->module->name, n_module_contexts);
-	for (size_t i = 0; i < n_module_contexts; i++)
-		fprintf(out, "%s{rc=%u, n_cpus=%u}", i ? ", " : " ", contexts[i]->refcount, contexts[i]->n_cpus);
+	for (size_t i = 0; i < n_module_contexts; i++) {
+		fprintf(out,
+			"%s{rc=%u, n_cpus=%u r=%u rd=%u maxrd=%u}",
+			i ? ", " : " ",
+			contexts[i]->refcount,
+			contexts[i]->n_cpus,
+			contexts[i]->renders_count,
+			contexts[i]->last_render_duration,
+			contexts[i]->max_render_duration);
+	}
 	fprintf(out, "\n");
 
 	return 0;