package querytracer import ( "bytes" "encoding/json" "flag" "fmt" "io" "strings" "sync/atomic" "time" "github.com/VictoriaMetrics/VictoriaMetrics/lib/buildinfo" ) 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 Done or 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 { // isDone is set to true after Done* call. // // It is used for determining whether it is safe to print the trace. // It is unsafe to print the trace when it isn't closed yet, since it may be modified // by concurrently running goroutines. // See https://github.com/VictoriaMetrics/VictoriaMetrics/issues/5319 isDone atomic.Bool // startTime is the time when Tracer was created startTime time.Time // doneTime is the time when Done or Donef was called doneTime time.Time // message is the message generated by NewChild, 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.AddJSON(). // If span is non-nil, then the remaining fields aren't used. span *span } // New creates a new instance of the tracer with the given fmt.Sprintf(format, args...) message. // // If enabled isn't set, then all function calls to the returned object will be no-op. // // Done or Donef must be called when the tracer should be finished. func New(enabled bool, format string, args ...interface{}) *Tracer { if *denyQueryTracing || !enabled { return nil } message := fmt.Sprintf(format, args...) message = buildinfo.Version + ": " + message return &Tracer{ message: message, 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 with the given fmt.Sprintf(format, args...) message. // // The returned child must be closed via Done or Donef calls. // // 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(format string, args ...interface{}) *Tracer { if t == nil { return nil } if t.isDone.Load() { panic(fmt.Errorf("BUG: NewChild() cannot be called after Donef(%q) call", t.message)) } child := &Tracer{ message: fmt.Sprintf(format, args...), startTime: time.Now(), } t.children = append(t.children, child) return child } // Done finishes t. // // Done cannot be called multiple times. // Other Tracer functions cannot be called after Done call. func (t *Tracer) Done() { if t == nil { return } if t.isDone.Load() { panic(fmt.Errorf("BUG: Donef(%q) already called", t.message)) } t.doneTime = time.Now() t.isDone.Store(true) } // Donef appends the given fmt.Sprintf(format, args..) message to t and finished it. // // 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.isDone.Load() { panic(fmt.Errorf("BUG: Donef(%q) already called", t.message)) } t.message += ": " + fmt.Sprintf(format, args...) t.doneTime = time.Now() t.isDone.Store(true) } // Printf adds new fmt.Sprintf(format, args...) message to t. // // Printf cannot be called from concurrent goroutines. func (t *Tracer) Printf(format string, args ...interface{}) { if t == nil { return } if t.isDone.Load() { 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...), } child.isDone.Store(true) 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. // // It is safe calling String() when child tracers aren't finished yet. // In this case they will contain the corresponding message. 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. // // It is safe calling ToJSON() when child tracers aren't finished yet. // In this case they will contain the corresponding message. 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.isDone.Load() { s := &span{ Message: fmt.Sprintf("missing Tracer.Done() call for the trace with message=%s", t.message), } return s, 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 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 } // span represents a single trace span type span struct { // DurationMsec is the duration for the current trace span in milliseconds. 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") }