Skip to content

Commit e534bfb

Browse files
olsajiriacmel
olsajiri
authored and
acmel
committed
perf script: Add 'tod' field to display time of day
Add a 'tod' field to display time of day column with time of date (wallclock) time. # perf record -k CLOCK_MONOTONIC kill kill: not enough arguments [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.033 MB perf.data (8 samples) ] # perf script perf 261340 152919.481538: 1 cycles: ffffffff8106d104 ... perf 261340 152919.481543: 1 cycles: ffffffff8106d104 ... perf 261340 152919.481545: 7 cycles: ffffffff8106d104 ... ... # perf script --ns perf 261340 152919.481538922: 1 cycles: ffffffff8106d ... perf 261340 152919.481543286: 1 cycles: ffffffff8106d ... perf 261340 152919.481545397: 7 cycles: ffffffff8106d ... ... # perf script -F+tod perf 261340 2020-07-13 18:26:55.620971 152919.481538: ... perf 261340 2020-07-13 18:26:55.620975 152919.481543: ... perf 261340 2020-07-13 18:26:55.620978 152919.481545: ... ... # perf script -F+tod --ns perf 261340 2020-07-13 18:26:55.620971621 152919.481538922: ... perf 261340 2020-07-13 18:26:55.620975985 152919.481543286: ... perf 261340 2020-07-13 18:26:55.620978096 152919.481545397: ... ... It's available only for recording with clockid specified, because it's the only case where we can get reference time to wallclock time. It's can't do that with perf clock yet. Error is display if you want to use --tod on data without clockid specified: # perf script -F+tod Can't provide 'tod' time, missing clock data. Please record with -k/--clockid option. Original-patch-by: David Ahern <[email protected]> Signed-off-by: Jiri Olsa <[email protected]> Cc: Alexander Shishkin <[email protected]> Cc: Andi Kleen <[email protected]> Cc: David Ahern <[email protected]> Cc: Geneviève Bastien <[email protected]> Cc: Ian Rogers <[email protected]> Cc: Jeremie Galarneau <[email protected]> Cc: Michael Petlan <[email protected]> Cc: Namhyung Kim <[email protected]> Cc: Peter Zijlstra <[email protected]> Cc: Wang Nan <[email protected]> Link: http://lore.kernel.org/lkml/[email protected] Signed-off-by: Arnaldo Carvalho de Melo <[email protected]>
1 parent 60e5eeb commit e534bfb

File tree

1 file changed

+98
-33
lines changed

1 file changed

+98
-33
lines changed

‎tools/perf/builtin-script.c

Lines changed: 98 additions & 33 deletions
Original file line numberDiff line numberDiff line change
@@ -114,6 +114,32 @@ enum perf_output_field {
114114
PERF_OUTPUT_MISC = 1ULL << 29,
115115
PERF_OUTPUT_SRCCODE = 1ULL << 30,
116116
PERF_OUTPUT_IPC = 1ULL << 31,
117+
PERF_OUTPUT_TOD = 1ULL << 32,
118+
};
119+
120+
struct perf_script {
121+
struct perf_tool tool;
122+
struct perf_session *session;
123+
bool show_task_events;
124+
bool show_mmap_events;
125+
bool show_switch_events;
126+
bool show_namespace_events;
127+
bool show_lost_events;
128+
bool show_round_events;
129+
bool show_bpf_events;
130+
bool show_cgroup_events;
131+
bool show_text_poke_events;
132+
bool allocated;
133+
bool per_event_dump;
134+
bool stitch_lbr;
135+
struct evswitch evswitch;
136+
struct perf_cpu_map *cpus;
137+
struct perf_thread_map *threads;
138+
int name_width;
139+
const char *time_str;
140+
struct perf_time_interval *ptime_range;
141+
int range_size;
142+
int range_num;
117143
};
118144

119145
struct output_option {
@@ -152,6 +178,7 @@ struct output_option {
152178
{.str = "misc", .field = PERF_OUTPUT_MISC},
153179
{.str = "srccode", .field = PERF_OUTPUT_SRCCODE},
154180
{.str = "ipc", .field = PERF_OUTPUT_IPC},
181+
{.str = "tod", .field = PERF_OUTPUT_TOD},
155182
};
156183

157184
enum {
@@ -502,6 +529,7 @@ static void set_print_ip_opts(struct perf_event_attr *attr)
502529
*/
503530
static int perf_session__check_output_opt(struct perf_session *session)
504531
{
532+
bool tod = false;
505533
unsigned int j;
506534
struct evsel *evsel;
507535

@@ -528,6 +556,7 @@ static int perf_session__check_output_opt(struct perf_session *session)
528556
continue;
529557

530558
set_print_ip_opts(&evsel->core.attr);
559+
tod |= output[j].fields & PERF_OUTPUT_TOD;
531560
}
532561

533562
if (!no_callchain) {
@@ -568,13 +597,17 @@ static int perf_session__check_output_opt(struct perf_session *session)
568597
}
569598
}
570599

600+
if (tod && !session->header.env.clock.enabled) {
601+
pr_err("Can't provide 'tod' time, missing clock data. "
602+
"Please record with -k/--clockid option.\n");
603+
return -1;
604+
}
571605
out:
572606
return 0;
573607
}
574608

575609
static int perf_sample__fprintf_regs(struct regs_dump *regs, uint64_t mask,
576-
FILE *fp
577-
)
610+
FILE *fp)
578611
{
579612
unsigned i = 0, r;
580613
int printed = 0;
@@ -592,6 +625,56 @@ static int perf_sample__fprintf_regs(struct regs_dump *regs, uint64_t mask,
592625
return printed;
593626
}
594627

628+
#define DEFAULT_TOD_FMT "%F %H:%M:%S"
629+
630+
static char*
631+
tod_scnprintf(struct perf_script *script, char *buf, int buflen,
632+
u64 timestamp)
633+
{
634+
u64 tod_ns, clockid_ns;
635+
struct perf_env *env;
636+
unsigned long nsec;
637+
struct tm ltime;
638+
char date[64];
639+
time_t sec;
640+
641+
buf[0] = '\0';
642+
if (buflen < 64 || !script)
643+
return buf;
644+
645+
env = &script->session->header.env;
646+
if (!env->clock.enabled) {
647+
scnprintf(buf, buflen, "disabled");
648+
return buf;
649+
}
650+
651+
clockid_ns = env->clock.clockid_ns;
652+
tod_ns = env->clock.tod_ns;
653+
654+
if (timestamp > clockid_ns)
655+
tod_ns += timestamp - clockid_ns;
656+
else
657+
tod_ns -= clockid_ns - timestamp;
658+
659+
sec = (time_t) (tod_ns / NSEC_PER_SEC);
660+
nsec = tod_ns - sec * NSEC_PER_SEC;
661+
662+
if (localtime_r(&sec, &ltime) == NULL) {
663+
scnprintf(buf, buflen, "failed");
664+
} else {
665+
strftime(date, sizeof(date), DEFAULT_TOD_FMT, &ltime);
666+
667+
if (symbol_conf.nanosecs) {
668+
snprintf(buf, buflen, "%s.%09lu", date, nsec);
669+
} else {
670+
snprintf(buf, buflen, "%s.%06lu",
671+
date, nsec / NSEC_PER_USEC);
672+
}
673+
}
674+
675+
return buf;
676+
}
677+
595678
static int perf_sample__fprintf_iregs(struct perf_sample *sample,
596679
struct perf_event_attr *attr, FILE *fp)
597680
{
@@ -606,7 +689,8 @@ static int perf_sample__fprintf_uregs(struct perf_sample *sample,
606689
attr->sample_regs_user, fp);
607690
}
608691

609-
static int perf_sample__fprintf_start(struct perf_sample *sample,
692+
static int perf_sample__fprintf_start(struct perf_script *script,
693+
struct perf_sample *sample,
610694
struct thread *thread,
611695
struct evsel *evsel,
612696
u32 type, FILE *fp)
@@ -615,6 +699,7 @@ static int perf_sample__fprintf_start(struct perf_sample *sample,
615699
unsigned long secs;
616700
unsigned long long nsecs;
617701
int printed = 0;
702+
char tstr[128];
618703

619704
if (PRINT_FIELD(COMM)) {
620705
if (latency_format)
@@ -683,6 +768,11 @@ static int perf_sample__fprintf_start(struct perf_sample *sample,
683768
printed += ret;
684769
}
685770

771+
if (PRINT_FIELD(TOD)) {
772+
tod_scnprintf(script, tstr, sizeof(tstr), sample->time);
773+
printed += fprintf(fp, "%s ", tstr);
774+
}
775+
686776
if (PRINT_FIELD(TIME)) {
687777
u64 t = sample->time;
688778
if (reltime) {
@@ -1667,31 +1757,6 @@ static int perf_sample__fprintf_synth(struct perf_sample *sample,
16671757
return 0;
16681758
}
16691759

1670-
struct perf_script {
1671-
struct perf_tool tool;
1672-
struct perf_session *session;
1673-
bool show_task_events;
1674-
bool show_mmap_events;
1675-
bool show_switch_events;
1676-
bool show_namespace_events;
1677-
bool show_lost_events;
1678-
bool show_round_events;
1679-
bool show_bpf_events;
1680-
bool show_cgroup_events;
1681-
bool show_text_poke_events;
1682-
bool allocated;
1683-
bool per_event_dump;
1684-
bool stitch_lbr;
1685-
struct evswitch evswitch;
1686-
struct perf_cpu_map *cpus;
1687-
struct perf_thread_map *threads;
1688-
int name_width;
1689-
const char *time_str;
1690-
struct perf_time_interval *ptime_range;
1691-
int range_size;
1692-
int range_num;
1693-
};
1694-
16951760
static int evlist__max_name_len(struct evlist *evlist)
16961761
{
16971762
struct evsel *evsel;
@@ -1739,7 +1804,7 @@ static void script_print_metric(struct perf_stat_config *config __maybe_unused,
17391804

17401805
if (!fmt)
17411806
return;
1742-
perf_sample__fprintf_start(mctx->sample, mctx->thread, mctx->evsel,
1807+
perf_sample__fprintf_start(NULL, mctx->sample, mctx->thread, mctx->evsel,
17431808
PERF_RECORD_SAMPLE, mctx->fp);
17441809
fputs("\tmetric: ", mctx->fp);
17451810
if (color)
@@ -1754,7 +1819,7 @@ static void script_new_line(struct perf_stat_config *config __maybe_unused,
17541819
{
17551820
struct metric_ctx *mctx = ctx;
17561821

1757-
perf_sample__fprintf_start(mctx->sample, mctx->thread, mctx->evsel,
1822+
perf_sample__fprintf_start(NULL, mctx->sample, mctx->thread, mctx->evsel,
17581823
PERF_RECORD_SAMPLE, mctx->fp);
17591824
fputs("\tmetric: ", mctx->fp);
17601825
}
@@ -1865,7 +1930,7 @@ static void process_event(struct perf_script *script,
18651930

18661931
++es->samples;
18671932

1868-
perf_sample__fprintf_start(sample, thread, evsel,
1933+
perf_sample__fprintf_start(script, sample, thread, evsel,
18691934
PERF_RECORD_SAMPLE, fp);
18701935

18711936
if (PRINT_FIELD(PERIOD))
@@ -2174,7 +2239,7 @@ static int print_event_with_time(struct perf_tool *tool,
21742239
thread = machine__findnew_thread(machine, pid, tid);
21752240

21762241
if (thread && evsel) {
2177-
perf_sample__fprintf_start(sample, thread, evsel,
2242+
perf_sample__fprintf_start(script, sample, thread, evsel,
21782243
event->header.type, stdout);
21792244
}
21802245

@@ -3439,7 +3504,7 @@ int cmd_script(int argc, const char **argv)
34393504
"Fields: comm,tid,pid,time,cpu,event,trace,ip,sym,dso,"
34403505
"addr,symoff,srcline,period,iregs,uregs,brstack,"
34413506
"brstacksym,flags,bpf-output,brstackinsn,brstackoff,"
3442-
"callindent,insn,insnlen,synth,phys_addr,metric,misc,ipc",
3507+
"callindent,insn,insnlen,synth,phys_addr,metric,misc,ipc,tod",
34433508
parse_output_fields),
34443509
OPT_BOOLEAN('a', "all-cpus", &system_wide,
34453510
"system-wide collection from all CPUs"),

0 commit comments

Comments
 (0)