aboutsummaryrefslogtreecommitdiffstats
path: root/kernel/trace/trace_boot.c
diff options
context:
space:
mode:
authorFrederic Weisbecker <fweisbec@gmail.com>2008-11-11 17:24:42 -0500
committerIngo Molnar <mingo@elte.hu>2008-11-12 04:17:19 -0500
commit74239072830ef3f1398edeb1bc1076fc330fd4a2 (patch)
tree60a244c6c88d9943760ded98a1a29ce018292107 /kernel/trace/trace_boot.c
parent3f5ec13696fd4a33bde42f385406cbb1d3cc96fd (diff)
tracing/fastboot: Use the ring-buffer timestamp for initcall entries
Impact: Split the boot tracer entries in two parts: call and return Now that we are using the sched tracer from the boot tracer, we want to use the same timestamp than the ring-buffer to have consistent time captures between sched events and initcall events. So we get rid of the old time capture by the boot tracer and split the initcall events in two parts: call and return. This way we have the ring buffer timestamp of both. An example trace: [ 27.904149584] calling net_ns_init+0x0/0x1c0 @ 1 [ 27.904429624] initcall net_ns_init+0x0/0x1c0 returned 0 after 0 msecs [ 27.904575926] calling reboot_init+0x0/0x20 @ 1 [ 27.904655399] initcall reboot_init+0x0/0x20 returned 0 after 0 msecs [ 27.904800228] calling sysctl_init+0x0/0x30 @ 1 [ 27.905142914] initcall sysctl_init+0x0/0x30 returned 0 after 0 msecs [ 27.905287211] calling ksysfs_init+0x0/0xb0 @ 1 ##### CPU 0 buffer started #### init-1 [000] 27.905395: 1:120:R + [001] 11:115:S ##### CPU 1 buffer started #### <idle>-0 [001] 27.905425: 0:140:R ==> [001] 11:115:R init-1 [000] 27.905426: 1:120:D ==> [000] 0:140:R <idle>-0 [000] 27.905431: 0:140:R + [000] 4:115:S <idle>-0 [000] 27.905451: 0:140:R ==> [000] 4:115:R ksoftirqd/0-4 [000] 27.905456: 4:115:S ==> [000] 0:140:R udevd-11 [001] 27.905458: 11:115:R + [001] 14:115:R <idle>-0 [000] 27.905459: 0:140:R + [000] 4:115:S <idle>-0 [000] 27.905462: 0:140:R ==> [000] 4:115:R udevd-11 [001] 27.905462: 11:115:R ==> [001] 14:115:R ksoftirqd/0-4 [000] 27.905467: 4:115:S ==> [000] 0:140:R <idle>-0 [000] 27.905470: 0:140:R + [000] 4:115:S <idle>-0 [000] 27.905473: 0:140:R ==> [000] 4:115:R ksoftirqd/0-4 [000] 27.905476: 4:115:S ==> [000] 0:140:R <idle>-0 [000] 27.905479: 0:140:R + [000] 4:115:S <idle>-0 [000] 27.905482: 0:140:R ==> [000] 4:115:R ksoftirqd/0-4 [000] 27.905486: 4:115:S ==> [000] 0:140:R udevd-14 [001] 27.905499: 14:120:X ==> [001] 11:115:R udevd-11 [001] 27.905506: 11:115:R + [000] 1:120:D <idle>-0 [000] 27.905515: 0:140:R ==> [000] 1:120:R udevd-11 [001] 27.905517: 11:115:S ==> [001] 0:140:R [ 27.905557107] initcall ksysfs_init+0x0/0xb0 returned 0 after 3906 msecs [ 27.905705736] calling init_jiffies_clocksource+0x0/0x10 @ 1 [ 27.905779239] initcall init_jiffies_clocksource+0x0/0x10 returned 0 after 0 msecs [ 27.906769814] calling pm_init+0x0/0x30 @ 1 [ 27.906853627] initcall pm_init+0x0/0x30 returned 0 after 0 msecs [ 27.906997803] calling pm_disk_init+0x0/0x20 @ 1 [ 27.907076946] initcall pm_disk_init+0x0/0x20 returned 0 after 0 msecs [ 27.907222556] calling swsusp_header_init+0x0/0x30 @ 1 [ 27.907294325] initcall swsusp_header_init+0x0/0x30 returned 0 after 0 msecs [ 27.907439620] calling stop_machine_init+0x0/0x50 @ 1 init-1 [000] 27.907485: 1:120:R + [000] 2:115:S init-1 [000] 27.907490: 1:120:D ==> [000] 2:115:R kthreadd-2 [000] 27.907507: 2:115:R + [001] 15:115:R <idle>-0 [001] 27.907517: 0:140:R ==> [001] 15:115:R kthreadd-2 [000] 27.907517: 2:115:D ==> [000] 0:140:R <idle>-0 [000] 27.907521: 0:140:R + [000] 4:115:S <idle>-0 [000] 27.907524: 0:140:R ==> [000] 4:115:R udevd-15 [001] 27.907527: 15:115:D + [000] 2:115:D ksoftirqd/0-4 [000] 27.907537: 4:115:S ==> [000] 2:115:R udevd-15 [001] 27.907537: 15:115:D ==> [001] 0:140:R kthreadd-2 [000] 27.907546: 2:115:R + [000] 1:120:D kthreadd-2 [000] 27.907550: 2:115:S ==> [000] 1:120:R init-1 [000] 27.907584: 1:120:R + [000] 15: 0:D init-1 [000] 27.907589: 1:120:R + [000] 2:115:S init-1 [000] 27.907593: 1:120:D ==> [000] 15: 0:R udevd-15 [000] 27.907601: 15: 0:S ==> [000] 2:115:R ##### CPU 0 buffer started #### kthreadd-2 [000] 27.907616: 2:115:R + [001] 16:115:R ##### CPU 1 buffer started #### <idle>-0 [001] 27.907620: 0:140:R ==> [001] 16:115:R kthreadd-2 [000] 27.907621: 2:115:D ==> [000] 0:140:R udevd-16 [001] 27.907625: 16:115:D + [000] 2:115:D <idle>-0 [000] 27.907628: 0:140:R + [000] 4:115:S udevd-16 [001] 27.907629: 16:115:D ==> [001] 0:140:R <idle>-0 [000] 27.907631: 0:140:R ==> [000] 4:115:R ksoftirqd/0-4 [000] 27.907636: 4:115:S ==> [000] 2:115:R kthreadd-2 [000] 27.907644: 2:115:R + [000] 1:120:D kthreadd-2 [000] 27.907647: 2:115:S ==> [000] 1:120:R init-1 [000] 27.907657: 1:120:R + [001] 16: 0:D <idle>-0 [001] 27.907666: 0:140:R ==> [001] 16: 0:R [ 27.907703862] initcall stop_machine_init+0x0/0x50 returned 0 after 0 msecs [ 27.907850704] calling filelock_init+0x0/0x30 @ 1 [ 27.907926573] initcall filelock_init+0x0/0x30 returned 0 after 0 msecs [ 27.908071327] calling init_script_binfmt+0x0/0x10 @ 1 [ 27.908165195] initcall init_script_binfmt+0x0/0x10 returned 0 after 0 msecs [ 27.908309461] calling init_elf_binfmt+0x0/0x10 @ 1 Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com> Acked-by: Steven Rostedt <rostedt@goodmis.org> Signed-off-by: Ingo Molnar <mingo@elte.hu>
Diffstat (limited to 'kernel/trace/trace_boot.c')
-rw-r--r--kernel/trace/trace_boot.c123
1 files changed, 93 insertions, 30 deletions
diff --git a/kernel/trace/trace_boot.c b/kernel/trace/trace_boot.c
index 8f71915e8bb4..cb333b7fd113 100644
--- a/kernel/trace/trace_boot.c
+++ b/kernel/trace/trace_boot.c
@@ -58,35 +58,71 @@ static void boot_trace_init(struct trace_array *tr)
58 tracing_sched_switch_assign_trace(tr); 58 tracing_sched_switch_assign_trace(tr);
59} 59}
60 60
61static enum print_line_t initcall_print_line(struct trace_iterator *iter) 61static enum print_line_t
62initcall_call_print_line(struct trace_iterator *iter)
62{ 63{
64 struct trace_entry *entry = iter->ent;
65 struct trace_seq *s = &iter->seq;
66 struct trace_boot_call *field;
67 struct boot_trace_call *call;
68 u64 ts;
69 unsigned long nsec_rem;
63 int ret; 70 int ret;
71
72 trace_assign_type(field, entry);
73 call = &field->boot_call;
74 ts = iter->ts;
75 nsec_rem = do_div(ts, 1000000000);
76
77 ret = trace_seq_printf(s, "[%5ld.%09ld] calling %s @ %i\n",
78 (unsigned long)ts, nsec_rem, call->func, call->caller);
79
80 if (!ret)
81 return TRACE_TYPE_PARTIAL_LINE;
82 else
83 return TRACE_TYPE_HANDLED;
84}
85
86static enum print_line_t
87initcall_ret_print_line(struct trace_iterator *iter)
88{
64 struct trace_entry *entry = iter->ent; 89 struct trace_entry *entry = iter->ent;
65 struct trace_boot *field = (struct trace_boot *)entry;
66 struct boot_trace *it = &field->initcall;
67 struct trace_seq *s = &iter->seq; 90 struct trace_seq *s = &iter->seq;
68 struct timespec calltime = ktime_to_timespec(it->calltime); 91 struct trace_boot_ret *field;
69 struct timespec rettime = ktime_to_timespec(it->rettime); 92 struct boot_trace_ret *init_ret;
70 93 u64 ts;
71 if (entry->type == TRACE_BOOT) { 94 unsigned long nsec_rem;
72 ret = trace_seq_printf(s, "[%5ld.%09ld] calling %s @ %i\n", 95 int ret;
73 calltime.tv_sec, 96
74 calltime.tv_nsec, 97 trace_assign_type(field, entry);
75 it->func, it->caller); 98 init_ret = &field->boot_ret;
76 if (!ret) 99 ts = iter->ts;
77 return TRACE_TYPE_PARTIAL_LINE; 100 nsec_rem = do_div(ts, 1000000000);
78 101
79 ret = trace_seq_printf(s, "[%5ld.%09ld] initcall %s " 102 ret = trace_seq_printf(s, "[%5ld.%09ld] initcall %s "
80 "returned %d after %lld msecs\n", 103 "returned %d after %llu msecs\n",
81 rettime.tv_sec, 104 (unsigned long) ts,
82 rettime.tv_nsec, 105 nsec_rem,
83 it->func, it->result, it->duration); 106 init_ret->func, init_ret->result, init_ret->duration);
84 107
85 if (!ret) 108 if (!ret)
86 return TRACE_TYPE_PARTIAL_LINE; 109 return TRACE_TYPE_PARTIAL_LINE;
110 else
87 return TRACE_TYPE_HANDLED; 111 return TRACE_TYPE_HANDLED;
112}
113
114static enum print_line_t initcall_print_line(struct trace_iterator *iter)
115{
116 struct trace_entry *entry = iter->ent;
117
118 switch (entry->type) {
119 case TRACE_BOOT_CALL:
120 return initcall_call_print_line(iter);
121 case TRACE_BOOT_RET:
122 return initcall_ret_print_line(iter);
123 default:
124 return TRACE_TYPE_UNHANDLED;
88 } 125 }
89 return TRACE_TYPE_UNHANDLED;
90} 126}
91 127
92struct tracer boot_tracer __read_mostly = 128struct tracer boot_tracer __read_mostly =
@@ -97,11 +133,10 @@ struct tracer boot_tracer __read_mostly =
97 .print_line = initcall_print_line, 133 .print_line = initcall_print_line,
98}; 134};
99 135
100void trace_boot(struct boot_trace *it, initcall_t fn) 136void trace_boot_call(struct boot_trace_call *bt, initcall_t fn)
101{ 137{
102 struct ring_buffer_event *event; 138 struct ring_buffer_event *event;
103 struct trace_boot *entry; 139 struct trace_boot_call *entry;
104 struct trace_array_cpu *data;
105 unsigned long irq_flags; 140 unsigned long irq_flags;
106 struct trace_array *tr = boot_trace; 141 struct trace_array *tr = boot_trace;
107 142
@@ -111,9 +146,37 @@ void trace_boot(struct boot_trace *it, initcall_t fn)
111 /* Get its name now since this function could 146 /* Get its name now since this function could
112 * disappear because it is in the .init section. 147 * disappear because it is in the .init section.
113 */ 148 */
114 sprint_symbol(it->func, (unsigned long)fn); 149 sprint_symbol(bt->func, (unsigned long)fn);
150 preempt_disable();
151
152 event = ring_buffer_lock_reserve(tr->buffer, sizeof(*entry),
153 &irq_flags);
154 if (!event)
155 goto out;
156 entry = ring_buffer_event_data(event);
157 tracing_generic_entry_update(&entry->ent, 0, 0);
158 entry->ent.type = TRACE_BOOT_CALL;
159 entry->boot_call = *bt;
160 ring_buffer_unlock_commit(tr->buffer, event, irq_flags);
161
162 trace_wake_up();
163
164 out:
165 preempt_enable();
166}
167
168void trace_boot_ret(struct boot_trace_ret *bt, initcall_t fn)
169{
170 struct ring_buffer_event *event;
171 struct trace_boot_ret *entry;
172 unsigned long irq_flags;
173 struct trace_array *tr = boot_trace;
174
175 if (!pre_initcalls_finished)
176 return;
177
178 sprint_symbol(bt->func, (unsigned long)fn);
115 preempt_disable(); 179 preempt_disable();
116 data = tr->data[smp_processor_id()];
117 180
118 event = ring_buffer_lock_reserve(tr->buffer, sizeof(*entry), 181 event = ring_buffer_lock_reserve(tr->buffer, sizeof(*entry),
119 &irq_flags); 182 &irq_flags);
@@ -121,8 +184,8 @@ void trace_boot(struct boot_trace *it, initcall_t fn)
121 goto out; 184 goto out;
122 entry = ring_buffer_event_data(event); 185 entry = ring_buffer_event_data(event);
123 tracing_generic_entry_update(&entry->ent, 0, 0); 186 tracing_generic_entry_update(&entry->ent, 0, 0);
124 entry->ent.type = TRACE_BOOT; 187 entry->ent.type = TRACE_BOOT_RET;
125 entry->initcall = *it; 188 entry->boot_ret = *bt;
126 ring_buffer_unlock_commit(tr->buffer, event, irq_flags); 189 ring_buffer_unlock_commit(tr->buffer, event, irq_flags);
127 190
128 trace_wake_up(); 191 trace_wake_up();
generated by cgit v1.2.2 (git 2.25.0) at 2024-12-19 10:27:38 -0500