builtin-trace.c 29 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734735736737738739740741742743744745746747748749750751752753754755756757758759760761762763764765766767768769770771772773774775776777778779780781782783784785786787788789790791792793794795796797798799800801802803804805806807808809810811812813814815816817818819820821822823824825826827828829830831832833834835836837838839840841842843844845846847848849850851852853854855856857858859860861862863864865866867868869870871872873874875876877878879880881882883884885886887888889890891892893894895896897898899900901902903904905906907908909910911912913914915916917918919920921922923924925926927928929930931932933934935936937938939940941942943944945946947948949950951952953954955956957958959960961962963964965966967968969970971972973974975976977978979980981982983984985986987988989990991992993994995996997998999100010011002100310041005100610071008100910101011101210131014101510161017101810191020102110221023102410251026102710281029103010311032103310341035103610371038103910401041104210431044104510461047104810491050105110521053105410551056105710581059106010611062106310641065106610671068106910701071107210731074107510761077107810791080108110821083108410851086108710881089109010911092109310941095109610971098109911001101110211031104110511061107110811091110111111121113111411151116111711181119112011211122112311241125
  1. #include <traceevent/event-parse.h>
  2. #include "builtin.h"
  3. #include "util/color.h"
  4. #include "util/debug.h"
  5. #include "util/evlist.h"
  6. #include "util/machine.h"
  7. #include "util/session.h"
  8. #include "util/thread.h"
  9. #include "util/parse-options.h"
  10. #include "util/strlist.h"
  11. #include "util/intlist.h"
  12. #include "util/thread_map.h"
  13. #include <libaudit.h>
  14. #include <stdlib.h>
  15. #include <sys/mman.h>
  16. static size_t syscall_arg__scnprintf_hex(char *bf, size_t size,
  17. unsigned long arg, u8 *arg_mask __maybe_unused)
  18. {
  19. return scnprintf(bf, size, "%#lx", arg);
  20. }
  21. #define SCA_HEX syscall_arg__scnprintf_hex
  22. static size_t syscall_arg__scnprintf_mmap_prot(char *bf, size_t size,
  23. unsigned long arg, u8 *arg_mask __maybe_unused)
  24. {
  25. int printed = 0, prot = arg;
  26. if (prot == PROT_NONE)
  27. return scnprintf(bf, size, "NONE");
  28. #define P_MMAP_PROT(n) \
  29. if (prot & PROT_##n) { \
  30. printed += scnprintf(bf + printed, size - printed, "%s%s", printed ? "|" : "", #n); \
  31. prot &= ~PROT_##n; \
  32. }
  33. P_MMAP_PROT(EXEC);
  34. P_MMAP_PROT(READ);
  35. P_MMAP_PROT(WRITE);
  36. #ifdef PROT_SEM
  37. P_MMAP_PROT(SEM);
  38. #endif
  39. P_MMAP_PROT(GROWSDOWN);
  40. P_MMAP_PROT(GROWSUP);
  41. #undef P_MMAP_PROT
  42. if (prot)
  43. printed += scnprintf(bf + printed, size - printed, "%s%#x", printed ? "|" : "", prot);
  44. return printed;
  45. }
  46. #define SCA_MMAP_PROT syscall_arg__scnprintf_mmap_prot
  47. static size_t syscall_arg__scnprintf_mmap_flags(char *bf, size_t size,
  48. unsigned long arg, u8 *arg_mask __maybe_unused)
  49. {
  50. int printed = 0, flags = arg;
  51. #define P_MMAP_FLAG(n) \
  52. if (flags & MAP_##n) { \
  53. printed += scnprintf(bf + printed, size - printed, "%s%s", printed ? "|" : "", #n); \
  54. flags &= ~MAP_##n; \
  55. }
  56. P_MMAP_FLAG(SHARED);
  57. P_MMAP_FLAG(PRIVATE);
  58. P_MMAP_FLAG(32BIT);
  59. P_MMAP_FLAG(ANONYMOUS);
  60. P_MMAP_FLAG(DENYWRITE);
  61. P_MMAP_FLAG(EXECUTABLE);
  62. P_MMAP_FLAG(FILE);
  63. P_MMAP_FLAG(FIXED);
  64. P_MMAP_FLAG(GROWSDOWN);
  65. #ifdef MAP_HUGETLB
  66. P_MMAP_FLAG(HUGETLB);
  67. #endif
  68. P_MMAP_FLAG(LOCKED);
  69. P_MMAP_FLAG(NONBLOCK);
  70. P_MMAP_FLAG(NORESERVE);
  71. P_MMAP_FLAG(POPULATE);
  72. P_MMAP_FLAG(STACK);
  73. #ifdef MAP_UNINITIALIZED
  74. P_MMAP_FLAG(UNINITIALIZED);
  75. #endif
  76. #undef P_MMAP_FLAG
  77. if (flags)
  78. printed += scnprintf(bf + printed, size - printed, "%s%#x", printed ? "|" : "", flags);
  79. return printed;
  80. }
  81. #define SCA_MMAP_FLAGS syscall_arg__scnprintf_mmap_flags
  82. static size_t syscall_arg__scnprintf_madvise_behavior(char *bf, size_t size,
  83. unsigned long arg, u8 *arg_mask __maybe_unused)
  84. {
  85. int behavior = arg;
  86. switch (behavior) {
  87. #define P_MADV_BHV(n) case MADV_##n: return scnprintf(bf, size, #n)
  88. P_MADV_BHV(NORMAL);
  89. P_MADV_BHV(RANDOM);
  90. P_MADV_BHV(SEQUENTIAL);
  91. P_MADV_BHV(WILLNEED);
  92. P_MADV_BHV(DONTNEED);
  93. P_MADV_BHV(REMOVE);
  94. P_MADV_BHV(DONTFORK);
  95. P_MADV_BHV(DOFORK);
  96. P_MADV_BHV(HWPOISON);
  97. #ifdef MADV_SOFT_OFFLINE
  98. P_MADV_BHV(SOFT_OFFLINE);
  99. #endif
  100. P_MADV_BHV(MERGEABLE);
  101. P_MADV_BHV(UNMERGEABLE);
  102. #ifdef MADV_HUGEPAGE
  103. P_MADV_BHV(HUGEPAGE);
  104. #endif
  105. #ifdef MADV_NOHUGEPAGE
  106. P_MADV_BHV(NOHUGEPAGE);
  107. #endif
  108. #ifdef MADV_DONTDUMP
  109. P_MADV_BHV(DONTDUMP);
  110. #endif
  111. #ifdef MADV_DODUMP
  112. P_MADV_BHV(DODUMP);
  113. #endif
  114. #undef P_MADV_PHV
  115. default: break;
  116. }
  117. return scnprintf(bf, size, "%#x", behavior);
  118. }
  119. #define SCA_MADV_BHV syscall_arg__scnprintf_madvise_behavior
  120. static struct syscall_fmt {
  121. const char *name;
  122. const char *alias;
  123. size_t (*arg_scnprintf[6])(char *bf, size_t size, unsigned long arg, u8 *arg_mask);
  124. bool errmsg;
  125. bool timeout;
  126. bool hexret;
  127. } syscall_fmts[] = {
  128. { .name = "access", .errmsg = true, },
  129. { .name = "arch_prctl", .errmsg = true, .alias = "prctl", },
  130. { .name = "brk", .hexret = true,
  131. .arg_scnprintf = { [0] = SCA_HEX, /* brk */ }, },
  132. { .name = "mmap", .hexret = true, },
  133. { .name = "connect", .errmsg = true, },
  134. { .name = "fstat", .errmsg = true, .alias = "newfstat", },
  135. { .name = "fstatat", .errmsg = true, .alias = "newfstatat", },
  136. { .name = "futex", .errmsg = true, },
  137. { .name = "ioctl", .errmsg = true,
  138. .arg_scnprintf = { [2] = SCA_HEX, /* arg */ }, },
  139. { .name = "lstat", .errmsg = true, .alias = "newlstat", },
  140. { .name = "madvise", .errmsg = true,
  141. .arg_scnprintf = { [0] = SCA_HEX, /* start */
  142. [2] = SCA_MADV_BHV, /* behavior */ }, },
  143. { .name = "mmap", .hexret = true,
  144. .arg_scnprintf = { [0] = SCA_HEX, /* addr */
  145. [2] = SCA_MMAP_PROT, /* prot */
  146. [3] = SCA_MMAP_FLAGS, /* flags */ }, },
  147. { .name = "mprotect", .errmsg = true,
  148. .arg_scnprintf = { [0] = SCA_HEX, /* start */
  149. [2] = SCA_MMAP_PROT, /* prot */ }, },
  150. { .name = "mremap", .hexret = true,
  151. .arg_scnprintf = { [0] = SCA_HEX, /* addr */
  152. [4] = SCA_HEX, /* new_addr */ }, },
  153. { .name = "munmap", .errmsg = true,
  154. .arg_scnprintf = { [0] = SCA_HEX, /* addr */ }, },
  155. { .name = "open", .errmsg = true, },
  156. { .name = "poll", .errmsg = true, .timeout = true, },
  157. { .name = "ppoll", .errmsg = true, .timeout = true, },
  158. { .name = "pread", .errmsg = true, .alias = "pread64", },
  159. { .name = "pwrite", .errmsg = true, .alias = "pwrite64", },
  160. { .name = "read", .errmsg = true, },
  161. { .name = "recvfrom", .errmsg = true, },
  162. { .name = "select", .errmsg = true, .timeout = true, },
  163. { .name = "socket", .errmsg = true, },
  164. { .name = "stat", .errmsg = true, .alias = "newstat", },
  165. { .name = "uname", .errmsg = true, .alias = "newuname", },
  166. };
  167. static int syscall_fmt__cmp(const void *name, const void *fmtp)
  168. {
  169. const struct syscall_fmt *fmt = fmtp;
  170. return strcmp(name, fmt->name);
  171. }
  172. static struct syscall_fmt *syscall_fmt__find(const char *name)
  173. {
  174. const int nmemb = ARRAY_SIZE(syscall_fmts);
  175. return bsearch(name, syscall_fmts, nmemb, sizeof(struct syscall_fmt), syscall_fmt__cmp);
  176. }
  177. struct syscall {
  178. struct event_format *tp_format;
  179. const char *name;
  180. bool filtered;
  181. struct syscall_fmt *fmt;
  182. size_t (**arg_scnprintf)(char *bf, size_t size,
  183. unsigned long arg, u8 *args_mask);
  184. };
  185. static size_t fprintf_duration(unsigned long t, FILE *fp)
  186. {
  187. double duration = (double)t / NSEC_PER_MSEC;
  188. size_t printed = fprintf(fp, "(");
  189. if (duration >= 1.0)
  190. printed += color_fprintf(fp, PERF_COLOR_RED, "%6.3f ms", duration);
  191. else if (duration >= 0.01)
  192. printed += color_fprintf(fp, PERF_COLOR_YELLOW, "%6.3f ms", duration);
  193. else
  194. printed += color_fprintf(fp, PERF_COLOR_NORMAL, "%6.3f ms", duration);
  195. return printed + fprintf(fp, "): ");
  196. }
  197. struct thread_trace {
  198. u64 entry_time;
  199. u64 exit_time;
  200. bool entry_pending;
  201. unsigned long nr_events;
  202. char *entry_str;
  203. double runtime_ms;
  204. };
  205. static struct thread_trace *thread_trace__new(void)
  206. {
  207. return zalloc(sizeof(struct thread_trace));
  208. }
  209. static struct thread_trace *thread__trace(struct thread *thread, FILE *fp)
  210. {
  211. struct thread_trace *ttrace;
  212. if (thread == NULL)
  213. goto fail;
  214. if (thread->priv == NULL)
  215. thread->priv = thread_trace__new();
  216. if (thread->priv == NULL)
  217. goto fail;
  218. ttrace = thread->priv;
  219. ++ttrace->nr_events;
  220. return ttrace;
  221. fail:
  222. color_fprintf(fp, PERF_COLOR_RED,
  223. "WARNING: not enough memory, dropping samples!\n");
  224. return NULL;
  225. }
  226. struct trace {
  227. struct perf_tool tool;
  228. int audit_machine;
  229. struct {
  230. int max;
  231. struct syscall *table;
  232. } syscalls;
  233. struct perf_record_opts opts;
  234. struct machine host;
  235. u64 base_time;
  236. FILE *output;
  237. unsigned long nr_events;
  238. struct strlist *ev_qualifier;
  239. bool not_ev_qualifier;
  240. struct intlist *tid_list;
  241. struct intlist *pid_list;
  242. bool sched;
  243. bool multiple_threads;
  244. double duration_filter;
  245. double runtime_ms;
  246. };
  247. static bool trace__filter_duration(struct trace *trace, double t)
  248. {
  249. return t < (trace->duration_filter * NSEC_PER_MSEC);
  250. }
  251. static size_t trace__fprintf_tstamp(struct trace *trace, u64 tstamp, FILE *fp)
  252. {
  253. double ts = (double)(tstamp - trace->base_time) / NSEC_PER_MSEC;
  254. return fprintf(fp, "%10.3f ", ts);
  255. }
  256. static bool done = false;
  257. static void sig_handler(int sig __maybe_unused)
  258. {
  259. done = true;
  260. }
  261. static size_t trace__fprintf_entry_head(struct trace *trace, struct thread *thread,
  262. u64 duration, u64 tstamp, FILE *fp)
  263. {
  264. size_t printed = trace__fprintf_tstamp(trace, tstamp, fp);
  265. printed += fprintf_duration(duration, fp);
  266. if (trace->multiple_threads)
  267. printed += fprintf(fp, "%d ", thread->tid);
  268. return printed;
  269. }
  270. static int trace__process_event(struct trace *trace, struct machine *machine,
  271. union perf_event *event)
  272. {
  273. int ret = 0;
  274. switch (event->header.type) {
  275. case PERF_RECORD_LOST:
  276. color_fprintf(trace->output, PERF_COLOR_RED,
  277. "LOST %" PRIu64 " events!\n", event->lost.lost);
  278. ret = machine__process_lost_event(machine, event);
  279. default:
  280. ret = machine__process_event(machine, event);
  281. break;
  282. }
  283. return ret;
  284. }
  285. static int trace__tool_process(struct perf_tool *tool,
  286. union perf_event *event,
  287. struct perf_sample *sample __maybe_unused,
  288. struct machine *machine)
  289. {
  290. struct trace *trace = container_of(tool, struct trace, tool);
  291. return trace__process_event(trace, machine, event);
  292. }
  293. static int trace__symbols_init(struct trace *trace, struct perf_evlist *evlist)
  294. {
  295. int err = symbol__init();
  296. if (err)
  297. return err;
  298. machine__init(&trace->host, "", HOST_KERNEL_ID);
  299. machine__create_kernel_maps(&trace->host);
  300. if (perf_target__has_task(&trace->opts.target)) {
  301. err = perf_event__synthesize_thread_map(&trace->tool, evlist->threads,
  302. trace__tool_process,
  303. &trace->host);
  304. } else {
  305. err = perf_event__synthesize_threads(&trace->tool, trace__tool_process,
  306. &trace->host);
  307. }
  308. if (err)
  309. symbol__exit();
  310. return err;
  311. }
  312. static int syscall__set_arg_fmts(struct syscall *sc)
  313. {
  314. struct format_field *field;
  315. int idx = 0;
  316. sc->arg_scnprintf = calloc(sc->tp_format->format.nr_fields - 1, sizeof(void *));
  317. if (sc->arg_scnprintf == NULL)
  318. return -1;
  319. for (field = sc->tp_format->format.fields->next; field; field = field->next) {
  320. if (sc->fmt && sc->fmt->arg_scnprintf[idx])
  321. sc->arg_scnprintf[idx] = sc->fmt->arg_scnprintf[idx];
  322. else if (field->flags & FIELD_IS_POINTER)
  323. sc->arg_scnprintf[idx] = syscall_arg__scnprintf_hex;
  324. ++idx;
  325. }
  326. return 0;
  327. }
  328. static int trace__read_syscall_info(struct trace *trace, int id)
  329. {
  330. char tp_name[128];
  331. struct syscall *sc;
  332. const char *name = audit_syscall_to_name(id, trace->audit_machine);
  333. if (name == NULL)
  334. return -1;
  335. if (id > trace->syscalls.max) {
  336. struct syscall *nsyscalls = realloc(trace->syscalls.table, (id + 1) * sizeof(*sc));
  337. if (nsyscalls == NULL)
  338. return -1;
  339. if (trace->syscalls.max != -1) {
  340. memset(nsyscalls + trace->syscalls.max + 1, 0,
  341. (id - trace->syscalls.max) * sizeof(*sc));
  342. } else {
  343. memset(nsyscalls, 0, (id + 1) * sizeof(*sc));
  344. }
  345. trace->syscalls.table = nsyscalls;
  346. trace->syscalls.max = id;
  347. }
  348. sc = trace->syscalls.table + id;
  349. sc->name = name;
  350. if (trace->ev_qualifier) {
  351. bool in = strlist__find(trace->ev_qualifier, name) != NULL;
  352. if (!(in ^ trace->not_ev_qualifier)) {
  353. sc->filtered = true;
  354. /*
  355. * No need to do read tracepoint information since this will be
  356. * filtered out.
  357. */
  358. return 0;
  359. }
  360. }
  361. sc->fmt = syscall_fmt__find(sc->name);
  362. snprintf(tp_name, sizeof(tp_name), "sys_enter_%s", sc->name);
  363. sc->tp_format = event_format__new("syscalls", tp_name);
  364. if (sc->tp_format == NULL && sc->fmt && sc->fmt->alias) {
  365. snprintf(tp_name, sizeof(tp_name), "sys_enter_%s", sc->fmt->alias);
  366. sc->tp_format = event_format__new("syscalls", tp_name);
  367. }
  368. if (sc->tp_format == NULL)
  369. return -1;
  370. return syscall__set_arg_fmts(sc);
  371. }
  372. static size_t syscall__scnprintf_args(struct syscall *sc, char *bf, size_t size,
  373. unsigned long *args)
  374. {
  375. int i = 0;
  376. size_t printed = 0;
  377. if (sc->tp_format != NULL) {
  378. struct format_field *field;
  379. u8 mask = 0, bit = 1;
  380. for (field = sc->tp_format->format.fields->next; field;
  381. field = field->next, ++i, bit <<= 1) {
  382. if (mask & bit)
  383. continue;
  384. printed += scnprintf(bf + printed, size - printed,
  385. "%s%s: ", printed ? ", " : "", field->name);
  386. if (sc->arg_scnprintf && sc->arg_scnprintf[i]) {
  387. printed += sc->arg_scnprintf[i](bf + printed, size - printed,
  388. args[i], &mask);
  389. } else {
  390. printed += scnprintf(bf + printed, size - printed,
  391. "%ld", args[i]);
  392. }
  393. }
  394. } else {
  395. while (i < 6) {
  396. printed += scnprintf(bf + printed, size - printed,
  397. "%sarg%d: %ld",
  398. printed ? ", " : "", i, args[i]);
  399. ++i;
  400. }
  401. }
  402. return printed;
  403. }
  404. typedef int (*tracepoint_handler)(struct trace *trace, struct perf_evsel *evsel,
  405. struct perf_sample *sample);
  406. static struct syscall *trace__syscall_info(struct trace *trace,
  407. struct perf_evsel *evsel,
  408. struct perf_sample *sample)
  409. {
  410. int id = perf_evsel__intval(evsel, sample, "id");
  411. if (id < 0) {
  412. /*
  413. * XXX: Noticed on x86_64, reproduced as far back as 3.0.36, haven't tried
  414. * before that, leaving at a higher verbosity level till that is
  415. * explained. Reproduced with plain ftrace with:
  416. *
  417. * echo 1 > /t/events/raw_syscalls/sys_exit/enable
  418. * grep "NR -1 " /t/trace_pipe
  419. *
  420. * After generating some load on the machine.
  421. */
  422. if (verbose > 1) {
  423. static u64 n;
  424. fprintf(trace->output, "Invalid syscall %d id, skipping (%s, %" PRIu64 ") ...\n",
  425. id, perf_evsel__name(evsel), ++n);
  426. }
  427. return NULL;
  428. }
  429. if ((id > trace->syscalls.max || trace->syscalls.table[id].name == NULL) &&
  430. trace__read_syscall_info(trace, id))
  431. goto out_cant_read;
  432. if ((id > trace->syscalls.max || trace->syscalls.table[id].name == NULL))
  433. goto out_cant_read;
  434. return &trace->syscalls.table[id];
  435. out_cant_read:
  436. if (verbose) {
  437. fprintf(trace->output, "Problems reading syscall %d", id);
  438. if (id <= trace->syscalls.max && trace->syscalls.table[id].name != NULL)
  439. fprintf(trace->output, "(%s)", trace->syscalls.table[id].name);
  440. fputs(" information\n", trace->output);
  441. }
  442. return NULL;
  443. }
  444. static int trace__sys_enter(struct trace *trace, struct perf_evsel *evsel,
  445. struct perf_sample *sample)
  446. {
  447. char *msg;
  448. void *args;
  449. size_t printed = 0;
  450. struct thread *thread;
  451. struct syscall *sc = trace__syscall_info(trace, evsel, sample);
  452. struct thread_trace *ttrace;
  453. if (sc == NULL)
  454. return -1;
  455. if (sc->filtered)
  456. return 0;
  457. thread = machine__findnew_thread(&trace->host, sample->pid,
  458. sample->tid);
  459. ttrace = thread__trace(thread, trace->output);
  460. if (ttrace == NULL)
  461. return -1;
  462. args = perf_evsel__rawptr(evsel, sample, "args");
  463. if (args == NULL) {
  464. fprintf(trace->output, "Problems reading syscall arguments\n");
  465. return -1;
  466. }
  467. ttrace = thread->priv;
  468. if (ttrace->entry_str == NULL) {
  469. ttrace->entry_str = malloc(1024);
  470. if (!ttrace->entry_str)
  471. return -1;
  472. }
  473. ttrace->entry_time = sample->time;
  474. msg = ttrace->entry_str;
  475. printed += scnprintf(msg + printed, 1024 - printed, "%s(", sc->name);
  476. printed += syscall__scnprintf_args(sc, msg + printed, 1024 - printed, args);
  477. if (!strcmp(sc->name, "exit_group") || !strcmp(sc->name, "exit")) {
  478. if (!trace->duration_filter) {
  479. trace__fprintf_entry_head(trace, thread, 1, sample->time, trace->output);
  480. fprintf(trace->output, "%-70s\n", ttrace->entry_str);
  481. }
  482. } else
  483. ttrace->entry_pending = true;
  484. return 0;
  485. }
  486. static int trace__sys_exit(struct trace *trace, struct perf_evsel *evsel,
  487. struct perf_sample *sample)
  488. {
  489. int ret;
  490. u64 duration = 0;
  491. struct thread *thread;
  492. struct syscall *sc = trace__syscall_info(trace, evsel, sample);
  493. struct thread_trace *ttrace;
  494. if (sc == NULL)
  495. return -1;
  496. if (sc->filtered)
  497. return 0;
  498. thread = machine__findnew_thread(&trace->host, sample->pid,
  499. sample->tid);
  500. ttrace = thread__trace(thread, trace->output);
  501. if (ttrace == NULL)
  502. return -1;
  503. ret = perf_evsel__intval(evsel, sample, "ret");
  504. ttrace = thread->priv;
  505. ttrace->exit_time = sample->time;
  506. if (ttrace->entry_time) {
  507. duration = sample->time - ttrace->entry_time;
  508. if (trace__filter_duration(trace, duration))
  509. goto out;
  510. } else if (trace->duration_filter)
  511. goto out;
  512. trace__fprintf_entry_head(trace, thread, duration, sample->time, trace->output);
  513. if (ttrace->entry_pending) {
  514. fprintf(trace->output, "%-70s", ttrace->entry_str);
  515. } else {
  516. fprintf(trace->output, " ... [");
  517. color_fprintf(trace->output, PERF_COLOR_YELLOW, "continued");
  518. fprintf(trace->output, "]: %s()", sc->name);
  519. }
  520. if (sc->fmt == NULL) {
  521. signed_print:
  522. fprintf(trace->output, ") = %d", ret);
  523. } else if (ret < 0 && sc->fmt->errmsg) {
  524. char bf[256];
  525. const char *emsg = strerror_r(-ret, bf, sizeof(bf)),
  526. *e = audit_errno_to_name(-ret);
  527. fprintf(trace->output, ") = -1 %s %s", e, emsg);
  528. } else if (ret == 0 && sc->fmt->timeout)
  529. fprintf(trace->output, ") = 0 Timeout");
  530. else if (sc->fmt->hexret)
  531. fprintf(trace->output, ") = %#x", ret);
  532. else
  533. goto signed_print;
  534. fputc('\n', trace->output);
  535. out:
  536. ttrace->entry_pending = false;
  537. return 0;
  538. }
  539. static int trace__sched_stat_runtime(struct trace *trace, struct perf_evsel *evsel,
  540. struct perf_sample *sample)
  541. {
  542. u64 runtime = perf_evsel__intval(evsel, sample, "runtime");
  543. double runtime_ms = (double)runtime / NSEC_PER_MSEC;
  544. struct thread *thread = machine__findnew_thread(&trace->host,
  545. sample->pid,
  546. sample->tid);
  547. struct thread_trace *ttrace = thread__trace(thread, trace->output);
  548. if (ttrace == NULL)
  549. goto out_dump;
  550. ttrace->runtime_ms += runtime_ms;
  551. trace->runtime_ms += runtime_ms;
  552. return 0;
  553. out_dump:
  554. fprintf(trace->output, "%s: comm=%s,pid=%u,runtime=%" PRIu64 ",vruntime=%" PRIu64 ")\n",
  555. evsel->name,
  556. perf_evsel__strval(evsel, sample, "comm"),
  557. (pid_t)perf_evsel__intval(evsel, sample, "pid"),
  558. runtime,
  559. perf_evsel__intval(evsel, sample, "vruntime"));
  560. return 0;
  561. }
  562. static bool skip_sample(struct trace *trace, struct perf_sample *sample)
  563. {
  564. if ((trace->pid_list && intlist__find(trace->pid_list, sample->pid)) ||
  565. (trace->tid_list && intlist__find(trace->tid_list, sample->tid)))
  566. return false;
  567. if (trace->pid_list || trace->tid_list)
  568. return true;
  569. return false;
  570. }
  571. static int trace__process_sample(struct perf_tool *tool,
  572. union perf_event *event __maybe_unused,
  573. struct perf_sample *sample,
  574. struct perf_evsel *evsel,
  575. struct machine *machine __maybe_unused)
  576. {
  577. struct trace *trace = container_of(tool, struct trace, tool);
  578. int err = 0;
  579. tracepoint_handler handler = evsel->handler.func;
  580. if (skip_sample(trace, sample))
  581. return 0;
  582. if (trace->base_time == 0)
  583. trace->base_time = sample->time;
  584. if (handler)
  585. handler(trace, evsel, sample);
  586. return err;
  587. }
  588. static bool
  589. perf_session__has_tp(struct perf_session *session, const char *name)
  590. {
  591. struct perf_evsel *evsel;
  592. evsel = perf_evlist__find_tracepoint_by_name(session->evlist, name);
  593. return evsel != NULL;
  594. }
  595. static int parse_target_str(struct trace *trace)
  596. {
  597. if (trace->opts.target.pid) {
  598. trace->pid_list = intlist__new(trace->opts.target.pid);
  599. if (trace->pid_list == NULL) {
  600. pr_err("Error parsing process id string\n");
  601. return -EINVAL;
  602. }
  603. }
  604. if (trace->opts.target.tid) {
  605. trace->tid_list = intlist__new(trace->opts.target.tid);
  606. if (trace->tid_list == NULL) {
  607. pr_err("Error parsing thread id string\n");
  608. return -EINVAL;
  609. }
  610. }
  611. return 0;
  612. }
  613. static int trace__run(struct trace *trace, int argc, const char **argv)
  614. {
  615. struct perf_evlist *evlist = perf_evlist__new();
  616. struct perf_evsel *evsel;
  617. int err = -1, i;
  618. unsigned long before;
  619. const bool forks = argc > 0;
  620. if (evlist == NULL) {
  621. fprintf(trace->output, "Not enough memory to run!\n");
  622. goto out;
  623. }
  624. if (perf_evlist__add_newtp(evlist, "raw_syscalls", "sys_enter", trace__sys_enter) ||
  625. perf_evlist__add_newtp(evlist, "raw_syscalls", "sys_exit", trace__sys_exit)) {
  626. fprintf(trace->output, "Couldn't read the raw_syscalls tracepoints information!\n");
  627. goto out_delete_evlist;
  628. }
  629. if (trace->sched &&
  630. perf_evlist__add_newtp(evlist, "sched", "sched_stat_runtime",
  631. trace__sched_stat_runtime)) {
  632. fprintf(trace->output, "Couldn't read the sched_stat_runtime tracepoint information!\n");
  633. goto out_delete_evlist;
  634. }
  635. err = perf_evlist__create_maps(evlist, &trace->opts.target);
  636. if (err < 0) {
  637. fprintf(trace->output, "Problems parsing the target to trace, check your options!\n");
  638. goto out_delete_evlist;
  639. }
  640. err = trace__symbols_init(trace, evlist);
  641. if (err < 0) {
  642. fprintf(trace->output, "Problems initializing symbol libraries!\n");
  643. goto out_delete_maps;
  644. }
  645. perf_evlist__config(evlist, &trace->opts);
  646. signal(SIGCHLD, sig_handler);
  647. signal(SIGINT, sig_handler);
  648. if (forks) {
  649. err = perf_evlist__prepare_workload(evlist, &trace->opts.target,
  650. argv, false, false);
  651. if (err < 0) {
  652. fprintf(trace->output, "Couldn't run the workload!\n");
  653. goto out_delete_maps;
  654. }
  655. }
  656. err = perf_evlist__open(evlist);
  657. if (err < 0) {
  658. fprintf(trace->output, "Couldn't create the events: %s\n", strerror(errno));
  659. goto out_delete_maps;
  660. }
  661. err = perf_evlist__mmap(evlist, UINT_MAX, false);
  662. if (err < 0) {
  663. fprintf(trace->output, "Couldn't mmap the events: %s\n", strerror(errno));
  664. goto out_close_evlist;
  665. }
  666. perf_evlist__enable(evlist);
  667. if (forks)
  668. perf_evlist__start_workload(evlist);
  669. trace->multiple_threads = evlist->threads->map[0] == -1 || evlist->threads->nr > 1;
  670. again:
  671. before = trace->nr_events;
  672. for (i = 0; i < evlist->nr_mmaps; i++) {
  673. union perf_event *event;
  674. while ((event = perf_evlist__mmap_read(evlist, i)) != NULL) {
  675. const u32 type = event->header.type;
  676. tracepoint_handler handler;
  677. struct perf_sample sample;
  678. ++trace->nr_events;
  679. err = perf_evlist__parse_sample(evlist, event, &sample);
  680. if (err) {
  681. fprintf(trace->output, "Can't parse sample, err = %d, skipping...\n", err);
  682. continue;
  683. }
  684. if (trace->base_time == 0)
  685. trace->base_time = sample.time;
  686. if (type != PERF_RECORD_SAMPLE) {
  687. trace__process_event(trace, &trace->host, event);
  688. continue;
  689. }
  690. evsel = perf_evlist__id2evsel(evlist, sample.id);
  691. if (evsel == NULL) {
  692. fprintf(trace->output, "Unknown tp ID %" PRIu64 ", skipping...\n", sample.id);
  693. continue;
  694. }
  695. if (sample.raw_data == NULL) {
  696. fprintf(trace->output, "%s sample with no payload for tid: %d, cpu %d, raw_size=%d, skipping...\n",
  697. perf_evsel__name(evsel), sample.tid,
  698. sample.cpu, sample.raw_size);
  699. continue;
  700. }
  701. handler = evsel->handler.func;
  702. handler(trace, evsel, &sample);
  703. }
  704. }
  705. if (trace->nr_events == before) {
  706. if (done)
  707. goto out_unmap_evlist;
  708. poll(evlist->pollfd, evlist->nr_fds, -1);
  709. }
  710. if (done)
  711. perf_evlist__disable(evlist);
  712. goto again;
  713. out_unmap_evlist:
  714. perf_evlist__munmap(evlist);
  715. out_close_evlist:
  716. perf_evlist__close(evlist);
  717. out_delete_maps:
  718. perf_evlist__delete_maps(evlist);
  719. out_delete_evlist:
  720. perf_evlist__delete(evlist);
  721. out:
  722. return err;
  723. }
  724. static int trace__replay(struct trace *trace)
  725. {
  726. const struct perf_evsel_str_handler handlers[] = {
  727. { "raw_syscalls:sys_enter", trace__sys_enter, },
  728. { "raw_syscalls:sys_exit", trace__sys_exit, },
  729. };
  730. struct perf_session *session;
  731. int err = -1;
  732. trace->tool.sample = trace__process_sample;
  733. trace->tool.mmap = perf_event__process_mmap;
  734. trace->tool.comm = perf_event__process_comm;
  735. trace->tool.exit = perf_event__process_exit;
  736. trace->tool.fork = perf_event__process_fork;
  737. trace->tool.attr = perf_event__process_attr;
  738. trace->tool.tracing_data = perf_event__process_tracing_data;
  739. trace->tool.build_id = perf_event__process_build_id;
  740. trace->tool.ordered_samples = true;
  741. trace->tool.ordering_requires_timestamps = true;
  742. /* add tid to output */
  743. trace->multiple_threads = true;
  744. if (symbol__init() < 0)
  745. return -1;
  746. session = perf_session__new(input_name, O_RDONLY, 0, false,
  747. &trace->tool);
  748. if (session == NULL)
  749. return -ENOMEM;
  750. err = perf_session__set_tracepoints_handlers(session, handlers);
  751. if (err)
  752. goto out;
  753. if (!perf_session__has_tp(session, "raw_syscalls:sys_enter")) {
  754. pr_err("Data file does not have raw_syscalls:sys_enter events\n");
  755. goto out;
  756. }
  757. if (!perf_session__has_tp(session, "raw_syscalls:sys_exit")) {
  758. pr_err("Data file does not have raw_syscalls:sys_exit events\n");
  759. goto out;
  760. }
  761. err = parse_target_str(trace);
  762. if (err != 0)
  763. goto out;
  764. setup_pager();
  765. err = perf_session__process_events(session, &trace->tool);
  766. if (err)
  767. pr_err("Failed to process events, error %d", err);
  768. out:
  769. perf_session__delete(session);
  770. return err;
  771. }
  772. static size_t trace__fprintf_threads_header(FILE *fp)
  773. {
  774. size_t printed;
  775. printed = fprintf(fp, "\n _____________________________________________________________________\n");
  776. printed += fprintf(fp," __) Summary of events (__\n\n");
  777. printed += fprintf(fp," [ task - pid ] [ events ] [ ratio ] [ runtime ]\n");
  778. printed += fprintf(fp," _____________________________________________________________________\n\n");
  779. return printed;
  780. }
  781. static size_t trace__fprintf_thread_summary(struct trace *trace, FILE *fp)
  782. {
  783. size_t printed = trace__fprintf_threads_header(fp);
  784. struct rb_node *nd;
  785. for (nd = rb_first(&trace->host.threads); nd; nd = rb_next(nd)) {
  786. struct thread *thread = rb_entry(nd, struct thread, rb_node);
  787. struct thread_trace *ttrace = thread->priv;
  788. const char *color;
  789. double ratio;
  790. if (ttrace == NULL)
  791. continue;
  792. ratio = (double)ttrace->nr_events / trace->nr_events * 100.0;
  793. color = PERF_COLOR_NORMAL;
  794. if (ratio > 50.0)
  795. color = PERF_COLOR_RED;
  796. else if (ratio > 25.0)
  797. color = PERF_COLOR_GREEN;
  798. else if (ratio > 5.0)
  799. color = PERF_COLOR_YELLOW;
  800. printed += color_fprintf(fp, color, "%20s", thread->comm);
  801. printed += fprintf(fp, " - %-5d :%11lu [", thread->tid, ttrace->nr_events);
  802. printed += color_fprintf(fp, color, "%5.1f%%", ratio);
  803. printed += fprintf(fp, " ] %10.3f ms\n", ttrace->runtime_ms);
  804. }
  805. return printed;
  806. }
  807. static int trace__set_duration(const struct option *opt, const char *str,
  808. int unset __maybe_unused)
  809. {
  810. struct trace *trace = opt->value;
  811. trace->duration_filter = atof(str);
  812. return 0;
  813. }
  814. static int trace__open_output(struct trace *trace, const char *filename)
  815. {
  816. struct stat st;
  817. if (!stat(filename, &st) && st.st_size) {
  818. char oldname[PATH_MAX];
  819. scnprintf(oldname, sizeof(oldname), "%s.old", filename);
  820. unlink(oldname);
  821. rename(filename, oldname);
  822. }
  823. trace->output = fopen(filename, "w");
  824. return trace->output == NULL ? -errno : 0;
  825. }
  826. int cmd_trace(int argc, const char **argv, const char *prefix __maybe_unused)
  827. {
  828. const char * const trace_usage[] = {
  829. "perf trace [<options>] [<command>]",
  830. "perf trace [<options>] -- <command> [<options>]",
  831. NULL
  832. };
  833. struct trace trace = {
  834. .audit_machine = audit_detect_machine(),
  835. .syscalls = {
  836. . max = -1,
  837. },
  838. .opts = {
  839. .target = {
  840. .uid = UINT_MAX,
  841. .uses_mmap = true,
  842. },
  843. .user_freq = UINT_MAX,
  844. .user_interval = ULLONG_MAX,
  845. .no_delay = true,
  846. .mmap_pages = 1024,
  847. },
  848. .output = stdout,
  849. };
  850. const char *output_name = NULL;
  851. const char *ev_qualifier_str = NULL;
  852. const struct option trace_options[] = {
  853. OPT_STRING('e', "expr", &ev_qualifier_str, "expr",
  854. "list of events to trace"),
  855. OPT_STRING('o', "output", &output_name, "file", "output file name"),
  856. OPT_STRING('i', "input", &input_name, "file", "Analyze events in file"),
  857. OPT_STRING('p', "pid", &trace.opts.target.pid, "pid",
  858. "trace events on existing process id"),
  859. OPT_STRING('t', "tid", &trace.opts.target.tid, "tid",
  860. "trace events on existing thread id"),
  861. OPT_BOOLEAN('a', "all-cpus", &trace.opts.target.system_wide,
  862. "system-wide collection from all CPUs"),
  863. OPT_STRING('C', "cpu", &trace.opts.target.cpu_list, "cpu",
  864. "list of cpus to monitor"),
  865. OPT_BOOLEAN(0, "no-inherit", &trace.opts.no_inherit,
  866. "child tasks do not inherit counters"),
  867. OPT_UINTEGER('m', "mmap-pages", &trace.opts.mmap_pages,
  868. "number of mmap data pages"),
  869. OPT_STRING('u', "uid", &trace.opts.target.uid_str, "user",
  870. "user to profile"),
  871. OPT_CALLBACK(0, "duration", &trace, "float",
  872. "show only events with duration > N.M ms",
  873. trace__set_duration),
  874. OPT_BOOLEAN(0, "sched", &trace.sched, "show blocking scheduler events"),
  875. OPT_INCR('v', "verbose", &verbose, "be more verbose"),
  876. OPT_END()
  877. };
  878. int err;
  879. char bf[BUFSIZ];
  880. argc = parse_options(argc, argv, trace_options, trace_usage, 0);
  881. if (output_name != NULL) {
  882. err = trace__open_output(&trace, output_name);
  883. if (err < 0) {
  884. perror("failed to create output file");
  885. goto out;
  886. }
  887. }
  888. if (ev_qualifier_str != NULL) {
  889. const char *s = ev_qualifier_str;
  890. trace.not_ev_qualifier = *s == '!';
  891. if (trace.not_ev_qualifier)
  892. ++s;
  893. trace.ev_qualifier = strlist__new(true, s);
  894. if (trace.ev_qualifier == NULL) {
  895. fputs("Not enough memory to parse event qualifier",
  896. trace.output);
  897. err = -ENOMEM;
  898. goto out_close;
  899. }
  900. }
  901. err = perf_target__validate(&trace.opts.target);
  902. if (err) {
  903. perf_target__strerror(&trace.opts.target, err, bf, sizeof(bf));
  904. fprintf(trace.output, "%s", bf);
  905. goto out_close;
  906. }
  907. err = perf_target__parse_uid(&trace.opts.target);
  908. if (err) {
  909. perf_target__strerror(&trace.opts.target, err, bf, sizeof(bf));
  910. fprintf(trace.output, "%s", bf);
  911. goto out_close;
  912. }
  913. if (!argc && perf_target__none(&trace.opts.target))
  914. trace.opts.target.system_wide = true;
  915. if (input_name)
  916. err = trace__replay(&trace);
  917. else
  918. err = trace__run(&trace, argc, argv);
  919. if (trace.sched && !err)
  920. trace__fprintf_thread_summary(&trace, trace.output);
  921. out_close:
  922. if (output_name != NULL)
  923. fclose(trace.output);
  924. out:
  925. return err;
  926. }