* [PATCH v2 1/3] perf tools: Record total sampling time
@ 2013-12-03 9:00 Namhyung Kim
2013-12-03 9:00 ` [PATCH v2 2/3] perf tools: Record sampling time for each entry Namhyung Kim
2013-12-03 9:00 ` [PATCH v2 3/3] perf report: Add --event-time option Namhyung Kim
0 siblings, 2 replies; 5+ messages in thread
From: Namhyung Kim @ 2013-12-03 9:00 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo
Cc: Peter Zijlstra, Paul Mackerras, Ingo Molnar, Namhyung Kim, LKML,
Jiri Olsa, David Ahern, Stephane Eranian, Andi Kleen,
Pekka Enberg, Frederic Weisbecker
From: Namhyung Kim <namhyung.kim@lge.com>
It's sometimes useful to see total sampling or elapsed time with
normal performance result. To do that, record first and last sample
time for each evsel and to display it in the header (--stdio only for
now).
$ perf record -a sleep 1
$ perf report --stdio
...
# Samples: 4K of event 'cycles'
# Event count (approx.): 4087481688
# Total sampling time : 1.001260 (sec)
#
# Overhead Command Shared Object Symbol
# ........ ............ .......................... .......................
#
89.06% nautilus libgobject-2.0.so.0.3701.0 [.] 0x0000000000020bf0
1.79% kworker/1:0 [kernel.kallsyms] [k] generic_exec_single
1.75% swapper [kernel.kallsyms] [k] intel_idle
1.14% nautilus [unknown] [.] 0x0000003153f2ff61
0.69% kworker/0:1 [kernel.kallsyms] [k] generic_exec_single
0.67% nautilus ld-2.17.so [.] do_lookup_x
Reviewed-by: Pekka Enberg <penberg@kernel.org>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/builtin-report.c | 15 ++++++++++++++-
tools/perf/util/evsel.h | 2 ++
tools/perf/util/hist.h | 1 +
tools/perf/util/session.c | 7 +++++++
4 files changed, 24 insertions(+), 1 deletion(-)
diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
index 8cf8e66ba594..1d47fbec4421 100644
--- a/tools/perf/builtin-report.c
+++ b/tools/perf/builtin-report.c
@@ -456,6 +456,14 @@ static size_t hists__fprintf_nr_sample_events(struct perf_report *rep,
ret += fprintf(fp, "\n# Sort order : %s", sort_order);
} else
ret += fprintf(fp, "\n# Event count (approx.): %" PRIu64, nr_events);
+ if (rep->tool.ordered_samples) {
+ u64 total_time = hists->stats.total_time;
+ u64 sec = total_time / NSEC_PER_SEC;
+ u64 usec = (total_time - sec * NSEC_PER_SEC) / NSEC_PER_USEC;
+
+ ret += fprintf(fp, "\n# Total sampling time : "
+ "%" PRIu64 ".%06" PRIu64 " (sec)", sec, usec);
+ }
return ret + fprintf(fp, "\n#\n");
}
@@ -565,8 +573,13 @@ static int __cmd_report(struct perf_report *rep)
}
nr_samples = 0;
- list_for_each_entry(pos, &session->evlist->entries, node)
+ list_for_each_entry(pos, &session->evlist->entries, node) {
nr_samples += pos->hists.nr_entries;
+ if (rep->tool.ordered_samples) {
+ pos->hists.stats.total_time = pos->last_timestamp -
+ pos->first_timestamp;
+ }
+ }
ui_progress__init(&prog, nr_samples, "Merging related events...");
diff --git a/tools/perf/util/evsel.h b/tools/perf/util/evsel.h
index 8120eeb86ac1..20a7c653b74b 100644
--- a/tools/perf/util/evsel.h
+++ b/tools/perf/util/evsel.h
@@ -67,6 +67,8 @@ struct perf_evsel {
int idx;
u32 ids;
struct hists hists;
+ u64 first_timestamp;
+ u64 last_timestamp;
char *name;
double scale;
const char *unit;
diff --git a/tools/perf/util/hist.h b/tools/perf/util/hist.h
index b621347a1585..bc5acdfc2b4b 100644
--- a/tools/perf/util/hist.h
+++ b/tools/perf/util/hist.h
@@ -28,6 +28,7 @@ struct symbol;
*/
struct events_stats {
u64 total_period;
+ u64 total_time;
u64 total_lost;
u64 total_invalid_chains;
u32 nr_events[PERF_RECORD_HEADER_MAX];
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index 4ce146bae552..e4b158f0586a 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -925,6 +925,13 @@ perf_session__deliver_sample(struct perf_session *session,
u64 sample_type = evsel->attr.sample_type;
u64 read_format = evsel->attr.read_format;
+ if (tool->ordered_samples) {
+ if (evsel->first_timestamp == 0)
+ evsel->first_timestamp = sample->time;
+
+ evsel->last_timestamp = sample->time;
+ }
+
/* Standard sample delievery. */
if (!(sample_type & PERF_SAMPLE_READ))
return tool->sample(tool, event, sample, evsel, machine);
--
1.7.11.7
^ permalink raw reply related [flat|nested] 5+ messages in thread
* [PATCH v2 2/3] perf tools: Record sampling time for each entry
2013-12-03 9:00 [PATCH v2 1/3] perf tools: Record total sampling time Namhyung Kim
@ 2013-12-03 9:00 ` Namhyung Kim
2013-12-03 16:20 ` David Ahern
2013-12-03 9:00 ` [PATCH v2 3/3] perf report: Add --event-time option Namhyung Kim
1 sibling, 1 reply; 5+ messages in thread
From: Namhyung Kim @ 2013-12-03 9:00 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo
Cc: Peter Zijlstra, Paul Mackerras, Ingo Molnar, Namhyung Kim, LKML,
Jiri Olsa, David Ahern, Stephane Eranian, Andi Kleen,
Pekka Enberg, Frederic Weisbecker
From: Namhyung Kim <namhyung.kim@lge.com>
Sometimes users might want see a relation between value and time of a
sample. And the time itself is a very important information to have.
As the sample->period value is a diff of counter values between samples
it might make sense to add time-diff between samples into a hist entry.
To do that, calculate elapsed time for each sample and record it. The
elapsed time is the diff between current sample->time and previous
sample->time which was saved for each evsel.
Maybe we can use PERF_SAMPLE_READ for the precise result.
Reviewed-by: Pekka Enberg <penberg@kernel.org>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/builtin-annotate.c | 2 +-
tools/perf/builtin-diff.c | 2 +-
tools/perf/builtin-report.c | 9 +++++----
tools/perf/builtin-top.c | 2 +-
tools/perf/tests/hists_link.c | 4 ++--
tools/perf/util/evsel.h | 1 +
tools/perf/util/hist.c | 10 ++++++++--
tools/perf/util/hist.h | 2 +-
tools/perf/util/session.c | 42 ++++++++++++++++++++++++++++++++++++++++++
tools/perf/util/sort.h | 1 +
10 files changed, 63 insertions(+), 12 deletions(-)
diff --git a/tools/perf/builtin-annotate.c b/tools/perf/builtin-annotate.c
index 4087ab19823c..dc43a64bf723 100644
--- a/tools/perf/builtin-annotate.c
+++ b/tools/perf/builtin-annotate.c
@@ -65,7 +65,7 @@ static int perf_evsel__add_sample(struct perf_evsel *evsel,
return 0;
}
- he = __hists__add_entry(&evsel->hists, al, NULL, NULL, NULL, 1, 1, 0);
+ he = __hists__add_entry(&evsel->hists, al, NULL, NULL, NULL, 1, 0, 1, 0);
if (he == NULL)
return -ENOMEM;
diff --git a/tools/perf/builtin-diff.c b/tools/perf/builtin-diff.c
index 3b67ea2444bd..85aa961a647e 100644
--- a/tools/perf/builtin-diff.c
+++ b/tools/perf/builtin-diff.c
@@ -307,7 +307,7 @@ static int hists__add_entry(struct hists *hists,
struct addr_location *al, u64 period,
u64 weight, u64 transaction)
{
- if (__hists__add_entry(hists, al, NULL, NULL, NULL, period, weight,
+ if (__hists__add_entry(hists, al, NULL, NULL, NULL, period, 0, weight,
transaction) != NULL)
return 0;
return -ENOMEM;
diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
index 1d47fbec4421..eb849e9f7093 100644
--- a/tools/perf/builtin-report.c
+++ b/tools/perf/builtin-report.c
@@ -116,7 +116,7 @@ static int perf_report__add_mem_hist_entry(struct perf_tool *tool,
* and the he_stat__add_period() function.
*/
he = __hists__add_entry(&evsel->hists, al, parent, NULL, mi,
- cost, cost, 0);
+ cost, 0, cost, 0);
if (!he)
return -ENOMEM;
@@ -210,7 +210,7 @@ static int perf_report__add_branch_hist_entry(struct perf_tool *tool,
* and not events sampled. Thus we use a pseudo period of 1.
*/
he = __hists__add_entry(&evsel->hists, al, parent, &bi[i], NULL,
- 1, 1, 0);
+ 1, 0, 1, 0);
if (he) {
struct annotation *notes;
bx = he->branch_info;
@@ -272,8 +272,9 @@ static int perf_evsel__add_hist_entry(struct perf_tool *tool,
}
he = __hists__add_entry(&evsel->hists, al, parent, NULL, NULL,
- sample->period, sample->weight,
- sample->transaction);
+ sample->period,
+ tool->ordered_samples ? sample->read.time_enabled : 0,
+ sample->weight, sample->transaction);
if (he == NULL)
return -ENOMEM;
diff --git a/tools/perf/builtin-top.c b/tools/perf/builtin-top.c
index 03d37a76c612..175bde2a0ece 100644
--- a/tools/perf/builtin-top.c
+++ b/tools/perf/builtin-top.c
@@ -247,7 +247,7 @@ static struct hist_entry *perf_evsel__add_hist_entry(struct perf_evsel *evsel,
pthread_mutex_lock(&evsel->hists.lock);
he = __hists__add_entry(&evsel->hists, al, NULL, NULL, NULL,
- sample->period, sample->weight,
+ sample->period, 0, sample->weight,
sample->transaction);
pthread_mutex_unlock(&evsel->hists.lock);
if (he == NULL)
diff --git a/tools/perf/tests/hists_link.c b/tools/perf/tests/hists_link.c
index 173bf42cc03e..7bb952e6be62 100644
--- a/tools/perf/tests/hists_link.c
+++ b/tools/perf/tests/hists_link.c
@@ -223,7 +223,7 @@ static int add_hist_entries(struct perf_evlist *evlist, struct machine *machine)
goto out;
he = __hists__add_entry(&evsel->hists, &al, NULL,
- NULL, NULL, 1, 1, 0);
+ NULL, NULL, 1, 0, 1, 0);
if (he == NULL)
goto out;
@@ -246,7 +246,7 @@ static int add_hist_entries(struct perf_evlist *evlist, struct machine *machine)
goto out;
he = __hists__add_entry(&evsel->hists, &al, NULL,
- NULL, NULL, 1, 1, 0);
+ NULL, NULL, 1, 0, 1, 0);
if (he == NULL)
goto out;
diff --git a/tools/perf/util/evsel.h b/tools/perf/util/evsel.h
index 20a7c653b74b..ac65fc67972c 100644
--- a/tools/perf/util/evsel.h
+++ b/tools/perf/util/evsel.h
@@ -69,6 +69,7 @@ struct perf_evsel {
struct hists hists;
u64 first_timestamp;
u64 last_timestamp;
+ u64 *prev_timestamps;
char *name;
double scale;
const char *unit;
diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
index 6ea46ec6593e..8b66921fc1bd 100644
--- a/tools/perf/util/hist.c
+++ b/tools/perf/util/hist.c
@@ -204,11 +204,12 @@ static void hist_entry__add_cpumode_period(struct hist_entry *he,
}
static void he_stat__add_period(struct he_stat *he_stat, u64 period,
- u64 weight)
+ u64 sample_time, u64 weight)
{
he_stat->period += period;
he_stat->weight += weight;
+ he_stat->time += sample_time;
he_stat->nr_events += 1;
}
@@ -221,10 +222,12 @@ static void he_stat__add_stat(struct he_stat *dest, struct he_stat *src)
dest->period_guest_us += src->period_guest_us;
dest->nr_events += src->nr_events;
dest->weight += src->weight;
+ dest->time += src->time;
}
static void hist_entry__decay(struct hist_entry *he)
{
+ he->stat.time = (he->stat.time * 7) / 8;
he->stat.period = (he->stat.period * 7) / 8;
he->stat.nr_events = (he->stat.nr_events * 7) / 8;
/* XXX need decay for weight too? */
@@ -366,6 +369,7 @@ static struct hist_entry *add_hist_entry(struct hists *hists,
if (!cmp) {
he_stat__add_period(&he->stat, entry->stat.period,
+ entry->stat.time,
entry->stat.weight);
/*
@@ -411,7 +415,8 @@ struct hist_entry *__hists__add_entry(struct hists *hists,
struct symbol *sym_parent,
struct branch_info *bi,
struct mem_info *mi,
- u64 period, u64 weight, u64 transaction)
+ u64 period, u64 sample_time,
+ u64 weight, u64 transaction)
{
struct hist_entry entry = {
.thread = al->thread,
@@ -427,6 +432,7 @@ struct hist_entry *__hists__add_entry(struct hists *hists,
.nr_events = 1,
.period = period,
.weight = weight,
+ .time = sample_time,
},
.parent = sym_parent,
.filtered = symbol__parent_filter(sym_parent),
diff --git a/tools/perf/util/hist.h b/tools/perf/util/hist.h
index bc5acdfc2b4b..0433469812dc 100644
--- a/tools/perf/util/hist.h
+++ b/tools/perf/util/hist.h
@@ -89,7 +89,7 @@ struct hist_entry *__hists__add_entry(struct hists *hists,
struct addr_location *al,
struct symbol *parent,
struct branch_info *bi,
- struct mem_info *mi, u64 period,
+ struct mem_info *mi, u64 period, u64 time,
u64 weight, u64 transaction);
int64_t hist_entry__cmp(struct hist_entry *left, struct hist_entry *right);
int64_t hist_entry__collapse(struct hist_entry *left, struct hist_entry *right);
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index e4b158f0586a..f36e95f00a05 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -926,6 +926,48 @@ perf_session__deliver_sample(struct perf_session *session,
u64 read_format = evsel->attr.read_format;
if (tool->ordered_samples) {
+ /* FIXME: need to find a way to determine cpu-wide session */
+ bool per_cpu_session = sample_type & PERF_SAMPLE_CPU;
+
+ sample->read.time_enabled = 0;
+
+ if (per_cpu_session) {
+ u64 *ts = evsel->prev_timestamps;
+
+ if (ts == NULL) {
+ int nr_cpus = session->header.env.nr_cpus_online;
+
+ ts = zalloc(nr_cpus * sizeof(ts));
+ if (ts == NULL)
+ return -ENOMEM;
+
+ evsel->prev_timestamps = ts;
+ }
+
+ if (ts[sample->cpu] != 0) {
+ u64 diff = sample->time - ts[sample->cpu];
+
+ sample->read.time_enabled = diff;
+ }
+ ts[sample->cpu] = sample->time;
+ } else {
+ u64 *ts = evsel->prev_timestamps;
+
+ if (ts == NULL) {
+ ts = zalloc(sizeof(*ts));
+ if (ts == NULL)
+ return -ENOMEM;
+
+ evsel->prev_timestamps = ts;
+ }
+
+ if (*ts != 0) {
+ u64 diff = sample->time - *ts;
+ sample->read.time_enabled = diff;
+ }
+ *ts = sample->time;
+ }
+
if (evsel->first_timestamp == 0)
evsel->first_timestamp = sample->time;
diff --git a/tools/perf/util/sort.h b/tools/perf/util/sort.h
index 43e5ff42a609..16aaf0a47346 100644
--- a/tools/perf/util/sort.h
+++ b/tools/perf/util/sort.h
@@ -51,6 +51,7 @@ struct he_stat {
u64 period_guest_sys;
u64 period_guest_us;
u64 weight;
+ u64 time;
u32 nr_events;
};
--
1.7.11.7
^ permalink raw reply related [flat|nested] 5+ messages in thread
* [PATCH v2 3/3] perf report: Add --event-time option
2013-12-03 9:00 [PATCH v2 1/3] perf tools: Record total sampling time Namhyung Kim
2013-12-03 9:00 ` [PATCH v2 2/3] perf tools: Record sampling time for each entry Namhyung Kim
@ 2013-12-03 9:00 ` Namhyung Kim
1 sibling, 0 replies; 5+ messages in thread
From: Namhyung Kim @ 2013-12-03 9:00 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo
Cc: Peter Zijlstra, Paul Mackerras, Ingo Molnar, Namhyung Kim, LKML,
Jiri Olsa, David Ahern, Stephane Eranian, Andi Kleen,
Pekka Enberg, Frederic Weisbecker
From: Namhyung Kim <namhyung.kim@lge.com>
The --event-time option is for displaying elapsed sampling time
information for each entry.
$ perf record -- perf bench sched messaging
$ perf report --stdio --event-time
...
# Samples: 10K of event 'cycles'
# Event count (approx.): 5118793536
# Total sampling time : 0.184277 (sec)
#
# Overhead Time Command Shared Object Symbol
# ........ .......... ............... ................. ...........................
#
7.26% 0.007413 sched-messaging [unknown] [.] 0x0000003153e7a6e7
4.79% 0.006088 sched-messaging [kernel.kallsyms] [k] avc_has_perm_flags
4.38% 0.004809 sched-messaging [kernel.kallsyms] [k] copy_user_generic_string
3.81% 0.005457 sched-messaging [kernel.kallsyms] [k] _raw_spin_lock
2.92% 0.002745 sched-messaging [kernel.kallsyms] [k] _raw_spin_lock_irqsave
2.72% 0.002896 sched-messaging [kernel.kallsyms] [k] unix_stream_recvmsg
2.55% 0.003745 sched-messaging [kernel.kallsyms] [k] __slab_free
2.45% 0.002807 sched-messaging [kernel.kallsyms] [k] page_fault
2.08% 0.002258 sched-messaging [kernel.kallsyms] [k] sock_has_perm
Reviewed-by: Pekka Enberg <penberg@kernel.org>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/Documentation/perf-report.txt | 6 +++
tools/perf/builtin-report.c | 2 +
tools/perf/ui/hist.c | 68 ++++++++++++++++++++++++++------
tools/perf/util/hist.h | 1 +
tools/perf/util/symbol.h | 3 +-
5 files changed, 68 insertions(+), 12 deletions(-)
diff --git a/tools/perf/Documentation/perf-report.txt b/tools/perf/Documentation/perf-report.txt
index 10a279871251..f420eef2b77f 100644
--- a/tools/perf/Documentation/perf-report.txt
+++ b/tools/perf/Documentation/perf-report.txt
@@ -237,6 +237,12 @@ OPTIONS
Do not show entries which have an overhead under that percent.
(Default: 0).
+--event-time::
+ Show a column with elapsed sample times. It could be useful when you
+ want to see a relation between time and period of samples. The elapsed
+ time is a sum of time-diff between two adjacent samples of a event as
+ sample period is a diff of counter values between the two samples.
+
SEE ALSO
--------
linkperf:perf-stat[1], linkperf:perf-annotate[1]
diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
index eb849e9f7093..c4e958bc96a7 100644
--- a/tools/perf/builtin-report.c
+++ b/tools/perf/builtin-report.c
@@ -898,6 +898,8 @@ int cmd_report(int argc, const char **argv, const char *prefix __maybe_unused)
OPT_BOOLEAN(0, "mem-mode", &report.mem_mode, "mem access profile"),
OPT_CALLBACK(0, "percent-limit", &report, "percent",
"Don't show entries under that percent", parse_percent_limit),
+ OPT_BOOLEAN(0, "event-time", &symbol_conf.show_event_time,
+ "Show a column with the elapsed time"),
OPT_END()
};
struct perf_data_file file = {
diff --git a/tools/perf/ui/hist.c b/tools/perf/ui/hist.c
index 78f4c92e9b73..2f075f447599 100644
--- a/tools/perf/ui/hist.c
+++ b/tools/perf/ui/hist.c
@@ -7,19 +7,24 @@
#include "../util/evsel.h"
/* hist period print (hpp) functions */
+enum hpp_fmt_type {
+ HPP_FMT__PERCENT,
+ HPP_FMT__RAW,
+ HPP_FMT__TIME,
+};
typedef int (*hpp_snprint_fn)(char *buf, size_t size, const char *fmt, ...);
static int __hpp__fmt(struct perf_hpp *hpp, struct hist_entry *he,
u64 (*get_field)(struct hist_entry *),
const char *fmt, hpp_snprint_fn print_fn,
- bool fmt_percent)
+ enum hpp_fmt_type type)
{
int ret;
struct hists *hists = he->hists;
struct perf_evsel *evsel = hists_to_evsel(hists);
- if (fmt_percent) {
+ if (type == HPP_FMT__PERCENT) {
double percent = 0.0;
if (hists->stats.total_period)
@@ -27,8 +32,15 @@ static int __hpp__fmt(struct perf_hpp *hpp, struct hist_entry *he,
hists->stats.total_period;
ret = print_fn(hpp->buf, hpp->size, fmt, percent);
- } else
+ } else if (type == HPP_FMT__RAW) {
ret = print_fn(hpp->buf, hpp->size, fmt, get_field(he));
+ } else if (type == HPP_FMT__TIME) {
+ u64 time = get_field(he);
+ u64 sec = time / NSEC_PER_SEC;
+ u64 usec = (time - sec * NSEC_PER_SEC) / NSEC_PER_USEC;
+
+ ret = print_fn(hpp->buf, hpp->size, fmt, sec, usec);
+ }
if (perf_evsel__is_group_event(evsel)) {
int prev_idx, idx_delta;
@@ -53,15 +65,22 @@ static int __hpp__fmt(struct perf_hpp *hpp, struct hist_entry *he,
* have no sample
*/
ret += print_fn(hpp->buf + ret, hpp->size - ret,
- fmt, 0);
+ fmt, 0, 0);
}
- if (fmt_percent)
+ if (type == HPP_FMT__PERCENT)
ret += print_fn(hpp->buf + ret, hpp->size - ret,
fmt, 100.0 * period / total);
- else
+ else if (type == HPP_FMT__RAW)
ret += print_fn(hpp->buf + ret, hpp->size - ret,
fmt, period);
+ else if (type == HPP_FMT__TIME) {
+ u64 sec = period / NSEC_PER_SEC;
+ u64 usec = (period - sec * NSEC_PER_SEC) / NSEC_PER_USEC;
+
+ ret += print_fn(hpp->buf + ret, hpp->size - ret,
+ fmt, sec, usec);
+ }
prev_idx = perf_evsel__group_idx(evsel);
}
@@ -73,7 +92,7 @@ static int __hpp__fmt(struct perf_hpp *hpp, struct hist_entry *he,
* zero-fill group members at last which have no sample
*/
ret += print_fn(hpp->buf + ret, hpp->size - ret,
- fmt, 0);
+ fmt, 0, 0);
}
}
return ret;
@@ -117,7 +136,7 @@ static int hpp__color_##_type(struct perf_hpp_fmt *fmt __maybe_unused, \
struct perf_hpp *hpp, struct hist_entry *he) \
{ \
return __hpp__fmt(hpp, he, he_get_##_field, " %6.2f%%", \
- percent_color_snprintf, true); \
+ percent_color_snprintf, HPP_FMT__PERCENT); \
}
#define __HPP_ENTRY_PERCENT_FN(_type, _field) \
@@ -126,7 +145,7 @@ static int hpp__entry_##_type(struct perf_hpp_fmt *_fmt __maybe_unused, \
{ \
const char *fmt = symbol_conf.field_sep ? " %.2f" : " %6.2f%%"; \
return __hpp__fmt(hpp, he, he_get_##_field, fmt, \
- scnprintf, true); \
+ scnprintf, HPP_FMT__PERCENT); \
}
#define __HPP_ENTRY_RAW_FN(_type, _field) \
@@ -139,7 +158,23 @@ static int hpp__entry_##_type(struct perf_hpp_fmt *_fmt __maybe_unused, \
struct perf_hpp *hpp, struct hist_entry *he) \
{ \
const char *fmt = symbol_conf.field_sep ? " %"PRIu64 : " %11"PRIu64; \
- return __hpp__fmt(hpp, he, he_get_raw_##_field, fmt, scnprintf, false); \
+ return __hpp__fmt(hpp, he, he_get_raw_##_field, fmt, scnprintf, \
+ HPP_FMT__RAW); \
+}
+
+#define __HPP_ENTRY_TIME_FN(_type, _field) \
+static u64 he_get_raw_##_field(struct hist_entry *he) \
+{ \
+ return he->stat._field; \
+} \
+ \
+static int hpp__entry_##_type(struct perf_hpp_fmt *_fmt __maybe_unused, \
+ struct perf_hpp *hpp, struct hist_entry *he) \
+{ \
+ const char *fmt = symbol_conf.field_sep ? " %"PRIu64 ".%06"PRIu64 : \
+ " %2"PRIu64 ".%06"PRIu64; \
+ return __hpp__fmt(hpp, he, he_get_raw_##_field, fmt, scnprintf, \
+ HPP_FMT__TIME); \
}
#define HPP_PERCENT_FNS(_type, _str, _field, _min_width, _unit_width) \
@@ -153,6 +188,11 @@ __HPP_HEADER_FN(_type, _str, _min_width, _unit_width) \
__HPP_WIDTH_FN(_type, _min_width, _unit_width) \
__HPP_ENTRY_RAW_FN(_type, _field)
+#define HPP_TIME_FNS(_type, _str, _field, _min_width, _unit_width) \
+__HPP_HEADER_FN(_type, _str, _min_width, _unit_width) \
+__HPP_WIDTH_FN(_type, _min_width, _unit_width) \
+__HPP_ENTRY_TIME_FN(_type, _field)
+
HPP_PERCENT_FNS(overhead, "Overhead", period, 8, 8)
HPP_PERCENT_FNS(overhead_sys, "sys", period_sys, 8, 8)
@@ -163,6 +203,8 @@ HPP_PERCENT_FNS(overhead_guest_us, "guest usr", period_guest_us, 9, 8)
HPP_RAW_FNS(samples, "Samples", nr_events, 12, 12)
HPP_RAW_FNS(period, "Period", period, 12, 12)
+HPP_TIME_FNS(time, "Time", time, 10, 10)
+
#define HPP__COLOR_PRINT_FNS(_name) \
{ \
.header = hpp__header_ ## _name, \
@@ -185,7 +227,8 @@ struct perf_hpp_fmt perf_hpp__format[] = {
HPP__COLOR_PRINT_FNS(overhead_guest_sys),
HPP__COLOR_PRINT_FNS(overhead_guest_us),
HPP__PRINT_FNS(samples),
- HPP__PRINT_FNS(period)
+ HPP__PRINT_FNS(period),
+ HPP__PRINT_FNS(time)
};
LIST_HEAD(perf_hpp__list);
@@ -223,6 +266,9 @@ void perf_hpp__init(void)
if (symbol_conf.show_total_period)
perf_hpp__column_enable(PERF_HPP__PERIOD);
+
+ if (symbol_conf.show_event_time)
+ perf_hpp__column_enable(PERF_HPP__TIME);
}
void perf_hpp__column_register(struct perf_hpp_fmt *format)
diff --git a/tools/perf/util/hist.h b/tools/perf/util/hist.h
index 0433469812dc..17e89fb31db9 100644
--- a/tools/perf/util/hist.h
+++ b/tools/perf/util/hist.h
@@ -162,6 +162,7 @@ enum {
PERF_HPP__OVERHEAD_GUEST_US,
PERF_HPP__SAMPLES,
PERF_HPP__PERIOD,
+ PERF_HPP__TIME,
PERF_HPP__MAX_INDEX
};
diff --git a/tools/perf/util/symbol.h b/tools/perf/util/symbol.h
index f1031a1358a1..599892b75cbc 100644
--- a/tools/perf/util/symbol.h
+++ b/tools/perf/util/symbol.h
@@ -99,7 +99,8 @@ struct symbol_conf {
annotate_asm_raw,
annotate_src,
event_group,
- demangle;
+ demangle,
+ show_event_time;
const char *vmlinux_name,
*kallsyms_name,
*source_prefix,
--
1.7.11.7
^ permalink raw reply related [flat|nested] 5+ messages in thread
* Re: [PATCH v2 2/3] perf tools: Record sampling time for each entry
2013-12-03 9:00 ` [PATCH v2 2/3] perf tools: Record sampling time for each entry Namhyung Kim
@ 2013-12-03 16:20 ` David Ahern
2013-12-09 7:59 ` Namhyung Kim
0 siblings, 1 reply; 5+ messages in thread
From: David Ahern @ 2013-12-03 16:20 UTC (permalink / raw)
To: Namhyung Kim, Arnaldo Carvalho de Melo
Cc: Peter Zijlstra, Paul Mackerras, Ingo Molnar, Namhyung Kim, LKML,
Jiri Olsa, Stephane Eranian, Andi Kleen, Pekka Enberg,
Frederic Weisbecker
On 12/3/13, 2:00 AM, Namhyung Kim wrote:
> diff --git a/tools/perf/util/evsel.h b/tools/perf/util/evsel.h
> index 20a7c653b74b..ac65fc67972c 100644
> --- a/tools/perf/util/evsel.h
> +++ b/tools/perf/util/evsel.h
> @@ -69,6 +69,7 @@ struct perf_evsel {
> struct hists hists;
> u64 first_timestamp;
> u64 last_timestamp;
> + u64 *prev_timestamps;
Why plural and why dynamically allocated? The allocation only does a
single u64, not an array.
David
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH v2 2/3] perf tools: Record sampling time for each entry
2013-12-03 16:20 ` David Ahern
@ 2013-12-09 7:59 ` Namhyung Kim
0 siblings, 0 replies; 5+ messages in thread
From: Namhyung Kim @ 2013-12-09 7:59 UTC (permalink / raw)
To: David Ahern
Cc: Arnaldo Carvalho de Melo, Peter Zijlstra, Paul Mackerras,
Ingo Molnar, Namhyung Kim, LKML, Jiri Olsa, Stephane Eranian,
Andi Kleen, Pekka Enberg, Frederic Weisbecker
Hi David,
On Tue, 03 Dec 2013 09:20:23 -0700, David Ahern wrote:
> On 12/3/13, 2:00 AM, Namhyung Kim wrote:
>> diff --git a/tools/perf/util/evsel.h b/tools/perf/util/evsel.h
>> index 20a7c653b74b..ac65fc67972c 100644
>> --- a/tools/perf/util/evsel.h
>> +++ b/tools/perf/util/evsel.h
>> @@ -69,6 +69,7 @@ struct perf_evsel {
>> struct hists hists;
>> u64 first_timestamp;
>> u64 last_timestamp;
>> + u64 *prev_timestamps;
>
>
> Why plural and why dynamically allocated? The allocation only does a
> single u64, not an array.
Nope, it'll be an array if the session was a system-wide one, so plural.
But, I think the current code won't work well if there're multiple
unrelated processes recorded - e.g. perf record -u `id -u` - since it'll
intermix all timestamps between the samples regardless of process.
Hmm.. I think there's not much thing we can do for this without help
from kernel side (PERF_SAMPLE_READ?). So I'll just drop this unless I
can come up with a better idea. But the patch 1/3 still makes some
sense and worth to merge by itself IMHO.
What do you think?
Thanks,
Namhyung
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2013-12-09 7:59 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2013-12-03 9:00 [PATCH v2 1/3] perf tools: Record total sampling time Namhyung Kim
2013-12-03 9:00 ` [PATCH v2 2/3] perf tools: Record sampling time for each entry Namhyung Kim
2013-12-03 16:20 ` David Ahern
2013-12-09 7:59 ` Namhyung Kim
2013-12-03 9:00 ` [PATCH v2 3/3] perf report: Add --event-time option Namhyung Kim
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox