package querytracer import ( "bytes" "encoding/json" "flag" "fmt" "io" "strings" "time" ) var denyQueryTracing = flag.Bool("denyQueryTracing", false, "Whether to disable the ability to trace queries. See https://docs.victoriametrics.com/#query-tracing") // Tracer represents query tracer. // // It must be created via New call. // Each created tracer must be finalized via Donef call. // // Tracer may contain sub-tracers (branches) in order to build tree-like execution order. // Call Tracer.NewChild func for adding sub-tracer. type Tracer struct { // startTime is the time when Tracer was created startTime time.Time // doneTime is the time when Donef was called doneTime time.Time // message is the message generated by Printf or Donef call. message string // children is a list of children Tracer objects children []*Tracer // span contains span for the given Tracer. It is added via Tracer.AddSpan(). // If span is non-nil, then the remaining fields aren't used. span *span } // New creates a new instance of the tracer. // // If enabled isn't set, then all function calls to the returned object will be no-op. // // Donef must be called when the tracer should be finished. func New(enabled bool) *Tracer { if *denyQueryTracing || !enabled { return nil } return &Tracer{ startTime: time.Now(), } } // Enabled returns true if the t is enabled. func (t *Tracer) Enabled() bool { return t != nil } // NewChild adds a new child Tracer to t. // // NewChild cannot be called from concurrent goroutines. // Create children tracers from a single goroutine and then pass them // to concurrent goroutines. func (t *Tracer) NewChild() *Tracer { if t == nil { return nil } if t.message != "" { panic(fmt.Errorf("BUG: NewChild() cannot be called after Donef(%q) call", t.message)) } child := &Tracer{ startTime: time.Now(), } t.children = append(t.children, child) return child } // Donef finishes t. // // Donef cannot be called multiple times. // Other Tracer functions cannot be called after Donef call. func (t *Tracer) Donef(format string, args ...interface{}) { if t == nil { return } if t.message != "" { panic(fmt.Errorf("BUG: Donef() already called with message %q", t.message)) } t.message = fmt.Sprintf(format, args...) t.doneTime = time.Now() } // Printf adds new message to t. // // Printf cannot be called from concurrent goroutines. func (t *Tracer) Printf(format string, args ...interface{}) { if t == nil { return } if t.message != "" { panic(fmt.Errorf("BUG: Printf() cannot be called after Done(%q) call", t.message)) } now := time.Now() child := &Tracer{ startTime: now, doneTime: now, message: fmt.Sprintf(format, args...), } t.children = append(t.children, child) } // AddJSON adds a sub-trace to t. // // The jsonTrace must be encoded with ToJSON. // // AddJSON cannot be called from concurrent goroutines. func (t *Tracer) AddJSON(jsonTrace []byte) error { if t == nil { return nil } if len(jsonTrace) == 0 { return nil } var s *span if err := json.Unmarshal(jsonTrace, &s); err != nil { return fmt.Errorf("cannot unmarshal json trace: %s", err) } child := &Tracer{ span: s, } t.children = append(t.children, child) return nil } // String returns string representation of t. // // String must be called when t methods aren't called by other goroutines. func (t *Tracer) String() string { if t == nil { return "" } s := t.toSpan() var bb bytes.Buffer s.writePlaintextWithIndent(&bb, 0) return bb.String() } // ToJSON returns JSON representation of t. // // ToJSON must be called when t methods aren't called by other goroutines. func (t *Tracer) ToJSON() string { if t == nil { return "" } s := t.toSpan() data, err := json.Marshal(s) if err != nil { panic(fmt.Errorf("BUG: unexpected error from json.Marshal: %w", err)) } return string(data) } func (t *Tracer) toSpan() *span { s, _ := t.toSpanInternal(time.Now()) return s } func (t *Tracer) toSpanInternal(prevTime time.Time) (*span, time.Time) { if t.span != nil { return t.span, prevTime } if t.doneTime == t.startTime { // a single-line trace d := t.startTime.Sub(prevTime) s := &span{ DurationMsec: float64(d.Microseconds()) / 1000, Message: t.message, } return s, t.doneTime } // tracer with children msg := t.message doneTime := t.doneTime if msg == "" { msg = "missing Tracer.Donef() call" doneTime = t.getLastChildDoneTime(t.startTime) } d := doneTime.Sub(t.startTime) var children []*span var sChild *span prevChildTime := t.startTime for _, child := range t.children { sChild, prevChildTime = child.toSpanInternal(prevChildTime) children = append(children, sChild) } s := &span{ DurationMsec: float64(d.Microseconds()) / 1000, Message: msg, Children: children, } return s, doneTime } func (t *Tracer) getLastChildDoneTime(defaultTime time.Time) time.Time { if len(t.children) == 0 { return defaultTime } lastChild := t.children[len(t.children)-1] return lastChild.getLastChildDoneTime(lastChild.startTime) } // span represents a single trace span type span struct { // DurationMsec is the duration for the current trace span in microseconds. DurationMsec float64 `json:"duration_msec"` // Message is a trace message Message string `json:"message"` // Children contains children spans Children []*span `json:"children,omitempty"` } func (s *span) writePlaintextWithIndent(w io.Writer, indent int) { prefix := "" for i := 0; i < indent; i++ { prefix += "| " } prefix += "- " msg := s.messageWithPrefix(prefix) fmt.Fprintf(w, "%s%.03fms: %s\n", prefix, s.DurationMsec, msg) childIndent := indent + 1 for _, sChild := range s.Children { sChild.writePlaintextWithIndent(w, childIndent) } } func (s *span) messageWithPrefix(prefix string) string { prefix = strings.Replace(prefix, "-", "|", 1) lines := strings.Split(s.Message, "\n") result := lines[:1] for i := range lines[1:] { ln := lines[i+1] if ln == "" { continue } ln = prefix + ln result = append(result, ln) } return strings.Join(result, "\n") }