github.com/waldiirawan/apm-agent-go/v2@v2.2.2/span_test.go (about) 1 // Licensed to Elasticsearch B.V. under one or more contributor 2 // license agreements. See the NOTICE file distributed with 3 // this work for additional information regarding copyright 4 // ownership. Elasticsearch B.V. licenses this file to you under 5 // the Apache License, Version 2.0 (the "License"); you may 6 // not use this file except in compliance with the License. 7 // You may obtain a copy of the License at 8 // 9 // http://www.apache.org/licenses/LICENSE-2.0 10 // 11 // Unless required by applicable law or agreed to in writing, 12 // software distributed under the License is distributed on an 13 // "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY 14 // KIND, either express or implied. See the License for the 15 // specific language governing permissions and limitations 16 // under the License. 17 18 package apm_test 19 20 import ( 21 "context" 22 "fmt" 23 "os" 24 "sort" 25 "sync" 26 "testing" 27 "time" 28 29 "github.com/pkg/errors" 30 "github.com/stretchr/testify/assert" 31 "github.com/stretchr/testify/require" 32 33 "github.com/waldiirawan/apm-agent-go/v2" 34 "github.com/waldiirawan/apm-agent-go/v2/apmtest" 35 "github.com/waldiirawan/apm-agent-go/v2/model" 36 "github.com/waldiirawan/apm-agent-go/v2/transport/transporttest" 37 ) 38 39 func TestStartSpanTransactionNotSampled(t *testing.T) { 40 tracer, _ := apm.NewTracer("tracer_testing", "") 41 defer tracer.Close() 42 // sample nothing 43 tracer.SetSampler(apm.NewRatioSampler(0)) 44 45 tx := tracer.StartTransaction("name", "type") 46 assert.False(t, tx.Sampled()) 47 span := tx.StartSpan("name", "type", nil) 48 assert.True(t, span.Dropped()) 49 } 50 51 func TestTracerStartSpan(t *testing.T) { 52 tracer, r := transporttest.NewRecorderTracer() 53 defer tracer.Close() 54 55 txTimestamp := time.Now() 56 tx := tracer.StartTransactionOptions("name", "type", apm.TransactionOptions{ 57 Start: txTimestamp, 58 }) 59 txTraceContext := tx.TraceContext() 60 span0 := tx.StartSpan("name", "type", nil) 61 span0TraceContext := span0.TraceContext() 62 span0.End() 63 tx.End() 64 65 // Even if the transaction and parent span have been ended, 66 // it is possible to report a span with their IDs. 67 tracer.StartSpan("name", "type", 68 txTraceContext.Span, 69 apm.SpanOptions{ 70 Parent: span0TraceContext, 71 Start: txTimestamp.Add(time.Second), 72 }, 73 ).End() 74 75 tracer.Flush(nil) 76 payloads := r.Payloads() 77 assert.Len(t, payloads.Transactions, 1) 78 assert.Len(t, payloads.Spans, 2) 79 80 assert.Equal(t, payloads.Transactions[0].ID, payloads.Spans[0].ParentID) 81 assert.Equal(t, payloads.Spans[0].ID, payloads.Spans[1].ParentID) 82 for _, span := range payloads.Spans { 83 assert.Equal(t, payloads.Transactions[0].TraceID, span.TraceID) 84 assert.Equal(t, payloads.Transactions[0].ID, span.TransactionID) 85 } 86 assert.NotZero(t, payloads.Spans[1].ID) 87 88 assert.Equal(t, time.Time(payloads.Transactions[0].Timestamp).Add(time.Second), time.Time(payloads.Spans[1].Timestamp)) 89 90 // The span created after the transaction (obviously?) 91 // doesn't get included in the transaction's span count. 92 assert.Equal(t, 1, payloads.Transactions[0].SpanCount.Started) 93 } 94 95 func TestSpanParentID(t *testing.T) { 96 tracer := apmtest.NewRecordingTracer() 97 defer tracer.Close() 98 99 tx := tracer.StartTransaction("name", "type") 100 span := tx.StartSpan("name", "type", nil) 101 traceContext := tx.TraceContext() 102 parentID := span.ParentID() 103 104 span.End() 105 tx.End() 106 // Assert that the parentID is not empty when the span hasn't been ended. 107 // And that the Span's parentID equals the traceContext Span. 108 assert.NotEqual(t, parentID, apm.SpanID{}) 109 assert.Equal(t, traceContext.Span, parentID) 110 111 // Assert that the parentID is not empty after the span has ended. 112 assert.NotZero(t, span.ParentID()) 113 assert.Equal(t, traceContext.Span, span.ParentID()) 114 115 tracer.Flush(nil) 116 payloads := tracer.Payloads() 117 require.Len(t, payloads.Spans, 1) 118 assert.Equal(t, model.SpanID(parentID), payloads.Spans[0].ParentID) 119 } 120 121 func TestSpanEnsureType(t *testing.T) { 122 tracer := apmtest.NewRecordingTracer() 123 defer tracer.Close() 124 125 tx := tracer.StartTransaction("name", "type") 126 span := tx.StartSpan("name", "", nil) 127 span.End() 128 tx.End() 129 tracer.Flush(nil) 130 131 payloads := tracer.Payloads() 132 require.Len(t, payloads.Spans, 1) 133 134 assert.Equal(t, "custom", payloads.Spans[0].Type) 135 } 136 137 func TestSpanLink(t *testing.T) { 138 tracer := apmtest.NewRecordingTracer() 139 defer tracer.Close() 140 141 links := []apm.SpanLink{ 142 {Trace: apm.TraceID{1}, Span: apm.SpanID{1}}, 143 {Trace: apm.TraceID{2}, Span: apm.SpanID{2}}, 144 } 145 146 tx := tracer.StartTransaction("name", "type") 147 span := tx.StartSpanOptions("name", "type", apm.SpanOptions{ 148 Links: links, 149 }) 150 151 span.End() 152 tx.End() 153 154 tracer.Flush(nil) 155 156 payloads := tracer.Payloads() 157 require.Len(t, payloads.Spans, 1) 158 require.Len(t, payloads.Spans[0].Links, len(links)) 159 160 // Assert span links are identical. 161 expectedLinks := []model.SpanLink{ 162 {TraceID: model.TraceID{1}, SpanID: model.SpanID{1}}, 163 {TraceID: model.TraceID{2}, SpanID: model.SpanID{2}}, 164 } 165 assert.Equal(t, expectedLinks, payloads.Spans[0].Links) 166 } 167 168 func TestSpanTiming(t *testing.T) { 169 var spanStart, spanEnd time.Time 170 txStart := time.Now() 171 tx, spans, _ := apmtest.WithTransactionOptions( 172 apm.TransactionOptions{Start: txStart}, 173 func(ctx context.Context) { 174 time.Sleep(500 * time.Millisecond) 175 span, _ := apm.StartSpan(ctx, "name", "type") 176 spanStart = time.Now() 177 time.Sleep(500 * time.Millisecond) 178 spanEnd = time.Now() 179 span.End() 180 }, 181 ) 182 require.Len(t, spans, 1) 183 span := spans[0] 184 185 assert.InEpsilon(t, 186 spanStart.Sub(txStart), 187 time.Time(span.Timestamp).Sub(time.Time(tx.Timestamp)), 188 0.1, // 10% error 189 ) 190 assert.InEpsilon(t, 191 spanEnd.Sub(spanStart)/time.Millisecond, 192 span.Duration, 193 0.1, // 10% error 194 ) 195 } 196 197 func TestSpanType(t *testing.T) { 198 spanTypes := []string{"type", "type.subtype", "type.subtype.action", "type.subtype.action.figure"} 199 _, spans, _ := apmtest.WithTransaction(func(ctx context.Context) { 200 for _, spanType := range spanTypes { 201 span, _ := apm.StartSpan(ctx, "name", spanType) 202 span.End() 203 } 204 }) 205 require.Len(t, spans, 4) 206 207 check := func(s model.Span, spanType, spanSubtype, spanAction string) { 208 assert.Equal(t, spanType, s.Type) 209 assert.Equal(t, spanSubtype, s.Subtype) 210 assert.Equal(t, spanAction, s.Action) 211 } 212 check(spans[0], "type", "", "") 213 check(spans[1], "type", "subtype", "") 214 check(spans[2], "type", "subtype", "action") 215 check(spans[3], "type", "subtype", "action.figure") 216 } 217 218 func TestStartExitSpan(t *testing.T) { 219 _, spans, _ := apmtest.WithTransaction(func(ctx context.Context) { 220 span, _ := apm.StartSpanOptions(ctx, "name", "type", apm.SpanOptions{ExitSpan: true}) 221 span.Duration = 2 * time.Millisecond 222 assert.True(t, span.IsExitSpan()) 223 span.End() 224 }) 225 require.Len(t, spans, 1) 226 // When the context's DestinationService is not explicitly set, ending 227 // the exit span will assign the value. 228 assert.Equal(t, spans[0].Context.Destination.Service.Resource, "type") 229 230 // When the context's ServiceTarget is not explicitly set, ending 231 // the exit span will assign the value. 232 assert.Equal(t, spans[0].Context.Service.Target.Type, "type") 233 234 tracer := apmtest.NewRecordingTracer() 235 defer tracer.Close() 236 237 tx := tracer.StartTransaction("name", "type") 238 239 span := tx.StartSpanOptions("name", "type", apm.SpanOptions{ExitSpan: true}) 240 assert.True(t, span.IsExitSpan()) 241 242 // when the parent span is an exit span, children with a different type or 243 // subtype should be noops. 244 span2 := tx.StartSpan("name", "differenttype", span) 245 span2.End() 246 assert.True(t, span2.Dropped()) 247 248 // Exit spans MAY have child spans that have the same `type` and `subtype`. 249 span3 := tx.StartSpan("name", "type", span) 250 span3.End() 251 assert.False(t, span3.Dropped()) 252 253 span.End() 254 255 // Spans should still be marked as an exit span after they've been 256 // ended. 257 assert.True(t, span.IsExitSpan()) 258 259 // Even ended exit spans MAY have child spans that have the same 260 // `type` and `subtype`. 261 span4 := tx.StartSpan("name", "type", span) 262 span4.End() 263 assert.False(t, span4.Dropped()) 264 } 265 266 func TestSpanStackTraceMinDurationSpecialCases(t *testing.T) { 267 tracer := apmtest.NewRecordingTracer() 268 269 // verify that no stacktraces are recorded 270 tracer.SetSpanStackTraceMinDuration(-1) 271 tx := tracer.StartTransaction("name", "type") 272 span := tx.StartSpan("span", "span", nil) 273 span.End() 274 tx.End() 275 276 tracer.Flush(nil) 277 tracer.Close() 278 279 spans := tracer.Payloads().Spans 280 require.Len(t, spans, 1) 281 assert.Len(t, spans[0].Stacktrace, 0) 282 283 // verify that stacktraces are always recorded 284 tracer = apmtest.NewRecordingTracer() 285 defer tracer.Close() 286 tracer.SetSpanStackTraceMinDuration(0) 287 tx = tracer.StartTransaction("name", "type") 288 span = tx.StartSpan("span2", "span2", nil) 289 span.End() 290 tx.End() 291 292 tracer.Flush(nil) 293 294 spans = tracer.Payloads().Spans 295 require.Len(t, spans, 1) 296 assert.NotEmpty(t, spans[0].Stacktrace) 297 } 298 299 func TestCompressSpanNonSiblings(t *testing.T) { 300 // Asserts that non sibling spans are not compressed. 301 tracer := apmtest.NewRecordingTracer() 302 defer tracer.Close() 303 304 tracer.SetSpanCompressionEnabled(true) 305 // Avoid the spans from being dropped by fast exit spans. 306 tracer.SetExitSpanMinDuration(time.Nanosecond) 307 308 tx := tracer.StartTransaction("name", "type") 309 parent := tx.StartSpan("parent", "parent", nil) 310 311 createSpans := []struct { 312 name, typ string 313 parent apm.TraceContext 314 }{ 315 {name: "not compressed", typ: "internal", parent: parent.TraceContext()}, 316 {name: "not compressed", typ: "internal", parent: tx.TraceContext()}, 317 {name: "compressed", typ: "internal", parent: parent.TraceContext()}, 318 {name: "compressed", typ: "internal", parent: parent.TraceContext()}, 319 {name: "compressed", typ: "different", parent: tx.TraceContext()}, 320 {name: "compressed", typ: "different", parent: tx.TraceContext()}, 321 } 322 for _, span := range createSpans { 323 span := tx.StartSpanOptions(span.name, span.typ, apm.SpanOptions{ 324 ExitSpan: true, Parent: span.parent, 325 }) 326 span.Duration = time.Millisecond 327 span.End() 328 } 329 330 parent.End() 331 tx.End() 332 tracer.Flush(nil) 333 334 spans := tracer.Payloads().Spans 335 require.Len(t, spans, 5) 336 337 // First two spans should not have been compressed together. 338 require.Nil(t, spans[0].Composite) 339 require.Nil(t, spans[1].Composite) 340 341 assert.NotNil(t, spans[2].Composite) 342 assert.Equal(t, 2, spans[2].Composite.Count) 343 assert.Equal(t, float64(2), spans[2].Composite.Sum) 344 assert.Equal(t, "exact_match", spans[2].Composite.CompressionStrategy) 345 346 assert.NotNil(t, spans[3].Composite) 347 assert.Equal(t, 2, spans[3].Composite.Count) 348 assert.Equal(t, float64(2), spans[3].Composite.Sum) 349 assert.Equal(t, "exact_match", spans[3].Composite.CompressionStrategy) 350 } 351 352 func TestCompressSpanExactMatch(t *testing.T) { 353 // Aserts that that span compression works on compressable spans with 354 // "exact_match" strategy. 355 tests := []struct { 356 setup func(t *testing.T) func() 357 assertFunc func(t *testing.T, tx model.Transaction, spans []model.Span) 358 name string 359 compressionEnabled bool 360 }{ 361 // |______________transaction (095b51e1b6ca784c) - 2.0013ms_______________| 362 // m 363 // m 364 // m 365 // m 366 // m 367 // m 368 // m 369 // m 370 // m 371 // m 372 // |___________________mysql SELECT * FROM users - 2ms____________________| 373 // r 374 // i 375 // r 376 { 377 name: "CompressFalse", 378 compressionEnabled: false, 379 assertFunc: func(t *testing.T, tx model.Transaction, spans []model.Span) { 380 require.NotEmpty(t, tx) 381 require.Equal(t, 14, len(spans)) 382 for _, span := range spans { 383 require.Nil(t, span.Composite) 384 } 385 }, 386 }, 387 // |______________transaction (7d3254511f02b26b) - 2.0013ms_______________| 388 // 10 389 // |___________________mysql SELECT * FROM users - 2ms___________________| 390 // r 391 // i 392 // r 393 { 394 name: "CompressTrueSettingTweak", 395 compressionEnabled: true, 396 setup: func(*testing.T) func() { 397 // This setting 398 envVarName := "ELASTIC_APM_SPAN_COMPRESSION_EXACT_MATCH_MAX_DURATION" 399 og := os.Getenv(envVarName) 400 os.Setenv(envVarName, "1ms") 401 return func() { os.Setenv(envVarName, og) } 402 }, 403 assertFunc: func(t *testing.T, tx model.Transaction, spans []model.Span) { 404 require.NotNil(t, tx) 405 require.Equal(t, 5, len(spans)) 406 composite := spans[0] 407 require.NotNil(t, composite.Composite) 408 assert.Equal(t, "SELECT * FROM users", composite.Name) 409 assert.Equal(t, "exact_match", composite.Composite.CompressionStrategy) 410 assert.Equal(t, composite.Composite.Count, 10) 411 assert.Equal(t, 0.001, composite.Composite.Sum) 412 assert.Equal(t, 0.001, composite.Duration) 413 414 for _, span := range spans[1:] { 415 require.Nil(t, span.Composite) 416 } 417 }, 418 }, 419 // |______________transaction (5797fe58c6ccce29) - 2.0013ms_______________| 420 // |_____________________11 Calls to mysql - 2.001ms______________________| 421 // r 422 // i 423 // r 424 { 425 name: "CompressSpanCount4", 426 compressionEnabled: true, 427 assertFunc: func(t *testing.T, tx model.Transaction, spans []model.Span) { 428 require.NotEmpty(t, tx) 429 var composite = spans[0] 430 assert.Equal(t, composite.Context.Destination.Service.Resource, "mysql") 431 432 require.NotNil(t, composite.Composite) 433 assert.Equal(t, "SELECT * FROM users", composite.Name) 434 assert.Equal(t, composite.Composite.Count, 11) 435 assert.Equal(t, "exact_match", composite.Composite.CompressionStrategy) 436 // Sum should be at least the time that each span ran for. The 437 // model time is in Milliseconds and the span duration should be 438 // at least 2 Milliseconds 439 assert.Equal(t, int(composite.Composite.Sum), 2) 440 assert.Equal(t, int(composite.Duration), 2) 441 442 for _, span := range spans { 443 if span.Type == "mysql" { 444 continue 445 } 446 assert.Nil(t, span.Composite) 447 } 448 }, 449 }, 450 } 451 for _, test := range tests { 452 t.Run(test.name, func(t *testing.T) { 453 if test.setup != nil { 454 defer test.setup(t)() 455 } 456 457 tracer := apmtest.NewRecordingTracer() 458 tracer.SetExitSpanMinDuration(time.Nanosecond) 459 defer tracer.Close() 460 tracer.SetSpanCompressionEnabled(test.compressionEnabled) 461 462 // When compression is enabled: 463 // Compress 10 spans into 1 and add another span with a different type 464 // [ Transaction ] 465 // [ mysql (11) ] [ request ] [ internal ] [ request ] 466 // 467 txStart := time.Now() 468 tx := tracer.StartTransactionOptions("name", "type", 469 apm.TransactionOptions{Start: txStart}, 470 ) 471 currentTime := txStart 472 for i := 0; i < 10; i++ { 473 span := tx.StartSpanOptions("SELECT * FROM users", "mysql", apm.SpanOptions{ 474 ExitSpan: true, Start: currentTime, 475 }) 476 span.Duration = 100 * time.Nanosecond 477 currentTime = currentTime.Add(span.Duration) 478 span.End() 479 } 480 // Compressed when the exact_match threshold is >= 2ms. 481 { 482 span := tx.StartSpanOptions("SELECT * FROM users", "mysql", apm.SpanOptions{ 483 ExitSpan: true, Start: currentTime, 484 }) 485 span.Duration = 2 * time.Millisecond 486 currentTime = currentTime.Add(span.Duration) 487 span.End() 488 } 489 490 // None of these should be added to the composite. 491 { 492 span := tx.StartSpanOptions("GET /", "request", apm.SpanOptions{ 493 ExitSpan: true, Start: currentTime, 494 }) 495 span.Duration = 100 * time.Nanosecond 496 currentTime = currentTime.Add(span.Duration) 497 span.End() 498 } 499 { 500 // Not an exit span, should not be compressed 501 span := tx.StartSpanOptions("calculate complex", "internal", apm.SpanOptions{ 502 Start: currentTime, 503 }) 504 span.Duration = 100 * time.Nanosecond 505 currentTime = currentTime.Add(span.Duration) 506 span.End() 507 } 508 { 509 // Exit span, this is a good candidate to be compressed, but 510 // since it can't be compressed with the last request type ("internal") 511 span := tx.StartSpanOptions("GET /", "request", apm.SpanOptions{ 512 ExitSpan: true, Start: currentTime, 513 }) 514 span.Duration = 100 * time.Nanosecond 515 currentTime = currentTime.Add(span.Duration) 516 span.End() 517 } 518 tx.Duration = currentTime.Sub(txStart) 519 tx.End() 520 tracer.Flush(nil) 521 522 transaction := tracer.Payloads().Transactions[0] 523 spans := tracer.Payloads().Spans 524 defer func() { 525 if t.Failed() { 526 apmtest.WriteTraceWaterfall(os.Stdout, transaction, spans) 527 apmtest.WriteTraceTable(os.Stdout, transaction, spans) 528 } 529 }() 530 531 if test.assertFunc != nil { 532 test.assertFunc(t, transaction, spans) 533 } 534 }) 535 } 536 } 537 538 func TestCompressSpanName(t *testing.T) { 539 type testcase struct { 540 name string 541 serviceTargetName string 542 serviceTargetType string 543 expectedName string 544 } 545 testcases := []testcase{{ 546 name: "unknown", 547 expectedName: "Calls to unknown", 548 }, { 549 name: "unknown type", 550 serviceTargetName: "foo", 551 // service target type is inferred so the expected name is type/name 552 expectedName: "Calls to request/foo", 553 }, { 554 name: "unknown name", 555 serviceTargetType: "bar", 556 expectedName: "Calls to bar", 557 }, { 558 name: "known", 559 serviceTargetName: "foo", 560 serviceTargetType: "bar", 561 expectedName: "Calls to bar/foo", 562 }} 563 for _, tc := range testcases { 564 t.Run(tc.name, func(t *testing.T) { 565 tracer := apmtest.NewRecordingTracer() 566 t.Cleanup(tracer.Close) 567 568 tracer.SetSpanCompressionEnabled(true) 569 tracer.SetSpanCompressionSameKindMaxDuration(5 * time.Second) 570 // Don't drop fast exit spans. 571 tracer.SetExitSpanMinDuration(0) 572 573 txStart := time.Now() 574 tx := tracer.StartTransactionOptions("name", "type", 575 apm.TransactionOptions{ 576 Start: txStart, 577 }, 578 ) 579 currentTime := txStart 580 581 // These should be compressed into 1 since they meet the compression 582 // criteria. 583 path := []string{"/a", "/b", "/c", "/d", "/e"} 584 for i := 0; i < len(path); i++ { 585 span := tx.StartSpanOptions(fmt.Sprint("GET ", path[i]), "request", apm.SpanOptions{ 586 ExitSpan: true, Start: currentTime, 587 }) 588 span.Duration = 100 * time.Nanosecond 589 currentTime = currentTime.Add(span.Duration) 590 span.Context.SetServiceTarget(apm.ServiceTargetSpanContext{ 591 Type: tc.serviceTargetType, 592 Name: tc.serviceTargetName, 593 }) 594 span.End() 595 } 596 597 tx.Duration = currentTime.Sub(txStart) 598 tx.End() 599 tracer.Flush(nil) 600 601 transaction := tracer.Payloads().Transactions[0] 602 spans := tracer.Payloads().Spans 603 604 t.Cleanup(func() { 605 if t.Failed() { 606 apmtest.WriteTraceWaterfall(os.Stdout, transaction, spans) 607 apmtest.WriteTraceTable(os.Stdout, transaction, spans) 608 } 609 }) 610 611 require.Equal(t, 1, len(spans)) 612 requestSpan := spans[0] 613 assert.NotNil(t, requestSpan.Composite) 614 assert.Equal(t, 5, requestSpan.Composite.Count) 615 assert.Equal(t, tc.expectedName, requestSpan.Name) 616 assert.Equal(t, "same_kind", requestSpan.Composite.CompressionStrategy) 617 }) 618 } 619 } 620 621 func TestCompressSpanSameKind(t *testing.T) { 622 // Aserts that that span compression works on compressable spans with 623 // "same_kind" strategy, and that different span types are not compressed. 624 testCase := func(tracer *apmtest.RecordingTracer) (model.Transaction, []model.Span, func()) { 625 txStart := time.Now() 626 tx := tracer.StartTransactionOptions("name", "type", 627 apm.TransactionOptions{Start: txStart}, 628 ) 629 currentTime := txStart 630 631 // Span is compressable, but cannot be compressed since the next span 632 // is not the same kind. It's published. 633 { 634 span := tx.StartSpanOptions("SELECT * FROM users", "mysql", apm.SpanOptions{ 635 ExitSpan: true, Start: currentTime, 636 }) 637 span.Duration = 100 * time.Nanosecond 638 currentTime = currentTime.Add(span.Duration) 639 span.End() 640 } 641 // These should be compressed into 1 since they meet the compression 642 // criteria. 643 path := []string{"/a", "/b", "/c", "/d", "/e"} 644 for i := 0; i < len(path); i++ { 645 span := tx.StartSpanOptions(fmt.Sprint("GET ", path[i]), "request", apm.SpanOptions{ 646 ExitSpan: true, Start: currentTime, 647 }) 648 span.Duration = 100 * time.Nanosecond 649 currentTime = currentTime.Add(span.Duration) 650 span.End() 651 } 652 // This span exceeds the default threshold (5ms) and won't be compressed. 653 { 654 span := tx.StartSpanOptions("GET /f", "request", apm.SpanOptions{ 655 ExitSpan: true, Start: currentTime, 656 }) 657 span.Duration = 6 * time.Millisecond 658 currentTime = currentTime.Add(span.Duration) 659 span.End() 660 } 661 // Span is compressable and the next span is the same kind, but cannot be compressed 662 // since the service target fields are different (inferred by the db instance). 663 { 664 span := tx.StartSpanOptions("SELECT * FROM users", "mysql", apm.SpanOptions{ 665 ExitSpan: true, Start: currentTime, 666 }) 667 span.Duration = 100 * time.Nanosecond 668 span.Context.SetServiceTarget(apm.ServiceTargetSpanContext{ 669 Type: "db", 670 Name: "foo", 671 }) 672 currentTime = currentTime.Add(span.Duration) 673 span.End() 674 } 675 { 676 span := tx.StartSpanOptions("SELECT * FROM users", "mysql", apm.SpanOptions{ 677 ExitSpan: true, Start: currentTime, 678 }) 679 span.Duration = 100 * time.Nanosecond 680 span.Context.SetServiceTarget(apm.ServiceTargetSpanContext{ 681 Type: "db", 682 Name: "bar", 683 }) 684 currentTime = currentTime.Add(span.Duration) 685 span.End() 686 } 687 tx.Duration = currentTime.Sub(txStart) 688 tx.End() 689 tracer.Flush(nil) 690 691 transaction := tracer.Payloads().Transactions[0] 692 spans := tracer.Payloads().Spans 693 debugFunc := func() { 694 if t.Failed() { 695 apmtest.WriteTraceWaterfall(os.Stdout, transaction, spans) 696 apmtest.WriteTraceTable(os.Stdout, transaction, spans) 697 } 698 } 699 return transaction, spans, debugFunc 700 } 701 702 t.Run("DefaultDisabled", func(t *testing.T) { 703 // By default same kind compression is disabled thus count will be 7. 704 tracer := apmtest.NewRecordingTracer() 705 defer tracer.Close() 706 tracer.SetSpanCompressionEnabled(true) 707 // Don't drop fast exit spans. 708 tracer.SetExitSpanMinDuration(0) 709 710 _, spans, debugFunc := testCase(tracer) 711 defer debugFunc() 712 713 require.Equal(t, 9, len(spans)) 714 mysqlSpan := spans[0] 715 assert.Equal(t, "mysql", mysqlSpan.Context.Destination.Service.Resource) 716 assert.Nil(t, mysqlSpan.Composite) 717 718 requestSpan := spans[1] 719 assert.Equal(t, "request", requestSpan.Context.Destination.Service.Resource) 720 require.Nil(t, requestSpan.Composite) 721 }) 722 723 t.Run("10msThreshold", func(t *testing.T) { 724 // With this threshold the composite count will be 6. 725 os.Setenv("ELASTIC_APM_SPAN_COMPRESSION_SAME_KIND_MAX_DURATION", "10ms") 726 defer os.Unsetenv("ELASTIC_APM_SPAN_COMPRESSION_SAME_KIND_MAX_DURATION") 727 728 tracer := apmtest.NewRecordingTracer() 729 defer tracer.Close() 730 tracer.SetSpanCompressionEnabled(true) 731 // Don't drop fast exit spans. 732 tracer.SetExitSpanMinDuration(0) 733 734 _, spans, debugFunc := testCase(tracer) 735 defer debugFunc() 736 737 mysqlSpan := spans[0] 738 assert.Equal(t, mysqlSpan.Context.Destination.Service.Resource, "mysql") 739 assert.Nil(t, mysqlSpan.Composite) 740 741 requestSpan := spans[1] 742 assert.Equal(t, requestSpan.Context.Destination.Service.Resource, "request") 743 assert.NotNil(t, requestSpan.Composite) 744 assert.Equal(t, 6, requestSpan.Composite.Count) 745 assert.Equal(t, "Calls to request", requestSpan.Name) 746 assert.Equal(t, "same_kind", requestSpan.Composite.CompressionStrategy) 747 // Check that the aggregate sum is at least the duration of the time we 748 // we waited for. 749 assert.Greater(t, requestSpan.Composite.Sum, float64(5*100/time.Millisecond)) 750 751 // Check that the total composite span duration is at least 5 milliseconds. 752 assert.Greater(t, requestSpan.Duration, float64(5*100/time.Millisecond)) 753 }) 754 t.Run("DefaultThresholdDropFastExitSpan", func(t *testing.T) { 755 tracer := apmtest.NewRecordingTracer() 756 defer tracer.Close() 757 tracer.SetSpanCompressionEnabled(true) 758 759 tx, spans, debugFunc := testCase(tracer) 760 defer debugFunc() 761 762 // drops all spans except the last request span. 763 require.Equal(t, 1, len(spans)) 764 // Collects statistics about the dropped spans (request and mysql). 765 require.Equal(t, 4, len(tx.DroppedSpansStats)) 766 }) 767 } 768 769 func TestCompressSpanSameKindParentSpan(t *testing.T) { 770 // This test asserts the span compression works when the spans are children 771 // of another span. 772 tracer := apmtest.NewRecordingTracer() 773 tracer.SetSpanCompressionEnabled(true) 774 tracer.SetExitSpanMinDuration(0) 775 tracer.SetSpanCompressionSameKindMaxDuration(5 * time.Millisecond) 776 777 // This test case covers spans that have other spans as parents. 778 // |_______________transaction (6b1e4866252dea6f) - 1.45ms________________| 779 // |__internal internal op - 700µs___| 780 // |request GET /r| 781 // |request G| 782 // |___internal another op - 750µs____| 783 // |2 Calls to re| 784 txStart := time.Now() 785 tx := tracer.StartTransactionOptions("name", "type", 786 apm.TransactionOptions{Start: txStart}, 787 ) 788 789 ctx := apm.ContextWithTransaction(context.Background(), tx) 790 currentTime := txStart 791 { 792 // Doesn't compress any spans since none meet the necessary conditions 793 // the "request" type are both the same type but the parent 794 parent, ctx := apm.StartSpanOptions(ctx, "internal op", "internal", apm.SpanOptions{ 795 Start: currentTime, 796 }) 797 // Have span propagate context downstream, this should not allow for 798 // compression 799 child, ctx := apm.StartSpanOptions(ctx, "GET /resource", "request", apm.SpanOptions{ 800 Start: currentTime.Add(100 * time.Microsecond), 801 }) 802 803 grandChild, _ := apm.StartSpanOptions(ctx, "GET /different", "request", apm.SpanOptions{ 804 ExitSpan: true, 805 Start: currentTime.Add(120 * time.Microsecond), 806 }) 807 808 grandChild.Duration = 200 * time.Microsecond 809 grandChild.End() 810 811 child.Duration = 300 * time.Microsecond 812 child.End() 813 814 parent.Duration = 700 * time.Microsecond 815 currentTime = currentTime.Add(parent.Duration) 816 parent.End() 817 } 818 { 819 // Compresses the last two spans together since they are both exit 820 // spans, same "request" type, don't propagate ctx and succeed. 821 parent, ctx := apm.StartSpanOptions(ctx, "another op", "internal", apm.SpanOptions{ 822 Start: currentTime.Add(50 * time.Microsecond), 823 }) 824 child, _ := apm.StartSpanOptions(ctx, "GET /res", "request", apm.SpanOptions{ 825 ExitSpan: true, 826 Start: currentTime.Add(120 * time.Microsecond), 827 }) 828 829 otherChild, _ := apm.StartSpanOptions(ctx, "GET /diff", "request", apm.SpanOptions{ 830 ExitSpan: true, 831 Start: currentTime.Add(150 * time.Microsecond), 832 }) 833 834 otherChild.Duration = 250 * time.Microsecond 835 otherChild.End() 836 837 child.Duration = 300 * time.Microsecond 838 child.End() 839 840 parent.Duration = 750 * time.Microsecond 841 currentTime = currentTime.Add(parent.Duration) 842 parent.End() 843 } 844 845 tx.Duration = currentTime.Sub(txStart) 846 tx.End() 847 tracer.Flush(nil) 848 849 transaction := tracer.Payloads().Transactions[0] 850 spans := tracer.Payloads().Spans 851 852 defer func() { 853 if t.Failed() { 854 apmtest.WriteTraceTable(os.Stdout, transaction, spans) 855 apmtest.WriteTraceWaterfall(os.Stdout, transaction, spans) 856 } 857 }() 858 require.NotNil(t, transaction) 859 assert.Equal(t, 5, len(spans)) 860 861 compositeSpan := spans[3] 862 compositeParent := spans[4] 863 require.NotNil(t, compositeSpan) 864 require.NotNil(t, compositeSpan.Composite) 865 assert.Equal(t, "Calls to request", compositeSpan.Name) 866 assert.Equal(t, "request", compositeSpan.Type) 867 assert.Equal(t, "internal", compositeParent.Type) 868 assert.Equal(t, compositeSpan.Composite.Count, 2) 869 assert.Equal(t, compositeSpan.ParentID, compositeParent.ID) 870 assert.GreaterOrEqual(t, compositeParent.Duration, compositeSpan.Duration) 871 } 872 873 func TestCompressSpanSameKindParentSpanContext(t *testing.T) { 874 // This test ensures that the compression also works when the s.Parent is 875 // set (via the context.Context). 876 // |________________transaction (6df3948c6eff7b57) - 15ms_________________| 877 // |_____________________internal parent - 14ms______________________| 878 // |_3 db - 3ms__| 879 // |_internal algorithm - 6ms__| 880 // |2 Calls to client | 881 // |inte| 882 tracer := apmtest.NewRecordingTracer() 883 tracer.SetSpanCompressionEnabled(true) 884 tracer.SetExitSpanMinDuration(0) 885 tracer.SetSpanCompressionSameKindMaxDuration(5 * time.Millisecond) 886 887 txStart := time.Now() 888 tx := tracer.StartTransactionOptions("name", "type", 889 apm.TransactionOptions{Start: txStart}, 890 ) 891 892 ctx := apm.ContextWithTransaction(context.Background(), tx) 893 parentStart := txStart.Add(time.Millisecond) 894 parent, ctx := apm.StartSpanOptions(ctx, "parent", "internal", apm.SpanOptions{ 895 Start: parentStart, 896 }) 897 898 // These spans are all compressed into a composite. 899 childrenStart := parentStart.Add(2 * time.Millisecond) 900 for i := 0; i < 3; i++ { 901 span, _ := apm.StartSpanOptions(ctx, "db", "redis", apm.SpanOptions{ 902 ExitSpan: true, 903 Start: childrenStart, 904 }) 905 childrenStart = childrenStart.Add(time.Millisecond) 906 span.Duration = time.Millisecond 907 span.End() 908 } 909 910 // We create a nother "internal" type span from which 3 children (below) 911 // are created. one of them 912 testSpans := []struct { 913 name string 914 typ string 915 duration time.Duration 916 }{ 917 {name: "GET /some", typ: "client", duration: time.Millisecond}, 918 {name: "GET /resource", typ: "client", duration: 2 * time.Millisecond}, 919 {name: "compute something", typ: "internal", duration: time.Millisecond}, 920 } 921 922 subParent, ctx := apm.StartSpanOptions(ctx, "algorithm", "internal", apm.SpanOptions{ 923 Start: childrenStart.Add(time.Millisecond), 924 }) 925 childrenStart = childrenStart.Add(time.Millisecond) 926 for _, childCfg := range testSpans { 927 child, _ := apm.StartSpanOptions(ctx, childCfg.name, childCfg.typ, apm.SpanOptions{ 928 ExitSpan: true, 929 Start: childrenStart.Add(childCfg.duration), 930 }) 931 childrenStart = childrenStart.Add(childCfg.duration) 932 child.Duration = childCfg.duration 933 child.End() 934 } 935 childrenStart = childrenStart.Add(time.Millisecond) 936 subParent.Duration = 6 * time.Millisecond 937 subParent.End() 938 939 parent.Duration = childrenStart.Add(2 * time.Millisecond).Sub(txStart) 940 parent.End() 941 tx.Duration = 15 * time.Millisecond 942 tx.End() 943 944 tracer.Flush(nil) 945 946 transaction := tracer.Payloads().Transactions[0] 947 spans := tracer.Payloads().Spans 948 949 defer func() { 950 if t.Failed() { 951 apmtest.WriteTraceTable(os.Stdout, transaction, spans) 952 apmtest.WriteTraceWaterfall(os.Stdout, transaction, spans) 953 } 954 }() 955 require.NotNil(t, transaction) 956 assert.Equal(t, 5, len(spans)) 957 958 sort.SliceStable(spans, func(i, j int) bool { 959 return time.Time(spans[i].Timestamp).Before(time.Time(spans[j].Timestamp)) 960 }) 961 962 redisSpan := spans[1] 963 require.NotNil(t, redisSpan.Composite) 964 assert.Equal(t, "db", redisSpan.Name) 965 assert.Equal(t, 3, redisSpan.Composite.Count) 966 assert.Equal(t, float64(3), redisSpan.Composite.Sum) 967 assert.Equal(t, "exact_match", redisSpan.Composite.CompressionStrategy) 968 969 clientSpan := spans[3] 970 require.NotNil(t, clientSpan.Composite) 971 assert.Equal(t, "Calls to client", clientSpan.Name) 972 assert.Equal(t, clientSpan.ParentID, spans[2].ID) 973 assert.Equal(t, 2, clientSpan.Composite.Count) 974 assert.Equal(t, float64(3), clientSpan.Composite.Sum) 975 assert.Equal(t, "same_kind", clientSpan.Composite.CompressionStrategy) 976 } 977 978 func TestCompressSpanSameKindConcurrent(t *testing.T) { 979 // This test verifies there aren't any deadlocks on calling 980 // span.End(), Parent.End() and tx.End(). 981 // Additionally, ensures that we're not leaking or losing any 982 // spans on parents and transaction being ended early. 983 tracer := apmtest.NewRecordingTracer() 984 tracer.SetSpanCompressionEnabled(true) 985 tracer.SetExitSpanMinDuration(0) 986 987 tx := tracer.StartTransaction("name", "type") 988 ctx := apm.ContextWithTransaction(context.Background(), tx) 989 parent, ctx := apm.StartSpan(ctx, "parent", "internal") 990 991 var wg sync.WaitGroup 992 count := 100 993 wg.Add(count) 994 spanStarted := make(chan struct{}) 995 for i := 0; i < count; i++ { 996 go func(i int) { 997 child, _ := apm.StartSpanOptions(ctx, fmt.Sprint(i), "request", apm.SpanOptions{ 998 ExitSpan: true, 999 }) 1000 spanStarted <- struct{}{} 1001 child.End() 1002 wg.Done() 1003 }(i) 1004 } 1005 1006 var received int 1007 for range spanStarted { 1008 received++ 1009 if received >= 30 { 1010 tx.End() 1011 } 1012 if received >= 50 { 1013 parent.End() 1014 } 1015 if received == count { 1016 close(spanStarted) 1017 } 1018 } 1019 // Wait until all the spans have ended. 1020 wg.Wait() 1021 1022 tracer.Flush(nil) 1023 payloads := tracer.Payloads() 1024 require.Len(t, payloads.Transactions, 1) 1025 defer func() { 1026 if t.Failed() { 1027 apmtest.WriteTraceTable(os.Stdout, payloads.Transactions[0], payloads.Spans) 1028 apmtest.WriteTraceWaterfall(os.Stdout, payloads.Transactions[0], payloads.Spans) 1029 } 1030 }() 1031 1032 var spanCount int 1033 for _, span := range payloads.Spans { 1034 if span.Composite != nil { 1035 // The real span count is the composite count. 1036 spanCount += span.Composite.Count 1037 continue 1038 } 1039 // If it's a normal span, then increment by 1. 1040 spanCount++ 1041 } 1042 1043 // Asserts that the total spancount is 101, (100 generated spans + parent). 1044 assert.Equal(t, 101, spanCount) 1045 } 1046 1047 func TestCompressSpanPrematureEnd(t *testing.T) { 1048 // This test cases assert that the cached spans are sent when the span or 1049 // tx that holds their cache is ended and the cache isn't lost. 1050 type expect struct { 1051 compressionStrategy string 1052 compositeSum float64 1053 spanCount int 1054 compositeCount int 1055 } 1056 assertResult := func(t *testing.T, tx model.Transaction, spans []model.Span, expect expect) { 1057 defer func() { 1058 if t.Failed() { 1059 apmtest.WriteTraceTable(os.Stdout, tx, spans) 1060 apmtest.WriteTraceWaterfall(os.Stdout, tx, spans) 1061 } 1062 }() 1063 assert.Equal(t, expect.spanCount, len(spans)) 1064 var composite *model.CompositeSpan 1065 for _, span := range spans { 1066 if span.Composite != nil { 1067 assert.Equal(t, expect.compositeCount, span.Composite.Count) 1068 assert.Equal(t, expect.compressionStrategy, span.Composite.CompressionStrategy) 1069 assert.Equal(t, expect.compositeSum, span.Composite.Sum) 1070 composite = span.Composite 1071 } 1072 } 1073 if expect.compositeCount > 0 { 1074 require.NotNil(t, composite) 1075 } 1076 } 1077 1078 testCases := []struct { 1079 name string 1080 exitSpanMinDuration time.Duration 1081 expect expect 1082 droppedSpansStats int 1083 }{ 1084 { 1085 name: "NoDropExitSpans", 1086 expect: expect{ 1087 spanCount: 3, 1088 compositeCount: 3, 1089 compressionStrategy: "same_kind", 1090 compositeSum: 1.5, 1091 }, 1092 }, 1093 { 1094 name: "DropExitSpans", 1095 exitSpanMinDuration: time.Millisecond, 1096 droppedSpansStats: 1, 1097 expect: expect{ 1098 spanCount: 2, 1099 compositeCount: 3, 1100 compressionStrategy: "same_kind", 1101 compositeSum: 1.5, 1102 }, 1103 }, 1104 } 1105 1106 // 1. The parent ends before they do. 1107 // The parent holds the compression cache in this test case. 1108 // | tx | 1109 // | parent | <--- The parent ends before the children ends. 1110 // | child | <--- compressed 1111 // | child | <--- compressed 1112 // | child | <--- compressed 1113 // | child | <--- NOT compressed 1114 // The expected result are 3 spans, the cache is invalidated and the span 1115 // ended after the parent ends. 1116 // 1117 // When drop fast exit spans is enabled, with 1ms min duration, the expected 1118 // span count is 2 (parent and the a composite which duration exceeds 1ms). 1119 // | tx | 1120 // | parent | <--- The parent ends before the children ends. 1121 // | child | <--- compressed 1122 // | child | <--- compressed 1123 // | child | <--- compressed 1124 // | child | <--- discarded since its duration is < than min exit. 1125 for _, test := range testCases { 1126 t.Run("ParentContext/"+test.name, func(t *testing.T) { 1127 tracer := apmtest.NewRecordingTracer() 1128 defer tracer.Close() 1129 tracer.SetSpanCompressionEnabled(true) 1130 tracer.SetExitSpanMinDuration(test.exitSpanMinDuration) 1131 tracer.SetSpanCompressionSameKindMaxDuration(5 * time.Millisecond) 1132 1133 txStart := time.Now() 1134 tx := tracer.StartTransaction("name", "type") 1135 ctx := apm.ContextWithTransaction(context.Background(), tx) 1136 currentTime := time.Now() 1137 parent, ctx := apm.StartSpanOptions(ctx, "parent", "internal", apm.SpanOptions{ 1138 Start: currentTime, 1139 }) 1140 for i := 0; i < 4; i++ { 1141 child, _ := apm.StartSpanOptions(ctx, fmt.Sprint(i), "type", apm.SpanOptions{ 1142 Parent: parent.TraceContext(), 1143 ExitSpan: true, 1144 Start: currentTime, 1145 }) 1146 child.Duration = 500 * time.Microsecond 1147 currentTime = currentTime.Add(time.Millisecond) 1148 child.End() 1149 if i == 2 { 1150 parent.Duration = 2 * time.Millisecond 1151 parent.End() 1152 } 1153 } 1154 tx.Duration = currentTime.Sub(txStart) 1155 tx.End() 1156 tracer.Flush(nil) 1157 1158 assertResult(t, 1159 tracer.Payloads().Transactions[0], tracer.Payloads().Spans, test.expect, 1160 ) 1161 1162 assert.Len(t, 1163 tracer.Payloads().Transactions[0].DroppedSpansStats, 1164 test.droppedSpansStats, 1165 ) 1166 }) 1167 } 1168 1169 // 2. The tx ends before the parent ends. 1170 // The tx holds the compression cache in this test case. 1171 // | tx | <--- The TX ends before parent. 1172 // | parent | 1173 // | child | <--- compressed 1174 // | child | <--- compressed 1175 // The expected result are 3 spans, the cache is invalidated and the span 1176 // ended after the parent ends. 1177 t.Run("TxEndBefore", func(t *testing.T) { 1178 tracer := apmtest.NewRecordingTracer() 1179 defer tracer.Close() 1180 tracer.SetSpanCompressionEnabled(true) 1181 tracer.SetExitSpanMinDuration(time.Nanosecond) 1182 tracer.SetSpanCompressionSameKindMaxDuration(5 * time.Millisecond) 1183 1184 tx := tracer.StartTransaction("name", "type") 1185 ctx := apm.ContextWithTransaction(context.Background(), tx) 1186 1187 parent, ctx := apm.StartSpan(ctx, "parent", "internal") 1188 for i := 0; i < 2; i++ { 1189 child, _ := apm.StartSpanOptions(ctx, fmt.Sprint(i), "type", apm.SpanOptions{ 1190 ExitSpan: true, 1191 }) 1192 child.Duration = time.Microsecond 1193 child.End() 1194 } 1195 tx.End() 1196 parent.End() 1197 tracer.Flush(nil) 1198 assertResult(t, tracer.Payloads().Transactions[0], tracer.Payloads().Spans, expect{ 1199 spanCount: 2, 1200 compositeCount: 2, 1201 compressionStrategy: "same_kind", 1202 compositeSum: 0.002, 1203 }) 1204 }) 1205 1206 // 2. The parent ends before the last of the children span are finished. 1207 // The tx holds the compression cache in this test case. 1208 // | tx | 1209 // | parent | <--- The parent ends before the last child ends. 1210 // | child | <--- compressed 1211 // | child | <--- compressed 1212 // | child | <--- NOT compressed 1213 t.Run("ParentFromTx", func(t *testing.T) { 1214 tracer := apmtest.NewRecordingTracer() 1215 defer tracer.Close() 1216 tracer.SetSpanCompressionEnabled(true) 1217 tracer.SetExitSpanMinDuration(time.Nanosecond) 1218 tracer.SetSpanCompressionSameKindMaxDuration(5 * time.Millisecond) 1219 1220 tx := tracer.StartTransaction("name", "type") 1221 parent := tx.StartSpan("parent", "internal", nil) 1222 for i := 0; i < 3; i++ { 1223 child := tx.StartSpanOptions(fmt.Sprint(i), "type", apm.SpanOptions{ 1224 Parent: parent.TraceContext(), 1225 ExitSpan: true, 1226 }) 1227 child.Duration = time.Microsecond 1228 child.End() 1229 if i == 1 { 1230 parent.End() 1231 } 1232 } 1233 tx.End() 1234 tracer.Flush(nil) 1235 assertResult(t, tracer.Payloads().Transactions[0], tracer.Payloads().Spans, expect{ 1236 spanCount: 3, 1237 compositeCount: 2, 1238 compressionStrategy: "same_kind", 1239 compositeSum: 0.002, 1240 }) 1241 }) 1242 } 1243 1244 func TestExitSpanDoesNotOverwriteDestinationServiceResource(t *testing.T) { 1245 _, spans, _ := apmtest.WithTransaction(func(ctx context.Context) { 1246 span, _ := apm.StartSpanOptions(ctx, "name", "type", apm.SpanOptions{ExitSpan: true}) 1247 assert.True(t, span.IsExitSpan()) 1248 span.Context.SetDestinationService(apm.DestinationServiceSpanContext{ 1249 Resource: "my-custom-resource", 1250 }) 1251 span.Duration = 2 * time.Millisecond 1252 span.End() 1253 }) 1254 require.Len(t, spans, 1) 1255 assert.Equal(t, spans[0].Context.Destination.Service.Resource, "my-custom-resource") 1256 } 1257 1258 func TestExitSpanDoesNotOverwriteServiceTarget(t *testing.T) { 1259 _, spans, _ := apmtest.WithTransaction(func(ctx context.Context) { 1260 span, _ := apm.StartSpanOptions(ctx, "name", "type", apm.SpanOptions{ExitSpan: true}) 1261 assert.True(t, span.IsExitSpan()) 1262 span.Context.SetServiceTarget(apm.ServiceTargetSpanContext{ 1263 Type: "my-custom-resource", 1264 Name: "foo", 1265 }) 1266 span.Duration = 2 * time.Millisecond 1267 span.End() 1268 }) 1269 require.Len(t, spans, 1) 1270 assert.Equal(t, spans[0].Context.Service.Target.Type, "my-custom-resource") 1271 assert.Equal(t, spans[0].Context.Service.Target.Name, "foo") 1272 } 1273 1274 func TestExitSpanDisableInferTarget(t *testing.T) { 1275 _, spans, _ := apmtest.WithTransaction(func(ctx context.Context) { 1276 span, _ := apm.StartSpanOptions(ctx, "name", "type", apm.SpanOptions{ExitSpan: true}) 1277 assert.True(t, span.IsExitSpan()) 1278 span.Context.SetDatabase(apm.DatabaseSpanContext{ 1279 Type: "mysql", 1280 Instance: "foo", 1281 }) 1282 span.Context.SetServiceTarget(apm.ServiceTargetSpanContext{}) 1283 span.Duration = 2 * time.Millisecond 1284 span.End() 1285 }) 1286 require.Len(t, spans, 1) 1287 assert.Empty(t, spans[0].Context.Service.Target.Type) 1288 assert.Empty(t, spans[0].Context.Service.Target.Name) 1289 } 1290 1291 func TestExitSpanInferTarget(t *testing.T) { 1292 _, spans, _ := apmtest.WithTransaction(func(ctx context.Context) { 1293 span, _ := apm.StartSpanOptions(ctx, "name", "type", apm.SpanOptions{ExitSpan: true}) 1294 assert.True(t, span.IsExitSpan()) 1295 span.Context.SetDatabase(apm.DatabaseSpanContext{ 1296 Type: "mysql", 1297 Instance: "foo", 1298 }) 1299 span.Duration = 2 * time.Millisecond 1300 span.End() 1301 }) 1302 require.Len(t, spans, 1) 1303 assert.Equal(t, spans[0].Context.Service.Target.Type, "type") 1304 assert.Equal(t, spans[0].Context.Service.Target.Name, "foo") 1305 } 1306 1307 func TestExitSpanInferTargetWithName(t *testing.T) { 1308 _, spans, _ := apmtest.WithTransaction(func(ctx context.Context) { 1309 span, _ := apm.StartSpanOptions(ctx, "name", "type", apm.SpanOptions{ExitSpan: true}) 1310 assert.True(t, span.IsExitSpan()) 1311 span.Context.SetDatabase(apm.DatabaseSpanContext{ 1312 Type: "mysql", 1313 Instance: "foo", 1314 }) 1315 span.Context.SetServiceTarget(apm.ServiceTargetSpanContext{ 1316 Name: "bar", 1317 }) 1318 span.Duration = 2 * time.Millisecond 1319 span.End() 1320 }) 1321 require.Len(t, spans, 1) 1322 assert.Equal(t, spans[0].Context.Service.Target.Type, "type") 1323 assert.Equal(t, spans[0].Context.Service.Target.Name, "bar") 1324 } 1325 1326 func TestTracerStartSpanIDSpecified(t *testing.T) { 1327 spanID := apm.SpanID{0, 1, 2, 3, 4, 5, 6, 7} 1328 _, spans, _ := apmtest.WithTransaction(func(ctx context.Context) { 1329 span, _ := apm.StartSpanOptions(ctx, "name", "type", apm.SpanOptions{SpanID: spanID}) 1330 span.End() 1331 }) 1332 require.Len(t, spans, 1) 1333 assert.Equal(t, model.SpanID(spanID), spans[0].ID) 1334 } 1335 1336 func TestSpanSampleRate(t *testing.T) { 1337 tracer := apmtest.NewRecordingTracer() 1338 defer tracer.Close() 1339 tracer.SetSampler(apm.NewRatioSampler(0.55555)) 1340 1341 tx := tracer.StartTransactionOptions("name", "type", apm.TransactionOptions{ 1342 // Use a known transaction ID for deterministic sampling. 1343 TransactionID: apm.SpanID{1, 2, 3, 4, 5, 6, 7, 8}, 1344 }) 1345 s1 := tx.StartSpan("name", "type", nil) 1346 s2 := tx.StartSpan("name", "type", s1) 1347 s2.End() 1348 s1.End() 1349 tx.End() 1350 tracer.Flush(nil) 1351 1352 payloads := tracer.Payloads() 1353 assert.Equal(t, 0.5556, *payloads.Transactions[0].SampleRate) 1354 assert.Equal(t, 0.5556, *payloads.Spans[0].SampleRate) 1355 assert.Equal(t, 0.5556, *payloads.Spans[1].SampleRate) 1356 } 1357 1358 func TestSpanFastExit(t *testing.T) { 1359 type expect struct { 1360 spans int 1361 droppedSpansStatsCount int 1362 } 1363 tests := []struct { 1364 expect expect 1365 setup func() func() 1366 name string 1367 }{ 1368 { 1369 name: "DefaultSetting/KeepSpan", 1370 expect: expect{ 1371 spans: 1, 1372 droppedSpansStatsCount: 0, 1373 }, 1374 }, 1375 { 1376 name: "2msSetting/KeepSpan", 1377 setup: func() func() { 1378 os.Setenv("ELASTIC_APM_EXIT_SPAN_MIN_DURATION", "2ms") 1379 return func() { os.Unsetenv("ELASTIC_APM_EXIT_SPAN_MIN_DURATION") } 1380 }, 1381 expect: expect{ 1382 spans: 1, 1383 droppedSpansStatsCount: 0, 1384 }, 1385 }, 1386 { 1387 name: "3msSetting/DropSpan", 1388 setup: func() func() { 1389 os.Setenv("ELASTIC_APM_EXIT_SPAN_MIN_DURATION", "3ms") 1390 return func() { os.Unsetenv("ELASTIC_APM_EXIT_SPAN_MIN_DURATION") } 1391 }, 1392 expect: expect{ 1393 spans: 0, 1394 droppedSpansStatsCount: 1, 1395 }, 1396 }, 1397 { 1398 name: "100usSetting/DropSpan", 1399 setup: func() func() { 1400 os.Setenv("ELASTIC_APM_EXIT_SPAN_MIN_DURATION", "100us") 1401 return func() { os.Unsetenv("ELASTIC_APM_EXIT_SPAN_MIN_DURATION") } 1402 }, 1403 expect: expect{ 1404 spans: 1, 1405 droppedSpansStatsCount: 0, 1406 }, 1407 }, 1408 } 1409 for _, test := range tests { 1410 t.Run(test.name, func(t *testing.T) { 1411 if test.setup != nil { 1412 defer test.setup()() 1413 } 1414 1415 tracer := apmtest.NewRecordingTracer() 1416 defer tracer.Close() 1417 1418 tx := tracer.StartTransaction("name", "type") 1419 span := tx.StartSpanOptions("name", "type", apm.SpanOptions{ExitSpan: true}) 1420 span.Duration = 2 * time.Millisecond 1421 1422 span.End() 1423 tx.End() 1424 tracer.Flush(nil) 1425 payloads := tracer.Payloads() 1426 require.Len(t, payloads.Transactions, 1) 1427 assert.Len(t, payloads.Spans, test.expect.spans) 1428 assert.Len(t, 1429 payloads.Transactions[0].DroppedSpansStats, 1430 test.expect.droppedSpansStatsCount, 1431 ) 1432 }) 1433 } 1434 } 1435 1436 func TestSpanFastExitWithCompress(t *testing.T) { 1437 // This test case asserts compressing spans into a composite: 1438 // * Takes precedence over dropping the spans 1439 // * When spans cannot be compressed but are discardable, they are. 1440 // * The compressed and dropped spans are not counted in tx.started. 1441 // * Dropped spans increment the dropped count. 1442 // Since compressed spans rely on the first compressed child's timestamp 1443 // to calculate the span duration, we're using a running timestsamp for 1444 // the spans. 1445 1446 tracer := apmtest.NewRecordingTracer() 1447 defer tracer.Close() 1448 tracer.SetSpanCompressionEnabled(true) 1449 1450 txts := time.Now() 1451 tx := tracer.StartTransactionOptions("name", "type", apm.TransactionOptions{ 1452 Start: txts, 1453 }) 1454 ctx := apm.ContextWithTransaction(context.Background(), tx) 1455 ts := time.Now() 1456 1457 // Compress 499 spans which are compressable and can be dropped, they will 1458 // be compressed since that takes precedence. 1459 for i := 0; i < 499; i++ { 1460 span, _ := apm.StartSpanOptions(ctx, "compressed", "type", apm.SpanOptions{ 1461 ExitSpan: true, Start: ts, 1462 }) 1463 span.Duration = time.Millisecond 1464 ts = ts.Add(span.Duration) 1465 span.End() 1466 } 1467 1468 // This span is compressable and can be dropped too but won't be since its 1469 // outcome is "failure". 1470 errorSpan, _ := apm.StartSpanOptions(ctx, "compressed", "type", apm.SpanOptions{ 1471 ExitSpan: true, Start: ts, 1472 }) 1473 errorSpan.Duration = time.Millisecond 1474 ts = ts.Add(errorSpan.Duration) 1475 errorSpan.Outcome = "failure" 1476 errorSpan.End() 1477 1478 // These spans will be compressed into a composite. 1479 for i := 0; i < 100; i++ { 1480 span, _ := apm.StartSpanOptions(ctx, "compressed", "anothertype", apm.SpanOptions{ 1481 ExitSpan: true, Start: ts, 1482 }) 1483 span.Duration = time.Millisecond 1484 ts = ts.Add(span.Duration) 1485 span.End() 1486 } 1487 1488 // Uncompressable spans are dropped when they are considered fast exit spans 1489 // <= 1ms by default. They should not be accounted in the "Started" spans. 1490 for i := 0; i < 100; i++ { 1491 span, _ := apm.StartSpanOptions(ctx, fmt.Sprint(i), fmt.Sprint(i), apm.SpanOptions{ 1492 ExitSpan: true, Start: ts, 1493 }) 1494 span.Duration = 500 * time.Microsecond 1495 ts = ts.Add(span.Duration) 1496 span.End() 1497 } 1498 1499 tx.Duration = ts.Sub(txts) 1500 tx.End() 1501 tracer.Flush(nil) 1502 payloads := tracer.Payloads() 1503 1504 require.Len(t, payloads.Transactions, 1) 1505 defer func() { 1506 if t.Failed() { 1507 apmtest.WriteTraceTable(os.Stdout, payloads.Transactions[0], payloads.Spans) 1508 apmtest.WriteTraceWaterfall(os.Stdout, payloads.Transactions[0], payloads.Spans) 1509 } 1510 }() 1511 1512 assert.Len(t, payloads.Spans, 3) 1513 transaction := payloads.Transactions[0] 1514 assert.Len(t, transaction.DroppedSpansStats, 100) 1515 assert.Equal(t, model.SpanCount{ 1516 Dropped: 100, 1517 Started: 3, 1518 }, transaction.SpanCount) 1519 } 1520 1521 func TestSpanFastExitNoTransaction(t *testing.T) { 1522 // This test case asserts that a discardable span is not discarded when the 1523 // transaction ends before the span, since the stats wouldn't be recorded. 1524 tracer := apmtest.NewRecordingTracer() 1525 defer tracer.Close() 1526 1527 tx := tracer.StartTransaction("name", "type") 1528 ctx := apm.ContextWithTransaction(context.Background(), tx) 1529 span, _ := apm.StartSpanOptions(ctx, "compressed", "type", apm.SpanOptions{ExitSpan: true}) 1530 1531 tx.End() 1532 span.Duration = time.Millisecond 1533 span.End() 1534 1535 tracer.Flush(nil) 1536 payloads := tracer.Payloads() 1537 1538 require.Len(t, payloads.Transactions, 1) 1539 require.Len(t, payloads.Spans, 1) 1540 transaction := payloads.Transactions[0] 1541 1542 assert.Len(t, transaction.DroppedSpansStats, 0) 1543 assert.Equal(t, model.SpanCount{ 1544 Started: 1, 1545 Dropped: 0, 1546 }, transaction.SpanCount) 1547 } 1548 1549 func TestSpanOutcome(t *testing.T) { 1550 _, spans, _ := apmtest.WithTransaction(func(ctx context.Context) { 1551 span1, _ := apm.StartSpan(ctx, "name", "type") 1552 span1.End() 1553 1554 span2, _ := apm.StartSpan(ctx, "name", "type") 1555 span2.Outcome = "unknown" 1556 span2.End() 1557 1558 span3, _ := apm.StartSpan(ctx, "name", "type") 1559 span3.Context.SetHTTPStatusCode(200) 1560 span3.End() 1561 1562 span4, _ := apm.StartSpan(ctx, "name", "type") 1563 span4.Context.SetHTTPStatusCode(400) 1564 span4.End() 1565 1566 span5, ctx := apm.StartSpan(ctx, "name", "type") 1567 apm.CaptureError(ctx, errors.New("an error")).Send() 1568 span5.End() 1569 }) 1570 1571 require.Len(t, spans, 5) 1572 assert.Equal(t, "success", spans[0].Outcome) // default 1573 assert.Equal(t, "unknown", spans[1].Outcome) // specified 1574 assert.Equal(t, "success", spans[2].Outcome) // HTTP status < 400 1575 assert.Equal(t, "failure", spans[3].Outcome) // HTTP status >= 400 1576 assert.Equal(t, "failure", spans[4].Outcome) 1577 }