kern - Convert aio from zalloc to objcache
[dragonfly.git] / sys / kern / kern_ktr.c
blob6d9021ac87208c0ebc685a52d10a41ed25f6800b
1 /*
2 * Copyright (c) 2005 The DragonFly Project. All rights reserved.
3 *
4 * This code is derived from software contributed to The DragonFly Project
5 * by Matthew Dillon <dillon@backplane.com>
6 *
7 * Redistribution and use in source and binary forms, with or without
8 * modification, are permitted provided that the following conditions
9 * are met:
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
16 * distribution.
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
32 * SUCH DAMAGE.
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
42 * are met:
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
62 * SUCH DAMAGE.
65 * $DragonFly: src/sys/kern/kern_ktr.c,v 1.23 2008/02/12 23:33:23 corecode Exp $
68 * Kernel tracepoint facility.
71 #include "opt_ddb.h"
72 #include "opt_ktr.h"
74 #include <sys/param.h>
75 #include <sys/cons.h>
76 #include <sys/kernel.h>
77 #include <sys/libkern.h>
78 #include <sys/proc.h>
79 #include <sys/sysctl.h>
80 #include <sys/ktr.h>
81 #include <sys/systm.h>
82 #include <sys/time.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>
94 #include <ddb/ddb.h>
96 #ifndef KTR_ENTRIES
97 #define KTR_ENTRIES 2048
98 #endif
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
108 #endif
109 KTR_INFO_MASTER(testlog);
110 #if KTR_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);
117 #ifdef SMP
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);
124 #endif
125 #define logtest(name) KTR_LOG(testlog_ ## name, 0, 0, 0, 0)
126 #define logtest_noargs(name) KTR_LOG(testlog_ ## name)
127 #endif
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, "");
145 #if KTR_TESTLOG
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;
149 #ifdef SMP
150 static int ktr_testipicnt_remainder;
151 #endif
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, "");
157 #endif
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] }
169 #ifdef SMP
170 static int64_t ktr_sync_tsc;
171 #endif
172 struct callout ktr_resync_callout;
174 #ifdef KTR_VERBOSE
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, "");
178 #endif
180 static void ktr_resync_callback(void *dummy __unused);
182 extern int64_t tsc_offsets[];
184 static void
185 ktr_sysinit(void *dummy)
187 struct ktr_cpu_core *kcpu;
188 int i;
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
205 * accurate reading.
207 * This callback occurs on cpu0.
209 #if KTR_TESTLOG
210 #ifdef SMP
211 static void ktr_pingpong_remote(void *dummy);
212 static void ktr_pipeline_remote(void *dummy);
213 #endif
214 #endif
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.
226 static
227 void
228 ktr_resync_callback(void *dummy __unused)
230 struct lwkt_cpusync cs;
231 #if KTR_TESTLOG
232 int count;
233 #endif
235 KKASSERT(mycpu->gd_cpuid == 0);
237 #if KTR_TESTLOG
239 * Test logging
241 if (ktr_testlogcnt) {
242 --ktr_testlogcnt;
243 cpu_disable_intr();
244 logtest(test1);
245 logtest(test2);
246 logtest(test3);
247 logtest_noargs(test4);
248 logtest_noargs(test5);
249 logtest_noargs(test6);
250 cpu_enable_intr();
254 * Test IPI messaging
256 if (ktr_testipicnt && ktr_testipicnt_remainder == 0 && ncpus > 1) {
257 ktr_testipicnt_remainder = ktr_testipicnt;
258 ktr_testipicnt = 0;
259 lwkt_send_ipiq_bycpu(1, ktr_pingpong_remote, NULL);
263 * Test critical sections
265 if (ktr_testcritcnt) {
266 crit_enter();
267 crit_exit();
268 logtest_noargs(crit_beg);
269 for (count = ktr_testcritcnt; count; --count) {
270 crit_enter();
271 crit_exit();
273 logtest_noargs(crit_end);
274 ktr_testcritcnt = 0;
278 * Test spinlock sections
280 if (ktr_testspincnt) {
281 struct spinlock spin;
283 spin_init(&spin);
284 spin_lock(&spin);
285 spin_unlock(&spin);
286 logtest_noargs(spin_beg);
287 for (count = ktr_testspincnt; count; --count) {
288 spin_lock(&spin);
289 spin_unlock(&spin);
291 logtest_noargs(spin_end);
292 ktr_testspincnt = 0;
294 #endif
297 * Resynchronize the TSC
299 if (ktr_resynchronize == 0)
300 goto done;
301 if ((cpu_feature & CPUID_TSC) == 0)
302 return;
304 crit_enter();
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);
310 crit_exit();
311 done:
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
319 * loop forever.
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).
324 static void
325 ktr_resync_remote(void *arg)
327 globaldata_t gd = mycpu;
328 int64_t delta;
329 int i;
331 if (gd->gd_cpuid == (int)(intptr_t)arg) {
332 for (i = 0; i < 2000; ++i)
333 ktr_sync_tsc = rdtsc();
334 } else {
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;
343 #if KTR_TESTLOG
345 static
346 void
347 ktr_pingpong_remote(void *dummy __unused)
349 int other_cpu;
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);
356 } else {
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);
365 static
366 void
367 ktr_pipeline_remote(void *dummy __unused)
369 logtest_noargs(pipeline);
372 #endif
374 #else /* !SMP */
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
379 * the callout.
381 static
382 void
383 ktr_resync_callback(void *dummy __unused)
385 #if KTR_TESTLOG
387 * Test logging
389 if (ktr_testlogcnt) {
390 --ktr_testlogcnt;
391 cpu_disable_intr();
392 logtest(test1);
393 logtest(test2);
394 logtest(test3);
395 logtest_noargs(test4);
396 logtest_noargs(test5);
397 logtest_noargs(test6);
398 cpu_enable_intr();
400 callout_reset(&ktr_resync_callout, hz / 10, ktr_resync_callback, NULL);
401 #endif
404 #endif
407 * KTR_WRITE_ENTRY - Primary entry point for kernel trace logging
410 static __inline
411 void
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;
416 int cpu;
418 cpu = mycpu->gd_cpuid;
419 kcpu = &ktr_cpu[cpu].core;
420 if (kcpu->ktr_buf == NULL)
421 return;
423 crit_enter();
424 entry = kcpu->ktr_buf + (kcpu->ktr_idx & KTR_ENTRIES_MASK);
425 ++kcpu->ktr_idx;
426 #ifdef _RDTSC_SUPPORTED_
427 if (cpu_feature & CPUID_TSC) {
428 #ifdef SMP
429 entry->ktr_timestamp = rdtsc() - tsc_offsets[cpu];
430 #else
431 entry->ktr_timestamp = rdtsc();
432 #endif
433 } else
434 #endif
436 entry->ktr_timestamp = get_approximate_time_t();
438 entry->ktr_info = info;
439 entry->ktr_file = file;
440 entry->ktr_line = line;
441 crit_exit();
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);
446 if (ktr_stacktrace)
447 cpu_ktr_caller(entry);
448 #ifdef KTR_VERBOSE
449 if (ktr_verbose && info->kf_format) {
450 #ifdef SMP
451 kprintf("cpu%d ", cpu);
452 #endif
453 if (ktr_verbose > 1) {
454 kprintf("%s.%d\t", entry->ktr_file, entry->ktr_line);
456 kvprintf(info->kf_format, va);
457 kprintf("\n");
459 #endif
462 void
463 ktr_log(struct ktr_info *info, const char *file, int line, ...)
465 __va_list va;
467 if (panicstr == NULL) {
468 __va_start(va, line);
469 ktr_write_entry(info, file, line, va);
470 __va_end(va);
474 #ifdef DDB
476 #define NUM_LINES_PER_PAGE 19
478 struct tstate {
479 int cur;
480 int first;
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;
489 int a_flag = 0;
490 int c;
491 int nl = 0;
492 int i;
493 struct tstate tstate[MAXCPU];
494 int printcpu = -1;
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;
501 db_ktr_verbose = 0;
502 while ((c = *(modif++)) != '\0') {
503 if (c == 'v') {
504 db_ktr_verbose = 1;
506 else if (c == 'a') {
507 a_flag = 1;
509 else if (c == 'c') {
510 printcpu = 0;
511 while ((c = *(modif++)) != '\0') {
512 if (isdigit(c)) {
513 printcpu *= 10;
514 printcpu += c - '0';
516 else {
517 modif++;
518 break;
521 modif--;
524 if (printcpu > ncpus - 1) {
525 db_printf("Invalid cpu number\n");
526 return;
529 * Lopp throug all the buffers and print the content of them, sorted
530 * by the timestamp.
532 while (1) {
533 int counter;
534 u_int64_t highest_ts;
535 int highest_cpu;
536 struct ktr_entry *kp;
538 if (a_flag == 1 && cncheckc() != -1)
539 return;
540 highest_ts = 0;
541 highest_cpu = -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)
548 continue;
549 if (printcpu != -1 && printcpu != i)
550 continue;
551 if (tstate[i].cur == -1) {
552 counter++;
553 if (counter == ncpus) {
554 db_printf("--- End of trace buffer ---\n");
555 return;
557 continue;
559 if (kcpu->ktr_buf[tstate[i].cur].ktr_timestamp > highest_ts) {
560 highest_ts = kcpu->ktr_buf[tstate[i].cur].ktr_timestamp;
561 highest_cpu = i;
564 if (highest_cpu < 0) {
565 db_printf("no KTR data available\n");
566 break;
568 i = highest_cpu;
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);
577 tstate[i].cur = -1;
578 continue;
580 if (kcpu->ktr_buf[tstate[i].cur].ktr_info == NULL)
581 tstate[i].cur = -1;
582 if (db_more(&nl) == -1)
583 break;
584 if (db_mach_vtrace(i, kp, tstate[i].cur + 1) == 0)
585 tstate[i].cur = -1;
589 static int
590 db_mach_vtrace(int cpu, struct ktr_entry *kp, int idx)
592 if (kp->ktr_info == NULL)
593 return(0);
594 #ifdef SMP
595 db_printf("cpu%d ", cpu);
596 #endif
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);
604 #ifdef __i386__
605 if (kp->ktr_info->kf_format)
606 db_vprintf(kp->ktr_info->kf_format, (__va_list)kp->ktr_data);
607 #endif
608 db_printf("\n");
610 return(1);
613 #endif /* DDB */