linux-kernel - [RFC PATCH 3/3] Make ftrace display walltime in output

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: <4A699085.9090903@cn.fujitsu.com>
Date:	Fri, 24 Jul 2009 18:44:21 +0800
From:	Zhaolei <zhaolei@...fujitsu.com>
To:	Steven Rostedt <rostedt@...dmis.org>
CC:	Frederic Weisbecker <fweisbec@...il.com>,
	Ingo Molnar <mingo@...e.hu>,
	LKML <linux-kernel@...r.kernel.org>
Subject: [RFC PATCH 3/3] Make ftrace display walltime in output

Now ring-buffer system have ability to support events' walltime record.
We can make ftrace display walltime in output as:
 # cd /mnt/debugfs/tracing/
 # echo sched_switch > current_tracer
 # cat trace
 # tracer: sched_switch
 #
 #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
 #              | |       |          |         |
             bash-2457  [000]   214.895446:   2457:120:S   + [000]  2457:120:S bash
             bash-2457  [000]   214.898298:   2457:120:R   + [000]     5:115:S events/0
             bash-2457  [000]   214.898684:   2457:120:R ==> [000]     5:115:R events/0
         events/0-5     [000]   214.899458:      5:115:R   + [000]  2455:120:S sshd
         events/0-5     [000]   214.899495:      5:115:S ==> [000]  2455:120:R sshd
 ...
 # echo 1 > options/walltime
 # cat trace
 # tracer: sched_switch
 #
 #           TASK-PID    CPU#                  TIMESTAMP  FUNCTION
 #              | |       |                        |         |
           <idle>-0     [000] 2009-07-25 18:01:00.848468:      0:140:R ==> [000]     5:115:R events/0
         events/0-5     [000] 2009-07-25 18:01:00.848523:      5:115:S ==> [000]     0:140:R <idle>
           <idle>-0     [000] 2009-07-25 18:01:01.613479:      0:140:R   + [000]  2455:120:S sshd
           <idle>-0     [000] 2009-07-25 18:01:01.613678:      0:140:R ==> [000]  2455:120:R sshd
             sshd-2455  [000] 2009-07-25 18:01:01.614015:   2455:120:S   + [000]  2455:120:S sshd
 ...

Signed-off-by: Zhao Lei <zhaolei@...fujitsu.com>
---
 kernel/trace/trace.c        |   14 ++++++++++++--
 kernel/trace/trace.h        |    1 +
 kernel/trace/trace_output.c |   21 +++++++++++++++++----
 3 files changed, 30 insertions(+), 6 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index af25bec..4e360cf 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -326,6 +326,7 @@ static const char *trace_options[] = {
 	"global-clock",
 	"sleep-time",
 	"graph-time",
+	"walltime",
 	NULL
 };
 
@@ -1601,8 +1602,17 @@ static void print_lat_help_header(struct seq_file *m)
 
 static void print_func_help_header(struct seq_file *m)
 {
-	seq_puts(m, "#           TASK-PID    CPU#    TIMESTAMP  FUNCTION\n");
-	seq_puts(m, "#              | |       |          |         |\n");
+	if (trace_flags & TRACE_ITER_WALLTIME) {
+		seq_puts(m, "#           TASK-PID    CPU# "
+			"                 TIMESTAMP  FUNCTION\n");
+		seq_puts(m, "#              | |       |   "
+			"                     |         |\n");
+	} else {
+		seq_puts(m, "#           TASK-PID    CPU# "
+			"   TIMESTAMP  FUNCTION\n");
+		seq_puts(m, "#              | |       |   "
+			"       |         |\n");
+	}
 }
 
 
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index fb3dcc8..0860b3b 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -664,6 +664,7 @@ enum trace_iterator_flags {
 	TRACE_ITER_GLOBAL_CLK		= 0x80000,
 	TRACE_ITER_SLEEP_TIME		= 0x100000,
 	TRACE_ITER_GRAPH_TIME		= 0x200000,
+	TRACE_ITER_WALLTIME		= 0x400000, /* Print walltime */
 };
 
 /*
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index f5c7f0c..3a52bb5 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -501,15 +501,28 @@ int trace_print_context(struct trace_iterator *iter)
 {
 	struct trace_seq *s = &iter->seq;
 	struct trace_entry *entry = iter->ent;
-	unsigned long long t = ns2usecs(iter->ts);
-	unsigned long usec_rem = do_div(t, USEC_PER_SEC);
-	unsigned long secs = (unsigned long)t;
 	char comm[TASK_COMM_LEN];
 
 	trace_find_cmdline(entry->pid, comm);
 
-	return trace_seq_printf(s, "%16s-%-5d [%03d] %5lu.%06lu: ",
+	if (trace_flags & TRACE_ITER_WALLTIME) {
+		struct tm tm;
+		localtime_r(iter->timespec.tv_sec, &tm);
+		return trace_seq_printf(s, "%16s-%-5d [%03d] "
+					"%04u-%02u-%02u "
+					"%02u:%02u:%02u.%06llu: ",
+					comm, entry->pid, iter->cpu,
+					tm.tm_year + 1900, tm.tm_mon + 1,
+					tm.tm_mday, tm.tm_hour, tm.tm_min,
+					tm.tm_sec,
+					ns2usecs(iter->timespec.tv_nsec));
+	} else {
+		unsigned long long t = ns2usecs(iter->ts);
+		unsigned long usec_rem = do_div(t, USEC_PER_SEC);
+		unsigned long secs = (unsigned long)t;
+		return trace_seq_printf(s, "%16s-%-5d [%03d] %5lu.%06lu: ",
 				comm, entry->pid, iter->cpu, secs, usec_rem);
+	}
 }
 
 int trace_print_lat_context(struct trace_iterator *iter)
-- 
1.5.5.3


--
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/