github.com/newrelic/go-agent@v3.26.0+incompatible/internal/txn_trace.go (about) 1 // Copyright 2020 New Relic Corporation. All rights reserved. 2 // SPDX-License-Identifier: Apache-2.0 3 4 package internal 5 6 import ( 7 "bytes" 8 "container/heap" 9 "sort" 10 "time" 11 12 "github.com/newrelic/go-agent/internal/jsonx" 13 ) 14 15 // See https://source.datanerd.us/agents/agent-specs/blob/master/Transaction-Trace-LEGACY.md 16 17 type traceNodeHeap []traceNode 18 19 type traceNodeParams struct { 20 attributes map[SpanAttribute]jsonWriter 21 StackTrace StackTrace 22 TransactionGUID string 23 exclusiveDurationMillis *float64 24 } 25 26 type traceNode struct { 27 start segmentTime 28 stop segmentTime 29 threadID uint64 30 duration time.Duration 31 traceNodeParams 32 name string 33 } 34 35 func (h traceNodeHeap) Len() int { return len(h) } 36 func (h traceNodeHeap) Less(i, j int) bool { return h[i].duration < h[j].duration } 37 func (h traceNodeHeap) Swap(i, j int) { h[i], h[j] = h[j], h[i] } 38 39 // Push and Pop are unused: only heap.Init and heap.Fix are used. 40 func (h traceNodeHeap) Push(x interface{}) {} 41 func (h traceNodeHeap) Pop() interface{} { return nil } 42 43 // TxnTrace contains the work in progress transaction trace. 44 type TxnTrace struct { 45 Enabled bool 46 SegmentThreshold time.Duration 47 StackTraceThreshold time.Duration 48 nodes traceNodeHeap 49 maxNodes int 50 } 51 52 // getMaxNodes allows the maximum number of nodes to be overwritten for unit 53 // tests. 54 func (trace *TxnTrace) getMaxNodes() int { 55 if 0 != trace.maxNodes { 56 return trace.maxNodes 57 } 58 return maxTxnTraceNodes 59 } 60 61 // considerNode exists to prevent unnecessary calls to witnessNode: constructing 62 // the metric name and params map requires allocations. 63 func (trace *TxnTrace) considerNode(end segmentEnd) bool { 64 return trace.Enabled && (end.duration >= trace.SegmentThreshold) 65 } 66 67 func (trace *TxnTrace) witnessNode(end segmentEnd, name string, attrs spanAttributeMap, externalGUID string) { 68 node := traceNode{ 69 start: end.start, 70 stop: end.stop, 71 duration: end.duration, 72 threadID: end.threadID, 73 name: name, 74 } 75 node.attributes = attrs 76 node.TransactionGUID = externalGUID 77 if !trace.considerNode(end) { 78 return 79 } 80 if trace.nodes == nil { 81 trace.nodes = make(traceNodeHeap, 0, startingTxnTraceNodes) 82 } 83 if end.exclusive >= trace.StackTraceThreshold { 84 node.StackTrace = GetStackTrace() 85 } 86 if max := trace.getMaxNodes(); len(trace.nodes) < max { 87 trace.nodes = append(trace.nodes, node) 88 if len(trace.nodes) == max { 89 heap.Init(trace.nodes) 90 } 91 return 92 } 93 94 if node.duration <= trace.nodes[0].duration { 95 return 96 } 97 trace.nodes[0] = node 98 heap.Fix(trace.nodes, 0) 99 } 100 101 // HarvestTrace contains a finished transaction trace ready for serialization to 102 // the collector. 103 type HarvestTrace struct { 104 TxnEvent 105 Trace TxnTrace 106 } 107 108 type nodeDetails struct { 109 name string 110 relativeStart time.Duration 111 relativeStop time.Duration 112 traceNodeParams 113 } 114 115 func printNodeStart(buf *bytes.Buffer, n nodeDetails) { 116 // time.Seconds() is intentionally not used here. Millisecond 117 // precision is enough. 118 relativeStartMillis := n.relativeStart.Nanoseconds() / (1000 * 1000) 119 relativeStopMillis := n.relativeStop.Nanoseconds() / (1000 * 1000) 120 121 buf.WriteByte('[') 122 jsonx.AppendInt(buf, relativeStartMillis) 123 buf.WriteByte(',') 124 jsonx.AppendInt(buf, relativeStopMillis) 125 buf.WriteByte(',') 126 jsonx.AppendString(buf, n.name) 127 buf.WriteByte(',') 128 129 w := jsonFieldsWriter{buf: buf} 130 buf.WriteByte('{') 131 if nil != n.StackTrace { 132 w.writerField("backtrace", n.StackTrace) 133 } 134 if nil != n.exclusiveDurationMillis { 135 w.floatField("exclusive_duration_millis", *n.exclusiveDurationMillis) 136 } 137 if "" != n.TransactionGUID { 138 w.stringField("transaction_guid", n.TransactionGUID) 139 } 140 for k, v := range n.attributes { 141 w.writerField(k.String(), v) 142 } 143 buf.WriteByte('}') 144 145 buf.WriteByte(',') 146 buf.WriteByte('[') 147 } 148 149 func printChildren(buf *bytes.Buffer, traceStart time.Time, nodes sortedTraceNodes, next int, stop *segmentStamp, threadID uint64) int { 150 firstChild := true 151 for { 152 if next >= len(nodes) { 153 // No more children to print. 154 break 155 } 156 if nodes[next].threadID != threadID { 157 // The next node is not of the same thread. Due to the 158 // node sorting, all nodes of the same thread should be 159 // together. 160 break 161 } 162 if stop != nil && nodes[next].start.Stamp >= *stop { 163 // Make sure this node is a child of the parent that is 164 // being printed. 165 break 166 } 167 if firstChild { 168 firstChild = false 169 } else { 170 buf.WriteByte(',') 171 } 172 printNodeStart(buf, nodeDetails{ 173 name: nodes[next].name, 174 relativeStart: nodes[next].start.Time.Sub(traceStart), 175 relativeStop: nodes[next].stop.Time.Sub(traceStart), 176 traceNodeParams: nodes[next].traceNodeParams, 177 }) 178 next = printChildren(buf, traceStart, nodes, next+1, &nodes[next].stop.Stamp, threadID) 179 buf.WriteString("]]") 180 181 } 182 return next 183 } 184 185 type sortedTraceNodes []*traceNode 186 187 func (s sortedTraceNodes) Len() int { return len(s) } 188 func (s sortedTraceNodes) Less(i, j int) bool { 189 // threadID is the first sort key and start.Stamp is the second key. 190 if s[i].threadID == s[j].threadID { 191 return s[i].start.Stamp < s[j].start.Stamp 192 } 193 return s[i].threadID < s[j].threadID 194 } 195 func (s sortedTraceNodes) Swap(i, j int) { s[i], s[j] = s[j], s[i] } 196 197 // MarshalJSON is used for testing. 198 // 199 // TODO: Eliminate this entirely by using harvestTraces.Data(). 200 func (trace *HarvestTrace) MarshalJSON() ([]byte, error) { 201 buf := bytes.NewBuffer(make([]byte, 0, 100+100*trace.Trace.nodes.Len())) 202 203 trace.writeJSON(buf) 204 205 return buf.Bytes(), nil 206 } 207 208 func (trace *HarvestTrace) writeJSON(buf *bytes.Buffer) { 209 nodes := make(sortedTraceNodes, len(trace.Trace.nodes)) 210 for i := 0; i < len(nodes); i++ { 211 nodes[i] = &trace.Trace.nodes[i] 212 } 213 sort.Sort(nodes) 214 215 buf.WriteByte('[') // begin trace 216 217 jsonx.AppendInt(buf, trace.Start.UnixNano()/1000) 218 buf.WriteByte(',') 219 jsonx.AppendFloat(buf, trace.Duration.Seconds()*1000.0) 220 buf.WriteByte(',') 221 jsonx.AppendString(buf, trace.FinalName) 222 buf.WriteByte(',') 223 if uri, _ := trace.Attrs.GetAgentValue(attributeRequestURI, destTxnTrace); "" != uri { 224 jsonx.AppendString(buf, uri) 225 } else { 226 buf.WriteString("null") 227 } 228 buf.WriteByte(',') 229 230 buf.WriteByte('[') // begin trace data 231 232 // If the trace string pool is used, insert another array here. 233 234 jsonx.AppendFloat(buf, 0.0) // unused timestamp 235 buf.WriteByte(',') // 236 buf.WriteString("{}") // unused: formerly request parameters 237 buf.WriteByte(',') // 238 buf.WriteString("{}") // unused: formerly custom parameters 239 buf.WriteByte(',') // 240 241 printNodeStart(buf, nodeDetails{ // begin outer root 242 name: "ROOT", 243 relativeStart: 0, 244 relativeStop: trace.Duration, 245 }) 246 247 // exclusive_duration_millis field is added to fix the transaction trace 248 // summary tab. If exclusive_duration_millis is not provided, the UIs 249 // will calculate exclusive time, which doesn't work for this root node 250 // since all async goroutines are children of this root. 251 exclusiveDurationMillis := trace.Duration.Seconds() * 1000.0 252 details := nodeDetails{ // begin inner root 253 name: trace.FinalName, 254 relativeStart: 0, 255 relativeStop: trace.Duration, 256 } 257 details.exclusiveDurationMillis = &exclusiveDurationMillis 258 printNodeStart(buf, details) 259 260 for next := 0; next < len(nodes); { 261 if next > 0 { 262 buf.WriteByte(',') 263 } 264 // We put each thread's nodes into the root node instead of the 265 // node that spawned the thread. This approach is simple and 266 // works when the segment which spawned a thread has been pruned 267 // from the trace. Each call to printChildren prints one 268 // thread. 269 next = printChildren(buf, trace.Start, nodes, next, nil, nodes[next].threadID) 270 } 271 272 buf.WriteString("]]") // end outer root 273 buf.WriteString("]]") // end inner root 274 275 buf.WriteByte(',') 276 buf.WriteByte('{') 277 buf.WriteString(`"agentAttributes":`) 278 agentAttributesJSON(trace.Attrs, buf, destTxnTrace) 279 buf.WriteByte(',') 280 buf.WriteString(`"userAttributes":`) 281 userAttributesJSON(trace.Attrs, buf, destTxnTrace, nil) 282 buf.WriteByte(',') 283 buf.WriteString(`"intrinsics":`) 284 intrinsicsJSON(&trace.TxnEvent, buf) 285 buf.WriteByte('}') 286 287 // If the trace string pool is used, end another array here. 288 289 buf.WriteByte(']') // end trace data 290 291 // catGUID 292 buf.WriteByte(',') 293 if trace.CrossProcess.Used() && trace.CrossProcess.GUID != "" { 294 jsonx.AppendString(buf, trace.CrossProcess.GUID) 295 } else if trace.BetterCAT.Enabled { 296 jsonx.AppendString(buf, trace.BetterCAT.TraceID()) 297 } else { 298 buf.WriteString(`""`) 299 } 300 buf.WriteByte(',') // 301 buf.WriteString(`null`) // reserved for future use 302 buf.WriteByte(',') // 303 buf.WriteString(`false`) // ForcePersist is not yet supported 304 buf.WriteByte(',') // 305 buf.WriteString(`null`) // X-Ray sessions not supported 306 buf.WriteByte(',') // 307 308 // Synthetics are supported: 309 if trace.CrossProcess.IsSynthetics() { 310 jsonx.AppendString(buf, trace.CrossProcess.Synthetics.ResourceID) 311 } else { 312 buf.WriteString(`""`) 313 } 314 315 buf.WriteByte(']') // end trace 316 } 317 318 type txnTraceHeap []*HarvestTrace 319 320 func (h *txnTraceHeap) isEmpty() bool { 321 return 0 == len(*h) 322 } 323 324 func newTxnTraceHeap(max int) *txnTraceHeap { 325 h := make(txnTraceHeap, 0, max) 326 heap.Init(&h) 327 return &h 328 } 329 330 // Implement sort.Interface. 331 func (h txnTraceHeap) Len() int { return len(h) } 332 func (h txnTraceHeap) Less(i, j int) bool { return h[i].Duration < h[j].Duration } 333 func (h txnTraceHeap) Swap(i, j int) { h[i], h[j] = h[j], h[i] } 334 335 // Implement heap.Interface. 336 func (h *txnTraceHeap) Push(x interface{}) { *h = append(*h, x.(*HarvestTrace)) } 337 338 func (h *txnTraceHeap) Pop() interface{} { 339 old := *h 340 n := len(old) 341 x := old[n-1] 342 *h = old[0 : n-1] 343 return x 344 } 345 346 func (h *txnTraceHeap) isKeeper(t *HarvestTrace) bool { 347 if len(*h) < cap(*h) { 348 return true 349 } 350 return t.Duration >= (*h)[0].Duration 351 } 352 353 func (h *txnTraceHeap) addTxnTrace(t *HarvestTrace) { 354 if len(*h) < cap(*h) { 355 heap.Push(h, t) 356 return 357 } 358 359 if t.Duration <= (*h)[0].Duration { 360 return 361 } 362 heap.Pop(h) 363 heap.Push(h, t) 364 } 365 366 type harvestTraces struct { 367 regular *txnTraceHeap 368 synthetics *txnTraceHeap 369 } 370 371 func newHarvestTraces() *harvestTraces { 372 return &harvestTraces{ 373 regular: newTxnTraceHeap(maxRegularTraces), 374 synthetics: newTxnTraceHeap(maxSyntheticsTraces), 375 } 376 } 377 378 func (traces *harvestTraces) Len() int { 379 return traces.regular.Len() + traces.synthetics.Len() 380 } 381 382 func (traces *harvestTraces) Witness(trace HarvestTrace) { 383 traceHeap := traces.regular 384 if trace.CrossProcess.IsSynthetics() { 385 traceHeap = traces.synthetics 386 } 387 388 if traceHeap.isKeeper(&trace) { 389 cpy := new(HarvestTrace) 390 *cpy = trace 391 traceHeap.addTxnTrace(cpy) 392 } 393 } 394 395 func (traces *harvestTraces) Data(agentRunID string, harvestStart time.Time) ([]byte, error) { 396 if traces.Len() == 0 { 397 return nil, nil 398 } 399 400 // This estimate is used to guess the size of the buffer. No worries if 401 // the estimate is small since the buffer will be lengthened as 402 // necessary. This is just about minimizing reallocations. 403 estimate := 512 404 for _, t := range *traces.regular { 405 estimate += 100 * t.Trace.nodes.Len() 406 } 407 for _, t := range *traces.synthetics { 408 estimate += 100 * t.Trace.nodes.Len() 409 } 410 411 buf := bytes.NewBuffer(make([]byte, 0, estimate)) 412 buf.WriteByte('[') 413 jsonx.AppendString(buf, agentRunID) 414 buf.WriteByte(',') 415 buf.WriteByte('[') 416 417 // use a function to add traces to the buffer to avoid duplicating comma 418 // logic in both loops 419 firstTrace := true 420 addTrace := func(trace *HarvestTrace) { 421 if firstTrace { 422 firstTrace = false 423 } else { 424 buf.WriteByte(',') 425 } 426 trace.writeJSON(buf) 427 } 428 429 for _, trace := range *traces.regular { 430 addTrace(trace) 431 } 432 for _, trace := range *traces.synthetics { 433 addTrace(trace) 434 } 435 buf.WriteByte(']') 436 buf.WriteByte(']') 437 438 return buf.Bytes(), nil 439 } 440 441 func (traces *harvestTraces) slice() []*HarvestTrace { 442 out := make([]*HarvestTrace, 0, traces.Len()) 443 out = append(out, (*traces.regular)...) 444 out = append(out, (*traces.synthetics)...) 445 446 return out 447 } 448 449 func (traces *harvestTraces) MergeIntoHarvest(h *Harvest) {} 450 451 func (traces *harvestTraces) EndpointMethod() string { 452 return cmdTxnTraces 453 }