linux-kernel - [PATCH 2/2] tracing, function_graph: add additional marks to signal very large function execution time

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-Id: <1414052242-9828-3-git-send-email-byungchul.park@lge.com>
Date:	Thu, 23 Oct 2014 17:17:22 +0900
From:	byungchul.park@....com
To:	rostedt@...dmis.org, mingo@...hat.com
Cc:	jolsa@...hat.com, vanilla@...ckduck.lge.com,
	linux-kernel@...r.kernel.org,
	Byungchul Park <byungchul.park@....com>
Subject: [PATCH 2/2] tracing, function_graph: add additional marks to signal very large function execution time

From: Byungchul Park <byungchul.park@....com>

Currently, function graph tracer prints "!" or "+" just before
function execution time to signal a function overhead, depending
on the time. Even it is usually enough to do that, we sometimes
need to be signaled for bigger execution time than 100 micro seconds.

For example, I used function graph tracer to detect if there is
any case that exit_mm() takes too much time. I did following steps
in /sys/kernel/debug/tracing. It was easier to detect very big
excution time with patched kernel than with original kernel.

$ echo exit_mm > set_graph_function
$ echo function_graph > current_tracer
$ echo > trace
$ cat trace_pipe > $LOGFILE
 ... (do something and terminate logging)
$ grep "!s" $LOGFILE
 3) !s22082032 us |                      } /* kernel_map_pages */
 3) !s22082040 us |                    } /* free_pages_prepare */
 3) !s22082113 us |                  } /* free_hot_cold_page */
 3) !s22083455 us |                } /* free_hot_cold_page_list */
 3) !s22083895 us |              } /* release_pages */
 3) !s22177873 us |            } /* free_pages_and_swap_cache */
 3) !s22178929 us |          } /* unmap_single_vma */
 3) !s22198885 us |        } /* unmap_vmas */
 3) !s22206949 us |      } /* exit_mmap */
 3) !s22207659 us |    } /* mmput */
 3) !s22207793 us |  } /* exit_mm */

And then, it was easy to find out that a schedule-out occured by
sub_preempt_count() within kernel_map_pages().

To detect very large function exection time either by problematic
function implementation or by scheduling issues, this patch can be
useful.

Signed-off-by: Byungchul Park <byungchul.park@....com>
---
 kernel/trace/trace_functions_graph.c |    8 +++++++-
 1 file changed, 7 insertions(+), 1 deletion(-)

diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index c18a1e3..ea8b7e7 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -822,8 +822,14 @@ print_graph_duration(unsigned long long duration, struct trace_seq *s,
 
 	/* Signal a overhead of time execution to the output */
 	if (flags & TRACE_GRAPH_PRINT_OVERHEAD) {
+		/* Duration exceeded 1 secs */
+		if (duration > 1000000000ULL)
+			ret = trace_seq_puts(s, "!s");
+		/* Duration exceeded 1 msecs */
+		else if (duration > 1000000ULL)
+			ret = trace_seq_puts(s, "!m");
 		/* Duration exceeded 100 usecs */
-		if (duration > 100000ULL)
+		else if (duration > 100000ULL)
 			ret = trace_seq_puts(s, "! ");
 		/* Duration exceeded 10 usecs */
 		else if (duration > 10000ULL)
-- 
1.7.9.5

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/