Tracer refactor: removed dead code and excessive logging

Author: Robert Bartoszewski

Sources/BugsnagPerformance/Private/EarlyConfiguration.h

@@ -30,7 +30,6 @@ NS_ASSUME_NONNULL_BEGIN
 
 @property(nonatomic, readonly) BOOL enableSwizzling;
 @property(nonatomic, readonly) BOOL swizzleViewLoadPreMain;
-@property(nonatomic, readwrite) BOOL appWasLaunchedPreWarmed;
 
 @end
 

Sources/BugsnagPerformance/Private/EarlyConfiguration.mm

@@ -18,13 +18,8 @@ - (instancetype) initWithBundleDictionary:(NSDictionary *)dict {
         }
         id swizzleViewLoadPreMain = [dict valueForKeyPath:@"bugsnag.performance.swizzleViewLoadPreMain"];
         _swizzleViewLoadPreMain = swizzleViewLoadPreMain != nil && [swizzleViewLoadPreMain boolValue];
-        _appWasLaunchedPreWarmed = [NSProcessInfo.processInfo.environment[@"ActivePrewarm"] isEqualToString:@"1"];
     }
 
-    BSGLogDebug(@"BSGEarlyConfiguration.enableSwizzling = %d", self.enableSwizzling);
-    BSGLogDebug(@"BSGEarlyConfiguration.swizzleViewLoadPreMain = %d", self.swizzleViewLoadPreMain);
-    BSGLogDebug(@"BSGEarlyConfiguration.appWasLaunchedPreWarmed = %d", self.appWasLaunchedPreWarmed);
-
     return self;
 }
 

Sources/BugsnagPerformance/Private/SpanFactory/ViewLoad/ViewLoadSpanFactoryCallbacks.h

@@ -11,13 +11,12 @@
 
 typedef BugsnagPerformanceSpan *_Nullable(^GetViewLoadParentSpanCallback)(void);
 typedef BOOL (^IsViewLoadInProgressCallback)(void);
-typedef void (^OnViewLoadSpanStarted)(BugsnagPerformanceSpan * _Nonnull, NSString * _Nonnull);
+typedef void (^OnViewLoadSpanStarted)(NSString * _Nonnull);
 
 @interface ViewLoadSpanFactoryCallbacks: NSObject
 
 @property (nonatomic, nullable) GetViewLoadParentSpanCallback getViewLoadParentSpan;
 @property (nonatomic, nullable) IsViewLoadInProgressCallback isViewLoadInProgress;
 @property (nonatomic, nullable) OnViewLoadSpanStarted onViewLoadSpanStarted;
-@property (nonatomic, nullable) SpanLifecycleCallback onViewLoadPhaseSpanStarted;
 
 @end

Sources/BugsnagPerformance/Private/SpanFactory/ViewLoad/ViewLoadSpanFactoryImpl.mm

@@ -116,7 +116,7 @@
                                              spanAttributes,
                                              conditionsToEndOnClose);
     if (callbacks_.onViewLoadSpanStarted != nil) {
-        callbacks_.onViewLoadSpanStarted(span, className);
+        callbacks_.onViewLoadSpanStarted(className);
     }
     return span;
 }
@@ -136,9 +136,6 @@
                                              BSGTriStateUnset,
                                              attributes,
                                              conditionsToEndOnClose);
-    if (callbacks_.onViewLoadPhaseSpanStarted != nil) {
-        callbacks_.onViewLoadPhaseSpanStarted(span);
-    }
     return span;
 }
 

Sources/BugsnagPerformance/Private/Tracer.h

@@ -49,7 +49,6 @@ class Tracer: public PhasedStartup {
            void (^onSpanStarted)()) noexcept
     : spanStackingHandler_(spanStackingHandler)
     , sampler_(sampler)
-    , prewarmSpans_([NSMutableArray new])
     , blockedSpans_([NSMutableArray new])
     , potentiallyOpenSpans_(std::make_shared<WeakSpansList>())
     , batch_(batch)
@@ -69,7 +68,7 @@ class Tracer: public PhasedStartup {
 
     ~Tracer() {};
 
-    void earlyConfigure(BSGEarlyConfiguration *) noexcept;
+    void earlyConfigure(BSGEarlyConfiguration *) noexcept {}
     void earlySetup() noexcept {}
     void configure(BugsnagPerformanceConfiguration *config) noexcept {
         plainSpanFactory_->setAttributeCountLimit(config.attributeCountLimit);
@@ -102,16 +101,12 @@ class Tracer: public PhasedStartup {
                                                    NSArray<BugsnagPerformanceSpanCondition *> *conditionsToEndOnClose) noexcept;
 
     void cancelQueuedSpan(BugsnagPerformanceSpan *span) noexcept;
-
-    void onPrewarmPhaseEnded(void) noexcept;
 
     void abortAllOpenSpans() noexcept;
 
     // Sweep must be called periodically to avoid a buildup of dead pointers.
     void sweep() noexcept;
 
-    void callOnSpanEndCallbacks(BugsnagPerformanceSpan *span);
-
 private:
     Tracer() = delete;
     std::shared_ptr<Sampler> sampler_;
@@ -122,10 +117,7 @@ class Tracer: public PhasedStartup {
     std::shared_ptr<ViewLoadSpanFactoryImpl> viewLoadSpanFactory_;
     std::shared_ptr<NetworkSpanFactoryImpl> networkSpanFactory_;
 
-    std::atomic<bool> willDiscardPrewarmSpans_{false};
     BugsnagPerformanceEnabledMetrics *enabledMetrics_{[BugsnagPerformanceEnabledMetrics withAllEnabled]};
-    std::mutex prewarmSpansMutex_;
-    NSMutableArray<BugsnagPerformanceSpan *> *prewarmSpans_;
     NSMutableArray<BugsnagPerformanceSpan *> *blockedSpans_;
     BSGPrioritizedStore<BugsnagPerformanceSpanStartCallback> *onSpanStartCallbacks_;
     BSGPrioritizedStore<BugsnagPerformanceSpanEndCallback> *onSpanEndCallbacks_;
@@ -142,13 +134,13 @@ class Tracer: public PhasedStartup {
     PlainSpanFactoryCallbacks *createPlainSpanFactoryCallbacks() noexcept;
     ViewLoadSpanFactoryCallbacks *createViewLoadSpanFactoryCallbacks() noexcept;
     void createFrozenFrameSpan(NSTimeInterval startTime, NSTimeInterval endTime, BugsnagPerformanceSpanContext *parentContext) noexcept;
-    void markPrewarmSpan(BugsnagPerformanceSpan *span) noexcept;
     void onSpanEndSet(BugsnagPerformanceSpan *span);
     void onSpanClosed(BugsnagPerformanceSpan *span);
     BugsnagPerformanceSpanCondition *onSpanBlocked(BugsnagPerformanceSpan *blocked, NSTimeInterval timeout);
     void reprocessEarlySpans(void);
     void processFrameMetrics(BugsnagPerformanceSpan *span) noexcept;
     bool shouldInstrumentRendering(BugsnagPerformanceSpan *span) noexcept;
     void callOnSpanStartCallbacks(BugsnagPerformanceSpan *span);
+    void callOnSpanEndCallbacks(BugsnagPerformanceSpan *span);
 };
 }

Sources/BugsnagPerformance/Private/Tracer.mm

@@ -18,39 +18,27 @@
 
 using namespace bugsnag;
 
-void
-Tracer::earlyConfigure(BSGEarlyConfiguration *config) noexcept {
-    willDiscardPrewarmSpans_ = config.appWasLaunchedPreWarmed;
-}
-
 void
 Tracer::preStartSetup() noexcept {
-    BSGLogDebug(@"Tracer::preStartSetup()");
     reprocessEarlySpans();
 }
 
 void Tracer::reprocessEarlySpans(void) {
-    BSGLogDebug(@"Tracer::reprocessEarlySpans()");
     // Up until now nothing was configured, so all early spans have been kept.
     // Now that configuration is complete, force-drain all early spans and re-process them.
     auto toReprocess = batch_->drain(true);
-    BSGLogDebug(@"Tracer::reprocessEarlySpans: Reprocessing %zu early spans", toReprocess.count);
     for (BugsnagPerformanceSpan *span in toReprocess) {
-        BSGLogDebug(@"Tracer::reprocessEarlySpans: Try to re-add span (%@) to batch", span.name);
         if (span.state != SpanStateEnded) {
-            BSGLogDebug(@"Tracer::reprocessEarlySpans: span %@ has state %d, so ignoring", span.name, span.state);
             continue;
         }
         if (!sampler_->sampled(span)) {
-            BSGLogDebug(@"Tracer::reprocessEarlySpans: span %@ was not sampled (P=%f), so dropping", span.name, sampler_->getProbability());
             [span abortUnconditionally];
             continue;
         }
         [span forceMutate:^() {
             callOnSpanEndCallbacks(span);
         }];
         if (span.state == SpanStateAborted) {
-            BSGLogDebug(@"Tracer::reprocessEarlySpans: span %@ was rejected in the OnEnd callbacks, so dropping", span.name);
             [span abortUnconditionally];
             continue;
         }
@@ -61,13 +49,11 @@
 
 void
 Tracer::abortAllOpenSpans() noexcept {
-    BSGLogDebug(@"Tracer::abortAllOpenSpans()");
     potentiallyOpenSpans_->abortAllOpen();
 }
 
 void
 Tracer::sweep() noexcept {
-    BSGLogDebug(@"Tracer::sweep()");
     constexpr unsigned minEntriesBeforeCompacting = 10000;
     if (potentiallyOpenSpans_->count() >= minEntriesBeforeCompacting) {
         potentiallyOpenSpans_->compact();
@@ -83,16 +69,12 @@
 }
 
 void Tracer::onSpanEndSet(BugsnagPerformanceSpan *span) {
-    BSGLogTrace(@"Tracer::onSpanEndSet: for span %@", span.name);
-
     if (shouldInstrumentRendering(span)) {
         span.endFramerateSnapshot = [frameMetricsCollector_ currentSnapshot];
     }
 }
 
 void Tracer::onSpanClosed(BugsnagPerformanceSpan *span) {
-    BSGLogTrace(@"Tracer::onSpanClosed: for span %@", span.name);
-    
     @synchronized (span) {
         for (BugsnagPerformanceSpanCondition *condition in span.conditionsToEndOnClose) {
             [condition closeWithEndTime:span.endTime];
@@ -102,30 +84,25 @@
     spanStackingHandler_->onSpanClosed(span.spanId);
 
     if(span.state == SpanStateAborted) {
-        BSGLogTrace(@"Tracer::onSpanClosed: span %@ has been aborted, so ignoring", span.name);
         return;
     }
 
     if (!sampler_->sampled(span)) {
-        BSGLogTrace(@"Tracer::onSpanClosed: span %@ was not sampled (P=%f), so dropping", span.name, sampler_->getProbability());
         [span abortUnconditionally];
         return;
     }
 
     if (span != nil && span.state == SpanStateEnded) {
         callOnSpanEndCallbacks(span);
         if (span.state == SpanStateAborted) {
-            BSGLogTrace(@"Tracer::onSpanClosed: span %@ was rejected in the OnEnd callbacks, so dropping", span.name);
             return;
         }
     }
 
     if (shouldInstrumentRendering(span)) {
-        BSGLogTrace(@"Tracer::onSpanClosed: Processing framerate metrics for span %@", span.name);
         processFrameMetrics(span);
     }
 
-    BSGLogTrace(@"Tracer::onSpanClosed: Adding span %@ to batch", span.name);
     batch_->add(span);
 }
 
@@ -134,7 +111,6 @@
         return nil;
     }
     if (span.state != SpanStateOpen && !span.isBlocked) {
-        BSGLogDebug(@"Tracer::onSpanBlocked: span %@ has state %d, so ignoring", span.name, span.state);
         return nil;
     }
     BugsnagPerformanceSpanCondition *condition = [BugsnagPerformanceSpanCondition conditionWithSpan:span onClosedCallback:^(BugsnagPerformanceSpanCondition *c, CFAbsoluteTime endTime) {
@@ -157,7 +133,6 @@
     [condition addOnDeactivatedCallback:^(BugsnagPerformanceSpanCondition *c) {
         __strong BugsnagPerformanceSpan *strongSpan = c.span;
         if (strongSpan.state == SpanStateEnded && !strongSpan.isBlocked) {
-            BSGLogTrace(@"Tracer::onSpanBlocked: Processing unblocked span %@", span.name);
             @synchronized (this->blockedSpans_) {
                 [this->blockedSpans_ removeObject:strongSpan];
                 this->conditionTimeoutExecutor_->cancelTimeout(c);
@@ -166,7 +141,6 @@
         }
     }];
     this->conditionTimeoutExecutor_->sheduleTimeout(condition, timeout);
-    BSGLogTrace(@"Tracer::onSpanBlocked: Blocked span %@ with timeout %f", span.name, timeout);
     return condition;
 }
 
@@ -189,7 +163,6 @@
         return;
     }
     if (span.state != SpanStateEnded) {
-        BSGLogDebug(@"Tracer::callOnSpanEndCallbacks: span %@ has state %d, so ignoring", span.name, span.state);
         return;
     }
 
@@ -204,13 +177,11 @@
             shouldDiscardSpan = false;
         }
         if(shouldDiscardSpan) {
-            BSGLogDebug(@"Tracer::callOnSpanEndCallbacks: span %@ OnEnd callback returned false. Dropping...", span.name);
             [span abortUnconditionally];
             return;
         }
     }
     CFAbsoluteTime callbacksEndTime = CFAbsoluteTimeGetCurrent();
-    BSGLogDebug(@"Tracer::callOnSpanEndCallbacks: Adding span %@ to batch", span.name);
     [span internalSetAttribute:@"bugsnag.span.callbacks_duration" withValue:@(intervalToNanoseconds(callbacksEndTime - callbacksStartTime))];
 }
 
@@ -273,22 +244,13 @@
 }
 
 void Tracer::cancelQueuedSpan(BugsnagPerformanceSpan *span) noexcept {
-    BSGLogTrace(@"Tracer::cancelQueuedSpan(%@)", span.name);
     if (span) {
         [span abortUnconditionally];
         batch_->removeSpan(span.traceIdHi, span.traceIdLo, span.spanId);
         [blockedSpans_ removeObject:span];
     }
 }
 
-void Tracer::markPrewarmSpan(BugsnagPerformanceSpan *span) noexcept {
-    BSGLogTrace(@"Tracer::markPrewarmSpan(%@)", span.name);
-    std::lock_guard<std::mutex> guard(prewarmSpansMutex_);
-    if (willDiscardPrewarmSpans_) {
-        [prewarmSpans_ addObject:span];
-    }
-}
-
 PlainSpanFactoryCallbacks *
 Tracer::createPlainSpanFactoryCallbacks() noexcept {
     __block auto blockThis = this;
@@ -345,21 +307,13 @@
         return blockThis->spanStackingHandler_->hasSpanWithAttribute(@"bugsnag.span.category", @"view_load");
     };
 
-    auto onSpanStarted = ^(BugsnagPerformanceSpan * _Nonnull span) {
-        if (blockThis->willDiscardPrewarmSpans_) {
-            blockThis->markPrewarmSpan(span);
-        }
-    };
-    
-    auto onViewLoadSpanStarted = ^(BugsnagPerformanceSpan * _Nonnull span, NSString * _Nonnull className) {
+    auto onViewLoadSpanStarted = ^(NSString * _Nonnull className) {
         if (onViewLoadSpanStarted_ != nil) {
             onViewLoadSpanStarted_(className);
         }
-        onSpanStarted(span);
     };
 
     callbacks.onViewLoadSpanStarted = onViewLoadSpanStarted;
-    callbacks.onViewLoadPhaseSpanStarted = onSpanStarted;
 
     return callbacks;
 }
@@ -376,20 +330,6 @@
     [span endWithAbsoluteTime:endTime];
 }
 
-void
-Tracer::onPrewarmPhaseEnded(void) noexcept {
-    BSGLogDebug(@"Tracer::onPrewarmPhaseEnded()");
-    std::lock_guard<std::mutex> guard(prewarmSpansMutex_);
-    willDiscardPrewarmSpans_ = false;
-    for (BugsnagPerformanceSpan *span: prewarmSpans_) {
-        // Only cancel unfinished prewarm spans
-        if (span.state == SpanStateOpen) {
-            cancelQueuedSpan(span);
-        }
-    }
-    [prewarmSpans_ removeAllObjects];
-}
-
 bool
 Tracer::shouldInstrumentRendering(BugsnagPerformanceSpan *span) noexcept {
     switch (span.metricsOptions.rendering) {