From 9202412723332ce0921284efcd4642f9257880f8 Mon Sep 17 00:00:00 2001 From: Julian Benda Date: Wed, 8 Dec 2021 19:05:58 +0100 Subject: [PATCH 1/2] Add Debugg docu + KEEP_STACK for summary --- doc/debugging.md | 6 +- lib/core/jtrace.c | 158 ++++++++++++++++++++++++++-------------------- 2 files changed, 96 insertions(+), 68 deletions(-) diff --git a/doc/debugging.md b/doc/debugging.md index c2d4c5924..10192580e 100644 --- a/doc/debugging.md +++ b/doc/debugging.md @@ -10,13 +10,17 @@ Moreover, developers should be aware of the fact that debug builds of JULEA can JULEA contains a tracing component that can be used to record information about various aspects of JULEA's behavior. The overall tracing can be influenced using the `JULEA_TRACE` environment variable. If the variable is set to `echo`, all tracing information will be printed to stderr. +If the variable is set to `summary`, the runtime and calls are added for each unique call stack. If JULEA has been built with OTF support, a value of `otf` will cause JULEA to produce traces via OTF. It is also possible to specify multiple values separated by commas. By default, all functions are traced. If this produces too much output, a filter can be set using the `JULEA_TRACE_FUNCTION` environment variable. -The variable can contain a list of function wildcards that are separated by commas. +The variable can contain a list of function matcher that are separated by commas. The wildcards support `*` and `?`. +Filterung will remove call stacks from the `summary`, +to keep the call stack do differ between different kind you can specify `KEEP_STACK` as matcher. +You can also add matcher for top level functions you are interested in. ## Coverage diff --git a/lib/core/jtrace.c b/lib/core/jtrace.c index 4d68202c5..3349520fa 100644 --- a/lib/core/jtrace.c +++ b/lib/core/jtrace.c @@ -107,6 +107,7 @@ struct JTrace }; static JTraceFlags j_trace_flags = J_TRACE_OFF; +static gboolean j_trace_summary_keep_stack = FALSE; static gchar* j_trace_name = NULL; static gint j_trace_thread_id = 1; @@ -400,9 +401,22 @@ j_trace_init(gchar const* name) p = g_strsplit(j_trace_function, ",", 0); l = g_strv_length(p); + for (guint i = 0; i < l; ++i) { + if(g_strcmp0(p[i], "KEEP_STACK") == 0) { + gchar* buf = p[l-1]; + p[l-1] = p[i]; + p[i] = buf; + + j_trace_summary_keep_stack = TRUE; + + l -= 1; + i -= 1; + } + } + j_trace_function_patterns = g_new(GPatternSpec*, l + 1); - for (guint i = 0; i < l; i++) + for (guint i = 0; i < l; ++i) { j_trace_function_patterns[i] = g_pattern_spec_new(p[i]); } @@ -506,6 +520,7 @@ j_trace_enter(gchar const* name, gchar const* format, ...) JTrace* trace; guint64 timestamp; va_list args; + gboolean ignore; if (j_trace_flags == J_TRACE_OFF) { @@ -516,11 +531,10 @@ j_trace_enter(gchar const* name, gchar const* format, ...) trace_thread = j_trace_thread_get_default(); - if (!j_trace_function_check(name)) - { - /// \todo also blacklist nested functions - return NULL; - } + ignore = !j_trace_function_check(name); + if(ignore + && (!j_trace_summary_keep_stack + || !(j_trace_flags & J_TRACE_SUMMARY))) { return NULL; } timestamp = g_get_real_time(); @@ -528,10 +542,32 @@ j_trace_enter(gchar const* name, gchar const* format, ...) trace->name = g_strdup(name); trace->enter_time = timestamp; - va_start(args, format); + if (j_trace_flags & J_TRACE_SUMMARY) + { + JTraceStack current_stack; + + if (trace_thread->stack->len == 0) + { + current_stack.name = g_strdup(name); + } + else + { + JTraceStack* top_stack; + + top_stack = &g_array_index(trace_thread->stack, JTraceStack, trace_thread->stack->len - 1); + current_stack.name = g_strdup_printf("%s/%s", top_stack->name, name); + } + + current_stack.enter_time = timestamp; + g_array_append_val(trace_thread->stack, current_stack); + if (ignore) { goto end; } + } + + if (j_trace_flags & J_TRACE_ECHO) { + va_start(args, format); G_LOCK(j_trace_echo); j_trace_echo_printerr(trace_thread, timestamp); @@ -548,6 +584,7 @@ j_trace_enter(gchar const* name, gchar const* format, ...) } G_UNLOCK(j_trace_echo); + va_end(args); } #ifdef HAVE_OTF @@ -576,28 +613,7 @@ j_trace_enter(gchar const* name, gchar const* format, ...) } #endif - if (j_trace_flags & J_TRACE_SUMMARY) - { - JTraceStack current_stack; - - if (trace_thread->stack->len == 0) - { - current_stack.name = g_strdup(name); - } - else - { - JTraceStack* top_stack; - - top_stack = &g_array_index(trace_thread->stack, JTraceStack, trace_thread->stack->len - 1); - current_stack.name = g_strdup_printf("%s/%s", top_stack->name, name); - } - - current_stack.enter_time = timestamp; - g_array_append_val(trace_thread->stack, current_stack); - } - - va_end(args); - +end: trace_thread->function_depth++; return trace; @@ -608,6 +624,7 @@ j_trace_leave(JTrace* trace) { JTraceThread* trace_thread; guint64 timestamp; + gboolean ignore; if (trace == NULL) { @@ -621,10 +638,10 @@ j_trace_leave(JTrace* trace) trace_thread = j_trace_thread_get_default(); - if (!j_trace_function_check(trace->name)) - { - goto end; - } + ignore = !j_trace_function_check(trace->name); + if(ignore + && (!j_trace_summary_keep_stack + || !(j_trace_flags & J_TRACE_SUMMARY))) { goto end; } /// \todo if (trace_thread->function_depth == 0) @@ -635,6 +652,46 @@ j_trace_leave(JTrace* trace) trace_thread->function_depth--; timestamp = g_get_real_time(); + if (j_trace_flags & J_TRACE_SUMMARY) + { + JTraceTime* combined_duration; + JTraceStack* top_stack; + guint64 duration; + + g_assert(trace_thread->stack->len > 0); + + top_stack = &g_array_index(trace_thread->stack, JTraceStack, trace_thread->stack->len - 1); + duration = timestamp - top_stack->enter_time; + + if(!ignore) + { + G_LOCK(j_trace_summary); + + combined_duration = g_hash_table_lookup(j_trace_summary_table, top_stack->name); + + if (combined_duration == NULL) + { + combined_duration = g_new(JTraceTime, 1); + combined_duration->time = ((gdouble)duration) / ((gdouble)G_USEC_PER_SEC); + combined_duration->count = 1; + + g_hash_table_insert(j_trace_summary_table, g_strdup(top_stack->name), combined_duration); + } + else + { + combined_duration->time += ((gdouble)duration) / ((gdouble)G_USEC_PER_SEC); + combined_duration->count++; + } + + G_UNLOCK(j_trace_summary); + } + + g_free(top_stack->name); + g_array_set_size(trace_thread->stack, trace_thread->stack->len - 1); + + if (ignore) { goto end; } + } + if (j_trace_flags & J_TRACE_ECHO) { guint64 duration; @@ -666,40 +723,7 @@ j_trace_leave(JTrace* trace) } #endif - if (j_trace_flags & J_TRACE_SUMMARY) - { - JTraceTime* combined_duration; - JTraceStack* top_stack; - guint64 duration; - - g_assert(trace_thread->stack->len > 0); - - top_stack = &g_array_index(trace_thread->stack, JTraceStack, trace_thread->stack->len - 1); - duration = timestamp - top_stack->enter_time; - - G_LOCK(j_trace_summary); - - combined_duration = g_hash_table_lookup(j_trace_summary_table, top_stack->name); - - if (combined_duration == NULL) - { - combined_duration = g_new(JTraceTime, 1); - combined_duration->time = ((gdouble)duration) / ((gdouble)G_USEC_PER_SEC); - combined_duration->count = 1; - - g_hash_table_insert(j_trace_summary_table, g_strdup(top_stack->name), combined_duration); - } - else - { - combined_duration->time += ((gdouble)duration) / ((gdouble)G_USEC_PER_SEC); - combined_duration->count++; - } - - G_UNLOCK(j_trace_summary); - - g_free(top_stack->name); - g_array_set_size(trace_thread->stack, trace_thread->stack->len - 1); - } + end: g_free(trace->name); From 786c83b411fe276a10a1988993e0725680e37684 Mon Sep 17 00:00:00 2001 From: Julian Benda Date: Mon, 20 Dec 2021 15:49:15 +0100 Subject: [PATCH 2/2] Formatting --- lib/core/jbatch.c | 2 +- lib/core/jtrace.c | 44 +++++++++++++++++++++++++++----------------- 2 files changed, 28 insertions(+), 18 deletions(-) diff --git a/lib/core/jbatch.c b/lib/core/jbatch.c index c83869310..3135d056a 100644 --- a/lib/core/jbatch.c +++ b/lib/core/jbatch.c @@ -118,7 +118,7 @@ j_batch_new(JSemantics* semantics) } JBatch* - j_batch_new_for_template(JSemanticsTemplate template) +j_batch_new_for_template(JSemanticsTemplate template) { J_TRACE_FUNCTION(NULL); diff --git a/lib/core/jtrace.c b/lib/core/jtrace.c index 3349520fa..f6d850099 100644 --- a/lib/core/jtrace.c +++ b/lib/core/jtrace.c @@ -401,10 +401,12 @@ j_trace_init(gchar const* name) p = g_strsplit(j_trace_function, ",", 0); l = g_strv_length(p); - for (guint i = 0; i < l; ++i) { - if(g_strcmp0(p[i], "KEEP_STACK") == 0) { - gchar* buf = p[l-1]; - p[l-1] = p[i]; + for (guint i = 0; i < l; ++i) + { + if (g_strcmp0(p[i], "KEEP_STACK") == 0) + { + gchar* buf = p[l - 1]; + p[l - 1] = p[i]; p[i] = buf; j_trace_summary_keep_stack = TRUE; @@ -532,9 +534,12 @@ j_trace_enter(gchar const* name, gchar const* format, ...) trace_thread = j_trace_thread_get_default(); ignore = !j_trace_function_check(name); - if(ignore - && (!j_trace_summary_keep_stack - || !(j_trace_flags & J_TRACE_SUMMARY))) { return NULL; } + if (ignore + && (!j_trace_summary_keep_stack + || !(j_trace_flags & J_TRACE_SUMMARY))) + { + return NULL; + } timestamp = g_get_real_time(); @@ -560,11 +565,12 @@ j_trace_enter(gchar const* name, gchar const* format, ...) current_stack.enter_time = timestamp; g_array_append_val(trace_thread->stack, current_stack); - if (ignore) { goto end; } + if (ignore) + { + goto end; + } } - - if (j_trace_flags & J_TRACE_ECHO) { va_start(args, format); @@ -639,9 +645,12 @@ j_trace_leave(JTrace* trace) trace_thread = j_trace_thread_get_default(); ignore = !j_trace_function_check(trace->name); - if(ignore - && (!j_trace_summary_keep_stack - || !(j_trace_flags & J_TRACE_SUMMARY))) { goto end; } + if (ignore + && (!j_trace_summary_keep_stack + || !(j_trace_flags & J_TRACE_SUMMARY))) + { + goto end; + } /// \todo if (trace_thread->function_depth == 0) @@ -663,7 +672,7 @@ j_trace_leave(JTrace* trace) top_stack = &g_array_index(trace_thread->stack, JTraceStack, trace_thread->stack->len - 1); duration = timestamp - top_stack->enter_time; - if(!ignore) + if (!ignore) { G_LOCK(j_trace_summary); @@ -689,7 +698,10 @@ j_trace_leave(JTrace* trace) g_free(top_stack->name); g_array_set_size(trace_thread->stack, trace_thread->stack->len - 1); - if (ignore) { goto end; } + if (ignore) + { + goto end; + } } if (j_trace_flags & J_TRACE_ECHO) @@ -723,8 +735,6 @@ j_trace_leave(JTrace* trace) } #endif - - end: g_free(trace->name); g_slice_free(JTrace, trace);