Source file
src/runtime/debuglog.go
Documentation: runtime
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16 package runtime
17
18 import (
19 "runtime/internal/atomic"
20 "unsafe"
21 )
22
23
24
25
26 const debugLogBytes = 16 << 10
27
28
29
30 const debugLogStringLimit = debugLogBytes / 8
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49 func dlog() *dlogger {
50 if !dlogEnabled {
51 return nil
52 }
53
54
55 tick, nano := uint64(cputicks()), uint64(nanotime())
56
57
58 l := getCachedDlogger()
59
60
61
62 if l == nil {
63 allp := (*uintptr)(unsafe.Pointer(&allDloggers))
64 all := (*dlogger)(unsafe.Pointer(atomic.Loaduintptr(allp)))
65 for l1 := all; l1 != nil; l1 = l1.allLink {
66 if atomic.Load(&l1.owned) == 0 && atomic.Cas(&l1.owned, 0, 1) {
67 l = l1
68 break
69 }
70 }
71 }
72
73
74 if l == nil {
75
76
77 l = (*dlogger)(sysAllocOS(unsafe.Sizeof(dlogger{})))
78 if l == nil {
79 throw("failed to allocate debug log")
80 }
81 l.w.r.data = &l.w.data
82 l.owned = 1
83
84
85 headp := (*uintptr)(unsafe.Pointer(&allDloggers))
86 for {
87 head := atomic.Loaduintptr(headp)
88 l.allLink = (*dlogger)(unsafe.Pointer(head))
89 if atomic.Casuintptr(headp, head, uintptr(unsafe.Pointer(l))) {
90 break
91 }
92 }
93 }
94
95
96
97
98 const deltaLimit = 1<<(3*7) - 1
99 if tick-l.w.tick > deltaLimit || nano-l.w.nano > deltaLimit {
100 l.w.writeSync(tick, nano)
101 }
102
103
104 l.w.ensure(debugLogHeaderSize)
105 l.w.write += debugLogHeaderSize
106
107
108 l.w.uvarint(tick - l.w.tick)
109 l.w.uvarint(nano - l.w.nano)
110 gp := getg()
111 if gp != nil && gp.m != nil && gp.m.p != 0 {
112 l.w.varint(int64(gp.m.p.ptr().id))
113 } else {
114 l.w.varint(-1)
115 }
116
117 return l
118 }
119
120
121
122
123
124
125
126 type dlogger struct {
127 w debugLogWriter
128
129
130 allLink *dlogger
131
132
133
134 owned uint32
135 }
136
137
138
139
140 var allDloggers *dlogger
141
142
143 func (l *dlogger) end() {
144 if !dlogEnabled {
145 return
146 }
147
148
149 size := l.w.write - l.w.r.end
150 if !l.w.writeFrameAt(l.w.r.end, size) {
151 throw("record too large")
152 }
153
154
155 l.w.r.end = l.w.write
156
157
158 if putCachedDlogger(l) {
159 return
160 }
161
162
163 atomic.Store(&l.owned, 0)
164 }
165
166 const (
167 debugLogUnknown = 1 + iota
168 debugLogBoolTrue
169 debugLogBoolFalse
170 debugLogInt
171 debugLogUint
172 debugLogHex
173 debugLogPtr
174 debugLogString
175 debugLogConstString
176 debugLogStringOverflow
177
178 debugLogPC
179 debugLogTraceback
180 )
181
182
183 func (l *dlogger) b(x bool) *dlogger {
184 if !dlogEnabled {
185 return l
186 }
187 if x {
188 l.w.byte(debugLogBoolTrue)
189 } else {
190 l.w.byte(debugLogBoolFalse)
191 }
192 return l
193 }
194
195
196 func (l *dlogger) i(x int) *dlogger {
197 return l.i64(int64(x))
198 }
199
200
201 func (l *dlogger) i8(x int8) *dlogger {
202 return l.i64(int64(x))
203 }
204
205
206 func (l *dlogger) i16(x int16) *dlogger {
207 return l.i64(int64(x))
208 }
209
210
211 func (l *dlogger) i32(x int32) *dlogger {
212 return l.i64(int64(x))
213 }
214
215
216 func (l *dlogger) i64(x int64) *dlogger {
217 if !dlogEnabled {
218 return l
219 }
220 l.w.byte(debugLogInt)
221 l.w.varint(x)
222 return l
223 }
224
225
226 func (l *dlogger) u(x uint) *dlogger {
227 return l.u64(uint64(x))
228 }
229
230
231 func (l *dlogger) uptr(x uintptr) *dlogger {
232 return l.u64(uint64(x))
233 }
234
235
236 func (l *dlogger) u8(x uint8) *dlogger {
237 return l.u64(uint64(x))
238 }
239
240
241 func (l *dlogger) u16(x uint16) *dlogger {
242 return l.u64(uint64(x))
243 }
244
245
246 func (l *dlogger) u32(x uint32) *dlogger {
247 return l.u64(uint64(x))
248 }
249
250
251 func (l *dlogger) u64(x uint64) *dlogger {
252 if !dlogEnabled {
253 return l
254 }
255 l.w.byte(debugLogUint)
256 l.w.uvarint(x)
257 return l
258 }
259
260
261 func (l *dlogger) hex(x uint64) *dlogger {
262 if !dlogEnabled {
263 return l
264 }
265 l.w.byte(debugLogHex)
266 l.w.uvarint(x)
267 return l
268 }
269
270
271 func (l *dlogger) p(x any) *dlogger {
272 if !dlogEnabled {
273 return l
274 }
275 l.w.byte(debugLogPtr)
276 if x == nil {
277 l.w.uvarint(0)
278 } else {
279 v := efaceOf(&x)
280 switch v._type.kind & kindMask {
281 case kindChan, kindFunc, kindMap, kindPtr, kindUnsafePointer:
282 l.w.uvarint(uint64(uintptr(v.data)))
283 default:
284 throw("not a pointer type")
285 }
286 }
287 return l
288 }
289
290
291 func (l *dlogger) s(x string) *dlogger {
292 if !dlogEnabled {
293 return l
294 }
295 str := stringStructOf(&x)
296 datap := &firstmoduledata
297 if len(x) > 4 && datap.etext <= uintptr(str.str) && uintptr(str.str) < datap.end {
298
299
300
301 l.w.byte(debugLogConstString)
302 l.w.uvarint(uint64(str.len))
303 l.w.uvarint(uint64(uintptr(str.str) - datap.etext))
304 } else {
305 l.w.byte(debugLogString)
306 var b []byte
307 bb := (*slice)(unsafe.Pointer(&b))
308 bb.array = str.str
309 bb.len, bb.cap = str.len, str.len
310 if len(b) > debugLogStringLimit {
311 b = b[:debugLogStringLimit]
312 }
313 l.w.uvarint(uint64(len(b)))
314 l.w.bytes(b)
315 if len(b) != len(x) {
316 l.w.byte(debugLogStringOverflow)
317 l.w.uvarint(uint64(len(x) - len(b)))
318 }
319 }
320 return l
321 }
322
323
324 func (l *dlogger) pc(x uintptr) *dlogger {
325 if !dlogEnabled {
326 return l
327 }
328 l.w.byte(debugLogPC)
329 l.w.uvarint(uint64(x))
330 return l
331 }
332
333
334 func (l *dlogger) traceback(x []uintptr) *dlogger {
335 if !dlogEnabled {
336 return l
337 }
338 l.w.byte(debugLogTraceback)
339 l.w.uvarint(uint64(len(x)))
340 for _, pc := range x {
341 l.w.uvarint(uint64(pc))
342 }
343 return l
344 }
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361 type debugLogWriter struct {
362 write uint64
363 data debugLogBuf
364
365
366
367 tick, nano uint64
368
369
370
371
372 r debugLogReader
373
374
375
376 buf [10]byte
377 }
378
379
380 type debugLogBuf [debugLogBytes]byte
381
382 const (
383
384
385 debugLogHeaderSize = 2
386
387
388 debugLogSyncSize = debugLogHeaderSize + 2*8
389 )
390
391
392 func (l *debugLogWriter) ensure(n uint64) {
393 for l.write+n >= l.r.begin+uint64(len(l.data)) {
394
395 if l.r.skip() == ^uint64(0) {
396
397
398
399
400
401
402 throw("record wrapped around")
403 }
404 }
405 }
406
407
408 func (l *debugLogWriter) writeFrameAt(pos, size uint64) bool {
409 l.data[pos%uint64(len(l.data))] = uint8(size)
410 l.data[(pos+1)%uint64(len(l.data))] = uint8(size >> 8)
411 return size <= 0xFFFF
412 }
413
414
415 func (l *debugLogWriter) writeSync(tick, nano uint64) {
416 l.tick, l.nano = tick, nano
417 l.ensure(debugLogHeaderSize)
418 l.writeFrameAt(l.write, 0)
419 l.write += debugLogHeaderSize
420 l.writeUint64LE(tick)
421 l.writeUint64LE(nano)
422 l.r.end = l.write
423 }
424
425
426 func (l *debugLogWriter) writeUint64LE(x uint64) {
427 var b [8]byte
428 b[0] = byte(x)
429 b[1] = byte(x >> 8)
430 b[2] = byte(x >> 16)
431 b[3] = byte(x >> 24)
432 b[4] = byte(x >> 32)
433 b[5] = byte(x >> 40)
434 b[6] = byte(x >> 48)
435 b[7] = byte(x >> 56)
436 l.bytes(b[:])
437 }
438
439
440 func (l *debugLogWriter) byte(x byte) {
441 l.ensure(1)
442 pos := l.write
443 l.write++
444 l.data[pos%uint64(len(l.data))] = x
445 }
446
447
448 func (l *debugLogWriter) bytes(x []byte) {
449 l.ensure(uint64(len(x)))
450 pos := l.write
451 l.write += uint64(len(x))
452 for len(x) > 0 {
453 n := copy(l.data[pos%uint64(len(l.data)):], x)
454 pos += uint64(n)
455 x = x[n:]
456 }
457 }
458
459
460 func (l *debugLogWriter) varint(x int64) {
461 var u uint64
462 if x < 0 {
463 u = (^uint64(x) << 1) | 1
464 } else {
465 u = (uint64(x) << 1)
466 }
467 l.uvarint(u)
468 }
469
470
471 func (l *debugLogWriter) uvarint(u uint64) {
472 i := 0
473 for u >= 0x80 {
474 l.buf[i] = byte(u) | 0x80
475 u >>= 7
476 i++
477 }
478 l.buf[i] = byte(u)
479 i++
480 l.bytes(l.buf[:i])
481 }
482
483 type debugLogReader struct {
484 data *debugLogBuf
485
486
487
488 begin, end uint64
489
490
491 tick, nano uint64
492 }
493
494
495 func (r *debugLogReader) skip() uint64 {
496
497 if r.begin+debugLogHeaderSize > r.end {
498 return ^uint64(0)
499 }
500 size := uint64(r.readUint16LEAt(r.begin))
501 if size == 0 {
502
503 r.tick = r.readUint64LEAt(r.begin + debugLogHeaderSize)
504 r.nano = r.readUint64LEAt(r.begin + debugLogHeaderSize + 8)
505 size = debugLogSyncSize
506 }
507 if r.begin+size > r.end {
508 return ^uint64(0)
509 }
510 r.begin += size
511 return size
512 }
513
514
515 func (r *debugLogReader) readUint16LEAt(pos uint64) uint16 {
516 return uint16(r.data[pos%uint64(len(r.data))]) |
517 uint16(r.data[(pos+1)%uint64(len(r.data))])<<8
518 }
519
520
521 func (r *debugLogReader) readUint64LEAt(pos uint64) uint64 {
522 var b [8]byte
523 for i := range b {
524 b[i] = r.data[pos%uint64(len(r.data))]
525 pos++
526 }
527 return uint64(b[0]) | uint64(b[1])<<8 |
528 uint64(b[2])<<16 | uint64(b[3])<<24 |
529 uint64(b[4])<<32 | uint64(b[5])<<40 |
530 uint64(b[6])<<48 | uint64(b[7])<<56
531 }
532
533 func (r *debugLogReader) peek() (tick uint64) {
534
535 size := uint64(0)
536 for size == 0 {
537 if r.begin+debugLogHeaderSize > r.end {
538 return ^uint64(0)
539 }
540 size = uint64(r.readUint16LEAt(r.begin))
541 if size != 0 {
542 break
543 }
544 if r.begin+debugLogSyncSize > r.end {
545 return ^uint64(0)
546 }
547
548 r.tick = r.readUint64LEAt(r.begin + debugLogHeaderSize)
549 r.nano = r.readUint64LEAt(r.begin + debugLogHeaderSize + 8)
550 r.begin += debugLogSyncSize
551 }
552
553
554 if r.begin+size > r.end {
555 return ^uint64(0)
556 }
557 pos := r.begin + debugLogHeaderSize
558 var u uint64
559 for i := uint(0); ; i += 7 {
560 b := r.data[pos%uint64(len(r.data))]
561 pos++
562 u |= uint64(b&^0x80) << i
563 if b&0x80 == 0 {
564 break
565 }
566 }
567 if pos > r.begin+size {
568 return ^uint64(0)
569 }
570 return r.tick + u
571 }
572
573 func (r *debugLogReader) header() (end, tick, nano uint64, p int) {
574
575
576 size := uint64(r.readUint16LEAt(r.begin))
577 end = r.begin + size
578 r.begin += debugLogHeaderSize
579
580
581 tick = r.uvarint() + r.tick
582 nano = r.uvarint() + r.nano
583 p = int(r.varint())
584
585 return
586 }
587
588 func (r *debugLogReader) uvarint() uint64 {
589 var u uint64
590 for i := uint(0); ; i += 7 {
591 b := r.data[r.begin%uint64(len(r.data))]
592 r.begin++
593 u |= uint64(b&^0x80) << i
594 if b&0x80 == 0 {
595 break
596 }
597 }
598 return u
599 }
600
601 func (r *debugLogReader) varint() int64 {
602 u := r.uvarint()
603 var v int64
604 if u&1 == 0 {
605 v = int64(u >> 1)
606 } else {
607 v = ^int64(u >> 1)
608 }
609 return v
610 }
611
612 func (r *debugLogReader) printVal() bool {
613 typ := r.data[r.begin%uint64(len(r.data))]
614 r.begin++
615
616 switch typ {
617 default:
618 print("<unknown field type ", hex(typ), " pos ", r.begin-1, " end ", r.end, ">\n")
619 return false
620
621 case debugLogUnknown:
622 print("<unknown kind>")
623
624 case debugLogBoolTrue:
625 print(true)
626
627 case debugLogBoolFalse:
628 print(false)
629
630 case debugLogInt:
631 print(r.varint())
632
633 case debugLogUint:
634 print(r.uvarint())
635
636 case debugLogHex, debugLogPtr:
637 print(hex(r.uvarint()))
638
639 case debugLogString:
640 sl := r.uvarint()
641 if r.begin+sl > r.end {
642 r.begin = r.end
643 print("<string length corrupted>")
644 break
645 }
646 for sl > 0 {
647 b := r.data[r.begin%uint64(len(r.data)):]
648 if uint64(len(b)) > sl {
649 b = b[:sl]
650 }
651 r.begin += uint64(len(b))
652 sl -= uint64(len(b))
653 gwrite(b)
654 }
655
656 case debugLogConstString:
657 len, ptr := int(r.uvarint()), uintptr(r.uvarint())
658 ptr += firstmoduledata.etext
659 str := stringStruct{
660 str: unsafe.Pointer(ptr),
661 len: len,
662 }
663 s := *(*string)(unsafe.Pointer(&str))
664 print(s)
665
666 case debugLogStringOverflow:
667 print("..(", r.uvarint(), " more bytes)..")
668
669 case debugLogPC:
670 printDebugLogPC(uintptr(r.uvarint()), false)
671
672 case debugLogTraceback:
673 n := int(r.uvarint())
674 for i := 0; i < n; i++ {
675 print("\n\t")
676
677
678
679
680 printDebugLogPC(uintptr(r.uvarint()), true)
681 }
682 }
683
684 return true
685 }
686
687
688 func printDebugLog() {
689 if !dlogEnabled {
690 return
691 }
692
693
694
695
696 printlock()
697
698
699 allp := (*uintptr)(unsafe.Pointer(&allDloggers))
700 all := (*dlogger)(unsafe.Pointer(atomic.Loaduintptr(allp)))
701
702
703 n := 0
704 for l := all; l != nil; l = l.allLink {
705 n++
706 }
707 if n == 0 {
708 printunlock()
709 return
710 }
711
712
713 type readState struct {
714 debugLogReader
715 first bool
716 lost uint64
717 nextTick uint64
718 }
719
720
721 state1 := sysAllocOS(unsafe.Sizeof(readState{}) * uintptr(n))
722 if state1 == nil {
723 println("failed to allocate read state for", n, "logs")
724 printunlock()
725 return
726 }
727 state := (*[1 << 20]readState)(state1)[:n]
728 {
729 l := all
730 for i := range state {
731 s := &state[i]
732 s.debugLogReader = l.w.r
733 s.first = true
734 s.lost = l.w.r.begin
735 s.nextTick = s.peek()
736 l = l.allLink
737 }
738 }
739
740
741 for {
742
743 var best struct {
744 tick uint64
745 i int
746 }
747 best.tick = ^uint64(0)
748 for i := range state {
749 if state[i].nextTick < best.tick {
750 best.tick = state[i].nextTick
751 best.i = i
752 }
753 }
754 if best.tick == ^uint64(0) {
755 break
756 }
757
758
759 s := &state[best.i]
760 if s.first {
761 print(">> begin log ", best.i)
762 if s.lost != 0 {
763 print("; lost first ", s.lost>>10, "KB")
764 }
765 print(" <<\n")
766 s.first = false
767 }
768
769 end, _, nano, p := s.header()
770 oldEnd := s.end
771 s.end = end
772
773 print("[")
774 var tmpbuf [21]byte
775 pnano := int64(nano) - runtimeInitTime
776 if pnano < 0 {
777
778 pnano = 0
779 }
780 pnanoBytes := itoaDiv(tmpbuf[:], uint64(pnano), 9)
781 print(slicebytetostringtmp((*byte)(noescape(unsafe.Pointer(&pnanoBytes[0]))), len(pnanoBytes)))
782 print(" P ", p, "] ")
783
784 for i := 0; s.begin < s.end; i++ {
785 if i > 0 {
786 print(" ")
787 }
788 if !s.printVal() {
789
790 print("<aborting P log>")
791 end = oldEnd
792 break
793 }
794 }
795 println()
796
797
798 s.begin = end
799 s.end = oldEnd
800 s.nextTick = s.peek()
801 }
802
803 printunlock()
804 }
805
806
807
808 func printDebugLogPC(pc uintptr, returnPC bool) {
809 fn := findfunc(pc)
810 if returnPC && (!fn.valid() || pc > fn.entry()) {
811
812
813 pc--
814 }
815
816 print(hex(pc))
817 if !fn.valid() {
818 print(" [unknown PC]")
819 } else {
820 name := funcname(fn)
821 file, line := funcline(fn, pc)
822 print(" [", name, "+", hex(pc-fn.entry()),
823 " ", file, ":", line, "]")
824 }
825 }
826
View as plain text