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.21 2007/04/30 07:18:53 dillon 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);
121 KTR_INFO(KTR_TESTLOG
, testlog
, crit_beg
, 8, "crit_beg", 0);
122 KTR_INFO(KTR_TESTLOG
, testlog
, crit_end
, 9, "crit_end", 0);
123 KTR_INFO(KTR_TESTLOG
, testlog
, spin_beg
, 10, "spin_beg", 0);
124 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 static int32_t ktr_cpumask
= -1;
134 TUNABLE_INT("debug.ktr.cpumask", &ktr_cpumask
);
135 SYSCTL_INT(_debug_ktr
, OID_AUTO
, cpumask
, CTLFLAG_RW
, &ktr_cpumask
, 0, "");
137 static int ktr_entries
= KTR_ENTRIES
;
138 SYSCTL_INT(_debug_ktr
, OID_AUTO
, entries
, CTLFLAG_RD
, &ktr_entries
, 0, "");
140 static int ktr_version
= KTR_VERSION
;
141 SYSCTL_INT(_debug_ktr
, OID_AUTO
, version
, CTLFLAG_RD
, &ktr_version
, 0, "");
143 static int ktr_stacktrace
= 1;
144 SYSCTL_INT(_debug_ktr
, OID_AUTO
, stacktrace
, CTLFLAG_RD
, &ktr_stacktrace
, 0, "");
146 static int ktr_resynchronize
= 0;
147 SYSCTL_INT(_debug_ktr
, OID_AUTO
, resynchronize
, CTLFLAG_RW
, &ktr_resynchronize
, 0, "");
150 static int ktr_testlogcnt
= 0;
151 SYSCTL_INT(_debug_ktr
, OID_AUTO
, testlogcnt
, CTLFLAG_RW
, &ktr_testlogcnt
, 0, "");
152 static int ktr_testipicnt
= 0;
153 static int ktr_testipicnt_remainder
;
154 SYSCTL_INT(_debug_ktr
, OID_AUTO
, testipicnt
, CTLFLAG_RW
, &ktr_testipicnt
, 0, "");
155 static int ktr_testcritcnt
= 0;
156 SYSCTL_INT(_debug_ktr
, OID_AUTO
, testcritcnt
, CTLFLAG_RW
, &ktr_testcritcnt
, 0, "");
157 static int ktr_testspincnt
= 0;
158 SYSCTL_INT(_debug_ktr
, OID_AUTO
, testspincnt
, CTLFLAG_RW
, &ktr_testspincnt
, 0, "");
162 * Give cpu0 a static buffer so the tracepoint facility can be used during
163 * early boot (note however that we still use a critical section, XXX).
165 static struct ktr_entry ktr_buf0
[KTR_ENTRIES
];
166 static struct ktr_entry
*ktr_buf
[MAXCPU
] = { &ktr_buf0
[0] };
167 static int ktr_idx
[MAXCPU
];
169 static int ktr_sync_state
= 0;
170 static int ktr_sync_count
;
171 static int64_t ktr_sync_tsc
;
173 struct callout ktr_resync_callout
;
176 int ktr_verbose
= KTR_VERBOSE
;
177 TUNABLE_INT("debug.ktr.verbose", &ktr_verbose
);
178 SYSCTL_INT(_debug_ktr
, OID_AUTO
, verbose
, CTLFLAG_RW
, &ktr_verbose
, 0, "");
181 static void ktr_resync_callback(void *dummy __unused
);
183 extern int64_t tsc_offsets
[];
186 ktr_sysinit(void *dummy
)
190 for(i
= 1; i
< ncpus
; ++i
) {
191 ktr_buf
[i
] = kmalloc(KTR_ENTRIES
* sizeof(struct ktr_entry
),
192 M_KTR
, M_WAITOK
| M_ZERO
);
194 callout_init(&ktr_resync_callout
);
195 callout_reset(&ktr_resync_callout
, hz
/ 10, ktr_resync_callback
, NULL
);
197 SYSINIT(ktr_sysinit
, SI_BOOT2_KLD
, SI_ORDER_ANY
, ktr_sysinit
, NULL
);
200 * Try to resynchronize the TSC's for all cpus. This is really, really nasty.
201 * We have to send an IPIQ message to all remote cpus, wait until they
202 * get into their IPIQ processing code loop, then do an even stricter hard
203 * loop to get the cpus as close to synchronized as we can to get the most
206 * This callback occurs on cpu0.
209 static void ktr_pingpong_remote(void *dummy
);
210 static void ktr_pipeline_remote(void *dummy
);
213 #if defined(SMP) && defined(_RDTSC_SUPPORTED_)
215 static void ktr_resync_remote(void *dummy
);
216 extern cpumask_t smp_active_mask
;
219 * We use a callout callback instead of a systimer because we cannot afford
220 * to preempt anyone to do this, or we might deadlock a spin-lock or
221 * serializer between two cpus.
225 ktr_resync_callback(void *dummy __unused
)
229 KKASSERT(mycpu
->gd_cpuid
== 0);
235 if (ktr_testlogcnt
) {
241 logtest_noargs(test4
);
242 logtest_noargs(test5
);
243 logtest_noargs(test6
);
250 if (ktr_testipicnt
&& ktr_testipicnt_remainder
== 0 && ncpus
> 1) {
251 ktr_testipicnt_remainder
= ktr_testipicnt
;
253 lwkt_send_ipiq_bycpu(1, ktr_pingpong_remote
, NULL
);
257 * Test critical sections
259 if (ktr_testcritcnt
) {
262 logtest_noargs(crit_beg
);
263 for (count
= ktr_testcritcnt
; count
; --count
) {
267 logtest_noargs(crit_end
);
272 * Test spinlock sections
274 if (ktr_testspincnt
) {
275 struct spinlock spin
;
279 spin_unlock_wr(&spin
);
280 logtest_noargs(spin_beg
);
281 for (count
= ktr_testspincnt
; count
; --count
) {
283 spin_unlock_wr(&spin
);
285 logtest_noargs(spin_end
);
286 logtest_noargs(spin_beg
);
287 for (count
= ktr_testspincnt
; count
; --count
) {
289 spin_unlock_rd(&spin
);
291 logtest_noargs(spin_end
);
297 * Resynchronize the TSC
299 if (ktr_resynchronize
== 0)
301 if ((cpu_feature
& CPUID_TSC
) == 0)
305 * Send the synchronizing IPI and wait for all cpus to get into
306 * their spin loop. We must process incoming IPIs while waiting
307 * to avoid a deadlock.
312 ktr_sync_tsc
= rdtsc();
313 count
= lwkt_send_ipiq_mask(mycpu
->gd_other_cpus
& smp_active_mask
,
314 (ipifunc1_t
)ktr_resync_remote
, NULL
);
315 while (ktr_sync_count
!= count
)
319 * Continuously update the TSC for cpu 0 while waiting for all other
320 * cpus to finish stage 2.
323 ktr_sync_tsc
= rdtsc();
327 while (ktr_sync_count
!= 0) {
328 ktr_sync_tsc
= rdtsc();
336 callout_reset(&ktr_resync_callout
, hz
/ 10, ktr_resync_callback
, NULL
);
340 * The remote-end of the KTR synchronization protocol runs on all cpus except
341 * cpu 0. Since this is an IPI function, it is entered with the current
342 * thread in a critical section.
345 ktr_resync_remote(void *dummy __unused
)
347 volatile int64_t tsc1
= ktr_sync_tsc
;
348 volatile int64_t tsc2
;
351 * Inform the master that we have entered our hard loop.
353 KKASSERT(ktr_sync_state
== 1);
354 atomic_add_int(&ktr_sync_count
, 1);
355 while (ktr_sync_state
== 1) {
360 * Now the master is in a hard loop, synchronize the TSC and
364 KKASSERT(ktr_sync_state
== 2);
367 tsc_offsets
[mycpu
->gd_cpuid
] = rdtsc() - tsc2
;
368 atomic_subtract_int(&ktr_sync_count
, 1);
376 ktr_pingpong_remote(void *dummy __unused
)
380 logtest_noargs(pingpong
);
381 other_cpu
= 1 - mycpu
->gd_cpuid
;
382 if (ktr_testipicnt_remainder
) {
383 --ktr_testipicnt_remainder
;
384 lwkt_send_ipiq_bycpu(other_cpu
, ktr_pingpong_remote
, NULL
);
386 lwkt_send_ipiq_bycpu(other_cpu
, ktr_pipeline_remote
, NULL
);
387 lwkt_send_ipiq_bycpu(other_cpu
, ktr_pipeline_remote
, NULL
);
388 lwkt_send_ipiq_bycpu(other_cpu
, ktr_pipeline_remote
, NULL
);
389 lwkt_send_ipiq_bycpu(other_cpu
, ktr_pipeline_remote
, NULL
);
390 lwkt_send_ipiq_bycpu(other_cpu
, ktr_pipeline_remote
, NULL
);
396 ktr_pipeline_remote(void *dummy __unused
)
398 logtest_noargs(pipeline
);
406 * The resync callback for UP doesn't do anything other then run the test
407 * log messages. If test logging is not enabled, don't bother resetting
412 ktr_resync_callback(void *dummy __unused
)
418 if (ktr_testlogcnt
) {
424 logtest_noargs(test4
);
425 logtest_noargs(test5
);
426 logtest_noargs(test6
);
429 callout_reset(&ktr_resync_callout
, hz
/ 10, ktr_resync_callback
, NULL
);
436 * KTR_WRITE_ENTRY - Primary entry point for kernel trace logging
440 ktr_write_entry(struct ktr_info
*info
, const char *file
, int line
,
443 struct ktr_entry
*entry
;
446 cpu
= mycpu
->gd_cpuid
;
451 entry
= ktr_buf
[cpu
] + (ktr_idx
[cpu
] & KTR_ENTRIES_MASK
);
453 #ifdef _RDTSC_SUPPORTED_
454 if (cpu_feature
& CPUID_TSC
) {
456 entry
->ktr_timestamp
= rdtsc() - tsc_offsets
[cpu
];
458 entry
->ktr_timestamp
= rdtsc();
463 entry
->ktr_timestamp
= get_approximate_time_t();
465 entry
->ktr_info
= info
;
466 entry
->ktr_file
= file
;
467 entry
->ktr_line
= line
;
469 if (info
->kf_data_size
> KTR_BUFSIZE
)
470 bcopyi(ptr
, entry
->ktr_data
, KTR_BUFSIZE
);
471 else if (info
->kf_data_size
)
472 bcopyi(ptr
, entry
->ktr_data
, info
->kf_data_size
);
474 cpu_ktr_caller(entry
);
476 if (ktr_verbose
&& info
->kf_format
) {
478 kprintf("cpu%d ", cpu
);
480 if (ktr_verbose
> 1) {
481 kprintf("%s.%d\t", entry
->ktr_file
, entry
->ktr_line
);
483 kvprintf(info
->kf_format
, ptr
);
490 ktr_log(struct ktr_info
*info
, const char *file
, int line
, ...)
494 if (panicstr
== NULL
) {
495 __va_start(va
, line
);
496 ktr_write_entry(info
, file
, line
, va
);
502 ktr_log_ptr(struct ktr_info
*info
, const char *file
, int line
, const void *ptr
)
504 if (panicstr
== NULL
) {
505 ktr_write_entry(info
, file
, line
, ptr
);
511 #define NUM_LINES_PER_PAGE 19
518 static int db_ktr_verbose
;
519 static int db_mach_vtrace(int cpu
, struct ktr_entry
*kp
, int idx
);
521 DB_SHOW_COMMAND(ktr
, db_ktr_all
)
527 struct tstate tstate
[MAXCPU
];
530 for(i
= 0; i
< ncpus
; i
++) {
531 tstate
[i
].first
= -1;
532 tstate
[i
].cur
= ktr_idx
[i
] & KTR_ENTRIES_MASK
;
535 while ((c
= *(modif
++)) != '\0') {
544 while ((c
= *(modif
++)) != '\0') {
557 if (printcpu
> ncpus
- 1) {
558 db_printf("Invalid cpu number\n");
562 * Lopp throug all the buffers and print the content of them, sorted
567 u_int64_t highest_ts
;
569 struct ktr_entry
*kp
;
571 if (a_flag
== 1 && cncheckc() != -1)
576 * Find the lowest timestamp
578 for (i
= 0, counter
= 0; i
< ncpus
; i
++) {
579 if (ktr_buf
[i
] == NULL
)
581 if (printcpu
!= -1 && printcpu
!= i
)
583 if (tstate
[i
].cur
== -1) {
585 if (counter
== ncpus
) {
586 db_printf("--- End of trace buffer ---\n");
591 if (ktr_buf
[i
][tstate
[i
].cur
].ktr_timestamp
> highest_ts
) {
592 highest_ts
= ktr_buf
[i
][tstate
[i
].cur
].ktr_timestamp
;
598 kp
= &ktr_buf
[i
][tstate
[i
].cur
];
599 if (tstate
[i
].first
== -1)
600 tstate
[i
].first
= tstate
[i
].cur
;
601 if (--tstate
[i
].cur
< 0)
602 tstate
[i
].cur
= KTR_ENTRIES
- 1;
603 if (tstate
[i
].first
== tstate
[i
].cur
) {
604 db_mach_vtrace(i
, kp
, tstate
[i
].cur
+ 1);
608 if (ktr_buf
[i
][tstate
[i
].cur
].ktr_info
== NULL
)
610 if (db_more(&nl
) == -1)
612 if (db_mach_vtrace(i
, kp
, tstate
[i
].cur
+ 1) == 0)
618 db_mach_vtrace(int cpu
, struct ktr_entry
*kp
, int idx
)
620 if (kp
->ktr_info
== NULL
)
623 db_printf("cpu%d ", cpu
);
625 db_printf("%d: ", idx
);
626 if (db_ktr_verbose
) {
627 db_printf("%10.10lld %s.%d\t", (long long)kp
->ktr_timestamp
,
628 kp
->ktr_file
, kp
->ktr_line
);
630 db_printf("%s\t", kp
->ktr_info
->kf_name
);
631 db_printf("from(%p,%p) ", kp
->ktr_caller1
, kp
->ktr_caller2
);
632 if (kp
->ktr_info
->kf_format
) {
633 int32_t *args
= kp
->ktr_data
;
634 db_printf(kp
->ktr_info
->kf_format
,
635 args
[0], args
[1], args
[2], args
[3],
636 args
[4], args
[5], args
[6], args
[7],
637 args
[8], args
[9], args
[10], args
[11]);