History

Merge tag 'trace-v5.14' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace

Pull tracing updates from Steven Rostedt: - Added option for per CPU threads to the hwlat tracer - Have hwlat tracer handle hotplug CPUs - New tracer: osnoise, that detects latency caused by interrupts, softirqs and scheduling of other tasks. - Added timerlat tracer that creates a thread and measures in detail what sources of latency it has for wake ups. - Removed the "success" field of the sched_wakeup trace event. This has been hardcoded as "1" since 2015, no tooling should be looking at it now. If one exists, we can revert this commit, fix that tool and try to remove it again in the future. - tgid mapping fixed to handle more than PID_MAX_DEFAULT pids/tgids. - New boot command line option "tp_printk_stop", as tp_printk causes trace events to write to console. When user space starts, this can easily live lock the system. Having a boot option to stop just after boot up is useful to prevent that from happening. - Have ftrace_dump_on_oops boot command line option take numbers that match the numbers shown in /proc/sys/kernel/ftrace_dump_on_oops. - Bootconfig clean ups, fixes and enhancements. - New ktest script that tests bootconfig options. - Add tracepoint_probe_register_may_exist() to register a tracepoint without triggering a WARN*() if it already exists. BPF has a path from user space that can do this. All other paths are considered a bug. - Small clean ups and fixes * tag 'trace-v5.14' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace: (49 commits) tracing: Resize tgid_map to pid_max, not PID_MAX_DEFAULT tracing: Simplify & fix saved_tgids logic treewide: Add missing semicolons to __assign_str uses tracing: Change variable type as bool for clean-up trace/timerlat: Fix indentation on timerlat_main() trace/osnoise: Make 'noise' variable s64 in run_osnoise() tracepoint: Add tracepoint_probe_register_may_exist() for BPF tracing tracing: Fix spelling in osnoise tracer "interferences" -> "interference" Documentation: Fix a typo on trace/osnoise-tracer trace/osnoise: Fix return value on osnoise_init_hotplug_support trace/osnoise: Make interval u64 on osnoise_main trace/osnoise: Fix 'no previous prototype' warnings tracing: Have osnoise_main() add a quiescent state for task rcu seq_buf: Make trace_seq_putmem_hex() support data longer than 8 seq_buf: Fix overflow in seq_buf_putmem_hex() trace/osnoise: Support hotplug operations trace/hwlat: Support hotplug operations trace/hwlat: Protect kdata->kthread with get/put_online_cpus trace: Add timerlat tracer trace: Add osnoise tracer ...

Linus Torvalds committed 5 years ago

Commit 757fa802 parents a70bb58 4030a6e74 files · +4439 −369Browse files

Showing the changes to include/trace (8 of 74 files). Show all

Unified · Split

8 files
  1. include/trace/events/btrfs.h +1 −1
  2. include/trace/events/dma_fence.h +2 −2
  3. include/trace/events/osnoise.h +142 −0
  4. include/trace/events/rpcgss.h +2 −2
  5. include/trace/events/sched.h +0 −2
  6. include/trace/events/sunrpc.h +20 −20
  7. include/trace/events/writeback.h +2 −1
  8. include/trace/trace_events.h +25 −0
include/trace/events/btrfs.h+1−1
@@ -1092,7 +1092,7 @@ TRACE_EVENT(btrfs_trigger_flush, · 1091 unmodified lines
1092 __entry->flags = flags;1092 __entry->flags = flags;
1093 __entry->bytes = bytes;1093 __entry->bytes = bytes;
1094 __entry->flush = flush;1094 __entry->flush = flush;
1095 __assign_str(reason, reason)1095 __assign_str(reason, reason);
1096 ),1096 ),
1097 1097
1098 TP_printk_btrfs("%s: flush=%d(%s) flags=%llu(%s) bytes=%llu",1098 TP_printk_btrfs("%s: flush=%d(%s) flags=%llu(%s) bytes=%llu",
include/trace/events/dma_fence.h+2−2
@@ -23,8 +23,8 @@ DECLARE_EVENT_CLASS(dma_fence, · 22 unmodified lines
23 ),23 ),
24 24
25 TP_fast_assign(25 TP_fast_assign(
26 __assign_str(driver, fence->ops->get_driver_name(fence))26 __assign_str(driver, fence->ops->get_driver_name(fence));
27 __assign_str(timeline, fence->ops->get_timeline_name(fence))27 __assign_str(timeline, fence->ops->get_timeline_name(fence));
28 __entry->context = fence->context;28 __entry->context = fence->context;
29 __entry->seqno = fence->seqno;29 __entry->seqno = fence->seqno;
30 ),30 ),
include/trace/events/osnoise.h+142−0
@@ -0,0 +1,142 @@
1/* SPDX-License-Identifier: GPL-2.0 */
2#undef TRACE_SYSTEM
3#define TRACE_SYSTEM osnoise
4
5#if !defined(_OSNOISE_TRACE_H) || defined(TRACE_HEADER_MULTI_READ)
6#define _OSNOISE_TRACE_H
7
8#include <linux/tracepoint.h>
9TRACE_EVENT(thread_noise,
10
11 TP_PROTO(struct task_struct *t, u64 start, u64 duration),
12
13 TP_ARGS(t, start, duration),
14
15 TP_STRUCT__entry(
16 __array( char, comm, TASK_COMM_LEN)
17 __field( u64, start )
18 __field( u64, duration)
19 __field( pid_t, pid )
20 ),
21
22 TP_fast_assign(
23 memcpy(__entry->comm, t->comm, TASK_COMM_LEN);
24 __entry->pid = t->pid;
25 __entry->start = start;
26 __entry->duration = duration;
27 ),
28
29 TP_printk("%8s:%d start %llu.%09u duration %llu ns",
30 __entry->comm,
31 __entry->pid,
32 __print_ns_to_secs(__entry->start),
33 __print_ns_without_secs(__entry->start),
34 __entry->duration)
35);
36
37TRACE_EVENT(softirq_noise,
38
39 TP_PROTO(int vector, u64 start, u64 duration),
40
41 TP_ARGS(vector, start, duration),
42
43 TP_STRUCT__entry(
44 __field( u64, start )
45 __field( u64, duration)
46 __field( int, vector )
47 ),
48
49 TP_fast_assign(
50 __entry->vector = vector;
51 __entry->start = start;
52 __entry->duration = duration;
53 ),
54
55 TP_printk("%8s:%d start %llu.%09u duration %llu ns",
56 show_softirq_name(__entry->vector),
57 __entry->vector,
58 __print_ns_to_secs(__entry->start),
59 __print_ns_without_secs(__entry->start),
60 __entry->duration)
61);
62
63TRACE_EVENT(irq_noise,
64
65 TP_PROTO(int vector, const char *desc, u64 start, u64 duration),
66
67 TP_ARGS(vector, desc, start, duration),
68
69 TP_STRUCT__entry(
70 __field( u64, start )
71 __field( u64, duration)
72 __string( desc, desc )
73 __field( int, vector )
74
75 ),
76
77 TP_fast_assign(
78 __assign_str(desc, desc);
79 __entry->vector = vector;
80 __entry->start = start;
81 __entry->duration = duration;
82 ),
83
84 TP_printk("%s:%d start %llu.%09u duration %llu ns",
85 __get_str(desc),
86 __entry->vector,
87 __print_ns_to_secs(__entry->start),
88 __print_ns_without_secs(__entry->start),
89 __entry->duration)
90);
91
92TRACE_EVENT(nmi_noise,
93
94 TP_PROTO(u64 start, u64 duration),
95
96 TP_ARGS(start, duration),
97
98 TP_STRUCT__entry(
99 __field( u64, start )
100 __field( u64, duration)
101 ),
102
103 TP_fast_assign(
104 __entry->start = start;
105 __entry->duration = duration;
106 ),
107
108 TP_printk("start %llu.%09u duration %llu ns",
109 __print_ns_to_secs(__entry->start),
110 __print_ns_without_secs(__entry->start),
111 __entry->duration)
112);
113
114TRACE_EVENT(sample_threshold,
115
116 TP_PROTO(u64 start, u64 duration, u64 interference),
117
118 TP_ARGS(start, duration, interference),
119
120 TP_STRUCT__entry(
121 __field( u64, start )
122 __field( u64, duration)
123 __field( u64, interference)
124 ),
125
126 TP_fast_assign(
127 __entry->start = start;
128 __entry->duration = duration;
129 __entry->interference = interference;
130 ),
131
132 TP_printk("start %llu.%09u duration %llu ns interference %llu",
133 __print_ns_to_secs(__entry->start),
134 __print_ns_without_secs(__entry->start),
135 __entry->duration,
136 __entry->interference)
137);
138
139#endif /* _TRACE_OSNOISE_H */
140
141/* This part must be outside protection */
142#include <trace/define_trace.h>
include/trace/events/rpcgss.h+2−2
@@ -152,7 +152,7 @@ DECLARE_EVENT_CLASS(rpcgss_ctx_class, · 151 unmodified lines
152 TP_fast_assign(152 TP_fast_assign(
153 __entry->cred = gc;153 __entry->cred = gc;
154 __entry->service = gc->gc_service;154 __entry->service = gc->gc_service;
155 __assign_str(principal, gc->gc_principal)155 __assign_str(principal, gc->gc_principal);
156 ),156 ),
157 157
158 TP_printk("cred=%p service=%s principal='%s'",158 TP_printk("cred=%p service=%s principal='%s'",
@@ -535,7 +535,7 @@ TRACE_EVENT(rpcgss_upcall_msg, · 376 unmodified lines
535 ),535 ),
536 536
537 TP_fast_assign(537 TP_fast_assign(
538 __assign_str(msg, buf)538 __assign_str(msg, buf);
539 ),539 ),
540 540
541 TP_printk("msg='%s'", __get_str(msg))541 TP_printk("msg='%s'", __get_str(msg))
include/trace/events/sched.h+0−2
@@ -148,7 +148,6 @@ DECLARE_EVENT_CLASS(sched_wakeup_template, · 147 unmodified lines
148 __array( char, comm, TASK_COMM_LEN )148 __array( char, comm, TASK_COMM_LEN )
149 __field( pid_t, pid )149 __field( pid_t, pid )
150 __field( int, prio )150 __field( int, prio )
151 __field( int, success )
152 __field( int, target_cpu )151 __field( int, target_cpu )
153 ),152 ),
154 153
@@ -156,7 +155,6 @@ DECLARE_EVENT_CLASS(sched_wakeup_template, · 1 unmodified line
156 memcpy(__entry->comm, p->comm, TASK_COMM_LEN);155 memcpy(__entry->comm, p->comm, TASK_COMM_LEN);
157 __entry->pid = p->pid;156 __entry->pid = p->pid;
158 __entry->prio = p->prio; /* XXX SCHED_DEADLINE */157 __entry->prio = p->prio; /* XXX SCHED_DEADLINE */
159 __entry->success = 1; /* rudiment, kill when possible */
160 __entry->target_cpu = task_cpu(p);158 __entry->target_cpu = task_cpu(p);
161 ),159 ),
162 160
include/trace/events/sunrpc.h+20−20
@@ -154,8 +154,8 @@ TRACE_EVENT(rpc_clnt_new, · 153 unmodified lines
154 __entry->client_id = clnt->cl_clid;154 __entry->client_id = clnt->cl_clid;
155 __assign_str(addr, xprt->address_strings[RPC_DISPLAY_ADDR]);155 __assign_str(addr, xprt->address_strings[RPC_DISPLAY_ADDR]);
156 __assign_str(port, xprt->address_strings[RPC_DISPLAY_PORT]);156 __assign_str(port, xprt->address_strings[RPC_DISPLAY_PORT]);
157 __assign_str(program, program)157 __assign_str(program, program);
158 __assign_str(server, server)158 __assign_str(server, server);
159 ),159 ),
160 160
161 TP_printk("client=%u peer=[%s]:%s program=%s server=%s",161 TP_printk("client=%u peer=[%s]:%s program=%s server=%s",
@@ -180,8 +180,8 @@ TRACE_EVENT(rpc_clnt_new_err, · 18 unmodified lines
180 180
181 TP_fast_assign(181 TP_fast_assign(
182 __entry->error = error;182 __entry->error = error;
183 __assign_str(program, program)183 __assign_str(program, program);
184 __assign_str(server, server)184 __assign_str(server, server);
185 ),185 ),
186 186
187 TP_printk("program=%s server=%s error=%d",187 TP_printk("program=%s server=%s error=%d",
@@ -284,8 +284,8 @@ TRACE_EVENT(rpc_request, · 96 unmodified lines
284 __entry->client_id = task->tk_client->cl_clid;284 __entry->client_id = task->tk_client->cl_clid;
285 __entry->version = task->tk_client->cl_vers;285 __entry->version = task->tk_client->cl_vers;
286 __entry->async = RPC_IS_ASYNC(task);286 __entry->async = RPC_IS_ASYNC(task);
287 __assign_str(progname, task->tk_client->cl_program->name)287 __assign_str(progname, task->tk_client->cl_program->name);
288 __assign_str(procname, rpc_proc_name(task))288 __assign_str(procname, rpc_proc_name(task));
289 ),289 ),
290 290
291 TP_printk("task:%u@%u %sv%d %s (%ssync)",291 TP_printk("task:%u@%u %sv%d %s (%ssync)",
@@ -494,10 +494,10 @@ DECLARE_EVENT_CLASS(rpc_reply_event, · 202 unmodified lines
494 __entry->task_id = task->tk_pid;494 __entry->task_id = task->tk_pid;
495 __entry->client_id = task->tk_client->cl_clid;495 __entry->client_id = task->tk_client->cl_clid;
496 __entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);496 __entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
497 __assign_str(progname, task->tk_client->cl_program->name)497 __assign_str(progname, task->tk_client->cl_program->name);
498 __entry->version = task->tk_client->cl_vers;498 __entry->version = task->tk_client->cl_vers;
499 __assign_str(procname, rpc_proc_name(task))499 __assign_str(procname, rpc_proc_name(task));
500 __assign_str(servername, task->tk_xprt->servername)500 __assign_str(servername, task->tk_xprt->servername);
501 ),501 ),
502 502
503 TP_printk("task:%u@%d server=%s xid=0x%08x %sv%d %s",503 TP_printk("task:%u@%d server=%s xid=0x%08x %sv%d %s",
@@ -622,8 +622,8 @@ TRACE_EVENT(rpc_stats_latency, · 118 unmodified lines
622 __entry->task_id = task->tk_pid;622 __entry->task_id = task->tk_pid;
623 __entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);623 __entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
624 __entry->version = task->tk_client->cl_vers;624 __entry->version = task->tk_client->cl_vers;
625 __assign_str(progname, task->tk_client->cl_program->name)625 __assign_str(progname, task->tk_client->cl_program->name);
626 __assign_str(procname, rpc_proc_name(task))626 __assign_str(procname, rpc_proc_name(task));
627 __entry->backlog = ktime_to_us(backlog);627 __entry->backlog = ktime_to_us(backlog);
628 __entry->rtt = ktime_to_us(rtt);628 __entry->rtt = ktime_to_us(rtt);
629 __entry->execute = ktime_to_us(execute);629 __entry->execute = ktime_to_us(execute);
@@ -669,15 +669,15 @@ TRACE_EVENT(rpc_xdr_overflow, · 39 unmodified lines
669 __entry->task_id = task->tk_pid;669 __entry->task_id = task->tk_pid;
670 __entry->client_id = task->tk_client->cl_clid;670 __entry->client_id = task->tk_client->cl_clid;
671 __assign_str(progname,671 __assign_str(progname,
672 task->tk_client->cl_program->name)672 task->tk_client->cl_program->name);
673 __entry->version = task->tk_client->cl_vers;673 __entry->version = task->tk_client->cl_vers;
674 __assign_str(procedure, task->tk_msg.rpc_proc->p_name)674 __assign_str(procedure, task->tk_msg.rpc_proc->p_name);
675 } else {675 } else {
676 __entry->task_id = 0;676 __entry->task_id = 0;
677 __entry->client_id = 0;677 __entry->client_id = 0;
678 __assign_str(progname, "unknown")678 __assign_str(progname, "unknown");
679 __entry->version = 0;679 __entry->version = 0;
680 __assign_str(procedure, "unknown")680 __assign_str(procedure, "unknown");
681 }681 }
682 __entry->requested = requested;682 __entry->requested = requested;
683 __entry->end = xdr->end;683 __entry->end = xdr->end;
@@ -735,9 +735,9 @@ TRACE_EVENT(rpc_xdr_alignment, · 51 unmodified lines
735 __entry->task_id = task->tk_pid;735 __entry->task_id = task->tk_pid;
736 __entry->client_id = task->tk_client->cl_clid;736 __entry->client_id = task->tk_client->cl_clid;
737 __assign_str(progname,737 __assign_str(progname,
738 task->tk_client->cl_program->name)738 task->tk_client->cl_program->name);
739 __entry->version = task->tk_client->cl_vers;739 __entry->version = task->tk_client->cl_vers;
740 __assign_str(procedure, task->tk_msg.rpc_proc->p_name)740 __assign_str(procedure, task->tk_msg.rpc_proc->p_name);
741 741
742 __entry->offset = offset;742 __entry->offset = offset;
743 __entry->copied = copied;743 __entry->copied = copied;
@@ -1107,9 +1107,9 @@ TRACE_EVENT(xprt_retransmit, · 363 unmodified lines
1107 __entry->xid = be32_to_cpu(rqst->rq_xid);1107 __entry->xid = be32_to_cpu(rqst->rq_xid);
1108 __entry->ntrans = rqst->rq_ntrans;1108 __entry->ntrans = rqst->rq_ntrans;
1109 __assign_str(progname,1109 __assign_str(progname,
1110 task->tk_client->cl_program->name)1110 task->tk_client->cl_program->name);
1111 __entry->version = task->tk_client->cl_vers;1111 __entry->version = task->tk_client->cl_vers;
1112 __assign_str(procedure, task->tk_msg.rpc_proc->p_name)1112 __assign_str(procedure, task->tk_msg.rpc_proc->p_name);
1113 ),1113 ),
1114 1114
1115 TP_printk(1115 TP_printk(
@@ -1842,7 +1842,7 @@ TRACE_EVENT(svc_xprt_accept, · 726 unmodified lines
1842 1842
1843 TP_fast_assign(1843 TP_fast_assign(
1844 __assign_str(addr, xprt->xpt_remotebuf);1844 __assign_str(addr, xprt->xpt_remotebuf);
1845 __assign_str(protocol, xprt->xpt_class->xcl_name)1845 __assign_str(protocol, xprt->xpt_class->xcl_name);
1846 __assign_str(service, service);1846 __assign_str(service, service);
1847 ),1847 ),
1848 1848
include/trace/events/writeback.h+2−1
@@ -36,7 +36,8 @@ · 35 unmodified lines
36 EM( WB_REASON_PERIODIC, "periodic") \36 EM( WB_REASON_PERIODIC, "periodic") \
37 EM( WB_REASON_LAPTOP_TIMER, "laptop_timer") \37 EM( WB_REASON_LAPTOP_TIMER, "laptop_timer") \
38 EM( WB_REASON_FS_FREE_SPACE, "fs_free_space") \38 EM( WB_REASON_FS_FREE_SPACE, "fs_free_space") \
39 EMe(WB_REASON_FORKER_THREAD, "forker_thread")39 EM( WB_REASON_FORKER_THREAD, "forker_thread") \
40 EMe(WB_REASON_FOREIGN_FLUSH, "foreign_flush")
40 41
41WB_WORK_REASON42WB_WORK_REASON
42 43
include/trace/trace_events.h+25−0
@@ -358,6 +358,21 @@ TRACE_MAKE_SYSTEM_STR(); · 357 unmodified lines
358 trace_print_hex_dump_seq(p, prefix_str, prefix_type, \358 trace_print_hex_dump_seq(p, prefix_str, prefix_type, \
359 rowsize, groupsize, buf, len, ascii)359 rowsize, groupsize, buf, len, ascii)
360 360
361#undef __print_ns_to_secs
362#define __print_ns_to_secs(value) \
363 ({ \
364 u64 ____val = (u64)(value); \
365 do_div(____val, NSEC_PER_SEC); \
366 ____val; \
367 })
368
369#undef __print_ns_without_secs
370#define __print_ns_without_secs(value) \
371 ({ \
372 u64 ____val = (u64)(value); \
373 (u32) do_div(____val, NSEC_PER_SEC); \
374 })
375
361#undef DECLARE_EVENT_CLASS376#undef DECLARE_EVENT_CLASS
362#define DECLARE_EVENT_CLASS(call, proto, args, tstruct, assign, print) \377#define DECLARE_EVENT_CLASS(call, proto, args, tstruct, assign, print) \
363static notrace enum print_line_t \378static notrace enum print_line_t \
@@ -736,6 +751,16 @@ static inline void ftrace_test_probe_##call(void) \ · 372 unmodified lines
736#undef __print_array751#undef __print_array
737#undef __print_hex_dump752#undef __print_hex_dump
738 753
754/*
755 * The below is not executed in the kernel. It is only what is
756 * displayed in the print format for userspace to parse.
757 */
758#undef __print_ns_to_secs
759#define __print_ns_to_secs(val) (val) / 1000000000UL
760
761#undef __print_ns_without_secs
762#define __print_ns_without_secs(val) (val) % 1000000000UL
763
739#undef TP_printk764#undef TP_printk
740#define TP_printk(fmt, args...) "\"" fmt "\", " __stringify(args)765#define TP_printk(fmt, args...) "\"" fmt "\", " __stringify(args)
741 766