2 * Copyright (c) 2005 The DragonFly Project. All rights reserved.
4 * This code is derived from software contributed to The DragonFly Project
5 * by Matthew Dillon <dillon@backplane.com>
7 * Redistribution and use in source and binary forms, with or without
8 * modification, are permitted provided that the following conditions
11 * 1. Redistributions of source code must retain the above copyright
12 * notice, this list of conditions and the following disclaimer.
13 * 2. Redistributions in binary form must reproduce the above copyright
14 * notice, this list of conditions and the following disclaimer in
15 * the documentation and/or other materials provided with the
17 * 3. Neither the name of The DragonFly Project nor the names of its
18 * contributors may be used to endorse or promote products derived
19 * from this software without specific, prior written permission.
21 * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
22 * ``AS IS'' AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
23 * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS
24 * FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE
25 * COPYRIGHT HOLDERS OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT,
26 * INCIDENTAL, SPECIAL, EXEMPLARY OR CONSEQUENTIAL DAMAGES (INCLUDING,
27 * BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES;
28 * LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED
29 * AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY,
30 * OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT
31 * OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
35 * The following copyright applies to the DDB command code:
37 * Copyright (c) 2000 John Baldwin <jhb@FreeBSD.org>
38 * All rights reserved.
40 * Redistribution and use in source and binary forms, with or without
41 * modification, are permitted provided that the following conditions
43 * 1. Redistributions of source code must retain the above copyright
44 * notice, this list of conditions and the following disclaimer.
45 * 2. Redistributions in binary form must reproduce the above copyright
46 * notice, this list of conditions and the following disclaimer in the
47 * documentation and/or other materials provided with the distribution.
48 * 3. Neither the name of the author nor the names of any co-contributors
49 * may be used to endorse or promote products derived from this software
50 * without specific prior written permission.
52 * THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
53 * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
54 * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
55 * ARE DISCLAIMED. IN NO EVENT SHALL THE AUTHOR OR CONTRIBUTORS BE LIABLE
56 * FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
57 * DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
58 * OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
59 * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
60 * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
61 * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
65 * $DragonFly: src/sys/kern/kern_ktr.c,v 1.23 2008/02/12 23:33:23 corecode Exp $
68 * Kernel tracepoint facility.
74 #include <sys/param.h>
76 #include <sys/kernel.h>
77 #include <sys/libkern.h>
79 #include <sys/sysctl.h>
81 #include <sys/systm.h>
83 #include <sys/malloc.h>
84 #include <sys/spinlock.h>
85 #include <sys/thread2.h>
86 #include <sys/spinlock2.h>
87 #include <sys/ctype.h>
89 #include <machine/cpu.h>
90 #include <machine/cpufunc.h>
91 #include <machine/specialreg.h>
92 #include <machine/md_var.h>
97 #define KTR_ENTRIES 2048
99 #define KTR_ENTRIES_MASK (KTR_ENTRIES - 1)
102 * test logging support. When ktr_testlogcnt is non-zero each synchronization
103 * interrupt will issue six back-to-back ktr logging messages on cpu 0
104 * so the user can determine KTR logging overheads.
106 #if !defined(KTR_TESTLOG)
107 #define KTR_TESTLOG KTR_ALL
109 KTR_INFO_MASTER(testlog
);
111 KTR_INFO(KTR_TESTLOG
, testlog
, test1
, 0, "test1", sizeof(void *) * 4);
112 KTR_INFO(KTR_TESTLOG
, testlog
, test2
, 1, "test2", sizeof(void *) * 4);
113 KTR_INFO(KTR_TESTLOG
, testlog
, test3
, 2, "test3", sizeof(void *) * 4);
114 KTR_INFO(KTR_TESTLOG
, testlog
, test4
, 3, "test4", 0);
115 KTR_INFO(KTR_TESTLOG
, testlog
, test5
, 4, "test5", 0);
116 KTR_INFO(KTR_TESTLOG
, testlog
, test6
, 5, "test6", 0);
118 KTR_INFO(KTR_TESTLOG
, testlog
, pingpong
, 6, "pingpong", 0);
119 KTR_INFO(KTR_TESTLOG
, testlog
, pipeline
, 7, "pipeline", 0);
120 KTR_INFO(KTR_TESTLOG
, testlog
, crit_beg
, 8, "crit_beg", 0);
121 KTR_INFO(KTR_TESTLOG
, testlog
, crit_end
, 9, "crit_end", 0);
122 KTR_INFO(KTR_TESTLOG
, testlog
, spin_beg
, 10, "spin_beg", 0);
123 KTR_INFO(KTR_TESTLOG
, testlog
, spin_end
, 11, "spin_end", 0);
125 #define logtest(name) KTR_LOG(testlog_ ## name, 0, 0, 0, 0)
126 #define logtest_noargs(name) KTR_LOG(testlog_ ## name)
129 MALLOC_DEFINE(M_KTR
, "ktr", "ktr buffers");
131 SYSCTL_NODE(_debug
, OID_AUTO
, ktr
, CTLFLAG_RW
, 0, "ktr");
133 int ktr_entries
= KTR_ENTRIES
;
134 SYSCTL_INT(_debug_ktr
, OID_AUTO
, entries
, CTLFLAG_RD
, &ktr_entries
, 0, "");
136 int ktr_version
= KTR_VERSION
;
137 SYSCTL_INT(_debug_ktr
, OID_AUTO
, version
, CTLFLAG_RD
, &ktr_version
, 0, "");
139 static int ktr_stacktrace
= 1;
140 SYSCTL_INT(_debug_ktr
, OID_AUTO
, stacktrace
, CTLFLAG_RD
, &ktr_stacktrace
, 0, "");
142 static int ktr_resynchronize
= 0;
143 SYSCTL_INT(_debug_ktr
, OID_AUTO
, resynchronize
, CTLFLAG_RW
, &ktr_resynchronize
, 0, "");
146 static int ktr_testlogcnt
= 0;
147 SYSCTL_INT(_debug_ktr
, OID_AUTO
, testlogcnt
, CTLFLAG_RW
, &ktr_testlogcnt
, 0, "");
148 static int ktr_testipicnt
= 0;
150 static int ktr_testipicnt_remainder
;
152 SYSCTL_INT(_debug_ktr
, OID_AUTO
, testipicnt
, CTLFLAG_RW
, &ktr_testipicnt
, 0, "");
153 static int ktr_testcritcnt
= 0;
154 SYSCTL_INT(_debug_ktr
, OID_AUTO
, testcritcnt
, CTLFLAG_RW
, &ktr_testcritcnt
, 0, "");
155 static int ktr_testspincnt
= 0;
156 SYSCTL_INT(_debug_ktr
, OID_AUTO
, testspincnt
, CTLFLAG_RW
, &ktr_testspincnt
, 0, "");
160 * Give cpu0 a static buffer so the tracepoint facility can be used during
161 * early boot (note however that we still use a critical section, XXX).
163 static struct ktr_entry ktr_buf0
[KTR_ENTRIES
];
165 __cachealign
struct ktr_cpu ktr_cpu
[MAXCPU
] = {
166 { .core
.ktr_buf
= &ktr_buf0
[0] }
170 static int64_t ktr_sync_tsc
;
172 struct callout ktr_resync_callout
;
175 int ktr_verbose
= KTR_VERBOSE
;
176 TUNABLE_INT("debug.ktr.verbose", &ktr_verbose
);
177 SYSCTL_INT(_debug_ktr
, OID_AUTO
, verbose
, CTLFLAG_RW
, &ktr_verbose
, 0, "");
180 static void ktr_resync_callback(void *dummy __unused
);
182 extern int64_t tsc_offsets
[];
185 ktr_sysinit(void *dummy
)
187 struct ktr_cpu_core
*kcpu
;
190 for(i
= 1; i
< ncpus
; ++i
) {
191 kcpu
= &ktr_cpu
[i
].core
;
192 kcpu
->ktr_buf
= kmalloc(KTR_ENTRIES
* sizeof(struct ktr_entry
),
193 M_KTR
, M_WAITOK
| M_ZERO
);
195 callout_init(&ktr_resync_callout
);
196 callout_reset(&ktr_resync_callout
, hz
/ 10, ktr_resync_callback
, NULL
);
198 SYSINIT(ktr_sysinit
, SI_BOOT2_KLD
, SI_ORDER_ANY
, ktr_sysinit
, NULL
);
201 * Try to resynchronize the TSC's for all cpus. This is really, really nasty.
202 * We have to send an IPIQ message to all remote cpus, wait until they
203 * get into their IPIQ processing code loop, then do an even stricter hard
204 * loop to get the cpus as close to synchronized as we can to get the most
207 * This callback occurs on cpu0.
211 static void ktr_pingpong_remote(void *dummy
);
212 static void ktr_pipeline_remote(void *dummy
);
216 #if defined(SMP) && defined(_RDTSC_SUPPORTED_)
218 static void ktr_resync_remote(void *dummy
);
219 extern cpumask_t smp_active_mask
;
222 * We use a callout callback instead of a systimer because we cannot afford
223 * to preempt anyone to do this, or we might deadlock a spin-lock or
224 * serializer between two cpus.
228 ktr_resync_callback(void *dummy __unused
)
230 struct lwkt_cpusync cs
;
235 KKASSERT(mycpu
->gd_cpuid
== 0);
241 if (ktr_testlogcnt
) {
247 logtest_noargs(test4
);
248 logtest_noargs(test5
);
249 logtest_noargs(test6
);
256 if (ktr_testipicnt
&& ktr_testipicnt_remainder
== 0 && ncpus
> 1) {
257 ktr_testipicnt_remainder
= ktr_testipicnt
;
259 lwkt_send_ipiq_bycpu(1, ktr_pingpong_remote
, NULL
);
263 * Test critical sections
265 if (ktr_testcritcnt
) {
268 logtest_noargs(crit_beg
);
269 for (count
= ktr_testcritcnt
; count
; --count
) {
273 logtest_noargs(crit_end
);
278 * Test spinlock sections
280 if (ktr_testspincnt
) {
281 struct spinlock spin
;
286 logtest_noargs(spin_beg
);
287 for (count
= ktr_testspincnt
; count
; --count
) {
291 logtest_noargs(spin_end
);
297 * Resynchronize the TSC
299 if (ktr_resynchronize
== 0)
301 if ((cpu_feature
& CPUID_TSC
) == 0)
305 lwkt_cpusync_init(&cs
, smp_active_mask
, ktr_resync_remote
,
306 (void *)(intptr_t)mycpu
->gd_cpuid
);
307 lwkt_cpusync_interlock(&cs
);
308 ktr_sync_tsc
= rdtsc();
309 lwkt_cpusync_deinterlock(&cs
);
312 callout_reset(&ktr_resync_callout
, hz
/ 10, ktr_resync_callback
, NULL
);
316 * The remote-end of the KTR synchronization protocol runs on all cpus.
317 * The one we run on the controlling cpu updates its tsc continuously
318 * until the others have finished syncing (theoretically), but we don't
321 * This is a bit ad-hoc but we need to avoid livelocking inside an IPI
322 * callback. rdtsc() is a synchronizing instruction (I think).
325 ktr_resync_remote(void *arg
)
327 globaldata_t gd
= mycpu
;
331 if (gd
->gd_cpuid
== (int)(intptr_t)arg
) {
332 for (i
= 0; i
< 2000; ++i
)
333 ktr_sync_tsc
= rdtsc();
335 delta
= rdtsc() - ktr_sync_tsc
;
336 if (tsc_offsets
[gd
->gd_cpuid
] == 0)
337 tsc_offsets
[gd
->gd_cpuid
] = delta
;
338 tsc_offsets
[gd
->gd_cpuid
] =
339 (tsc_offsets
[gd
->gd_cpuid
] * 7 + delta
) / 8;
347 ktr_pingpong_remote(void *dummy __unused
)
351 logtest_noargs(pingpong
);
352 other_cpu
= 1 - mycpu
->gd_cpuid
;
353 if (ktr_testipicnt_remainder
) {
354 --ktr_testipicnt_remainder
;
355 lwkt_send_ipiq_bycpu(other_cpu
, ktr_pingpong_remote
, NULL
);
357 lwkt_send_ipiq_bycpu(other_cpu
, ktr_pipeline_remote
, NULL
);
358 lwkt_send_ipiq_bycpu(other_cpu
, ktr_pipeline_remote
, NULL
);
359 lwkt_send_ipiq_bycpu(other_cpu
, ktr_pipeline_remote
, NULL
);
360 lwkt_send_ipiq_bycpu(other_cpu
, ktr_pipeline_remote
, NULL
);
361 lwkt_send_ipiq_bycpu(other_cpu
, ktr_pipeline_remote
, NULL
);
367 ktr_pipeline_remote(void *dummy __unused
)
369 logtest_noargs(pipeline
);
377 * The resync callback for UP doesn't do anything other then run the test
378 * log messages. If test logging is not enabled, don't bother resetting
383 ktr_resync_callback(void *dummy __unused
)
389 if (ktr_testlogcnt
) {
395 logtest_noargs(test4
);
396 logtest_noargs(test5
);
397 logtest_noargs(test6
);
400 callout_reset(&ktr_resync_callout
, hz
/ 10, ktr_resync_callback
, NULL
);
407 * KTR_WRITE_ENTRY - Primary entry point for kernel trace logging
412 ktr_write_entry(struct ktr_info
*info
, const char *file
, int line
, __va_list va
)
414 struct ktr_cpu_core
*kcpu
;
415 struct ktr_entry
*entry
;
418 cpu
= mycpu
->gd_cpuid
;
419 kcpu
= &ktr_cpu
[cpu
].core
;
420 if (kcpu
->ktr_buf
== NULL
)
424 entry
= kcpu
->ktr_buf
+ (kcpu
->ktr_idx
& KTR_ENTRIES_MASK
);
426 #ifdef _RDTSC_SUPPORTED_
427 if (cpu_feature
& CPUID_TSC
) {
429 entry
->ktr_timestamp
= rdtsc() - tsc_offsets
[cpu
];
431 entry
->ktr_timestamp
= rdtsc();
436 entry
->ktr_timestamp
= get_approximate_time_t();
438 entry
->ktr_info
= info
;
439 entry
->ktr_file
= file
;
440 entry
->ktr_line
= line
;
442 if (info
->kf_data_size
> KTR_BUFSIZE
)
443 bcopy(va
, entry
->ktr_data
, KTR_BUFSIZE
);
444 else if (info
->kf_data_size
)
445 bcopy(va
, entry
->ktr_data
, info
->kf_data_size
);
447 cpu_ktr_caller(entry
);
449 if (ktr_verbose
&& info
->kf_format
) {
451 kprintf("cpu%d ", cpu
);
453 if (ktr_verbose
> 1) {
454 kprintf("%s.%d\t", entry
->ktr_file
, entry
->ktr_line
);
456 kvprintf(info
->kf_format
, va
);
463 ktr_log(struct ktr_info
*info
, const char *file
, int line
, ...)
467 if (panicstr
== NULL
) {
468 __va_start(va
, line
);
469 ktr_write_entry(info
, file
, line
, va
);
476 #define NUM_LINES_PER_PAGE 19
483 static int db_ktr_verbose
;
484 static int db_mach_vtrace(int cpu
, struct ktr_entry
*kp
, int idx
);
486 DB_SHOW_COMMAND(ktr
, db_ktr_all
)
488 struct ktr_cpu_core
*kcpu
;
493 struct tstate tstate
[MAXCPU
];
496 for(i
= 0; i
< ncpus
; i
++) {
497 kcpu
= &ktr_cpu
[i
].core
;
498 tstate
[i
].first
= -1;
499 tstate
[i
].cur
= (kcpu
->ktr_idx
- 1) & KTR_ENTRIES_MASK
;
502 while ((c
= *(modif
++)) != '\0') {
511 while ((c
= *(modif
++)) != '\0') {
524 if (printcpu
> ncpus
- 1) {
525 db_printf("Invalid cpu number\n");
529 * Lopp throug all the buffers and print the content of them, sorted
534 u_int64_t highest_ts
;
536 struct ktr_entry
*kp
;
538 if (a_flag
== 1 && cncheckc() != -1)
543 * Find the lowest timestamp
545 for (i
= 0, counter
= 0; i
< ncpus
; i
++) {
546 kcpu
= &ktr_cpu
[i
].core
;
547 if (kcpu
->ktr_buf
== NULL
)
549 if (printcpu
!= -1 && printcpu
!= i
)
551 if (tstate
[i
].cur
== -1) {
553 if (counter
== ncpus
) {
554 db_printf("--- End of trace buffer ---\n");
559 if (kcpu
->ktr_buf
[tstate
[i
].cur
].ktr_timestamp
> highest_ts
) {
560 highest_ts
= kcpu
->ktr_buf
[tstate
[i
].cur
].ktr_timestamp
;
564 if (highest_cpu
< 0) {
565 db_printf("no KTR data available\n");
569 kcpu
= &ktr_cpu
[i
].core
;
570 kp
= &kcpu
->ktr_buf
[tstate
[i
].cur
];
571 if (tstate
[i
].first
== -1)
572 tstate
[i
].first
= tstate
[i
].cur
;
573 if (--tstate
[i
].cur
< 0)
574 tstate
[i
].cur
= KTR_ENTRIES
- 1;
575 if (tstate
[i
].first
== tstate
[i
].cur
) {
576 db_mach_vtrace(i
, kp
, tstate
[i
].cur
+ 1);
580 if (kcpu
->ktr_buf
[tstate
[i
].cur
].ktr_info
== NULL
)
582 if (db_more(&nl
) == -1)
584 if (db_mach_vtrace(i
, kp
, tstate
[i
].cur
+ 1) == 0)
590 db_mach_vtrace(int cpu
, struct ktr_entry
*kp
, int idx
)
592 if (kp
->ktr_info
== NULL
)
595 db_printf("cpu%d ", cpu
);
597 db_printf("%d: ", idx
);
598 if (db_ktr_verbose
) {
599 db_printf("%10.10lld %s.%d\t", (long long)kp
->ktr_timestamp
,
600 kp
->ktr_file
, kp
->ktr_line
);
602 db_printf("%s\t", kp
->ktr_info
->kf_name
);
603 db_printf("from(%p,%p) ", kp
->ktr_caller1
, kp
->ktr_caller2
);
605 if (kp
->ktr_info
->kf_format
)
606 db_vprintf(kp
->ktr_info
->kf_format
, (__va_list
)kp
->ktr_data
);