[performance]: disable logging by default & add logging configuration (#151)

jamieQ · web-flow · commit 1ee49f22c8e9 · 2022-08-19T09:54:23.000-05:00
## Background

- during some recent investigations into rendering performance, we found that leaving the runtime os logging enabled (the current implicit behavior) had a noticeable adverse effect.

## Changes

- logging is now opt-in, and disabled by default
- added additional configuration options to control which categories of runtime data are logged
- added synthetic performance tests to gut check execution time changes under various logging configurations
diff --git a/Workflow/Sources/SubtreeManager.swift b/Workflow/Sources/SubtreeManager.swift
@@ -406,7 +406,7 @@ extension WorkflowNode.SubtreeManager {
         }
 
         func render() -> W.Rendering {
-            return node.render()
+            return node.render(isRootNode: false)
         }
 
         func update(workflow: W, outputMap: @escaping (W.Output) -> AnyWorkflowAction<WorkflowType>, eventPipe: EventPipe) {
diff --git a/Workflow/Sources/WorkflowHost.swift b/Workflow/Sources/WorkflowHost.swift
@@ -54,7 +54,7 @@ public final class WorkflowHost<WorkflowType: Workflow> {
 
         self.rootNode = WorkflowNode(workflow: workflow)
 
-        self.mutableRendering = MutableProperty(rootNode.render())
+        self.mutableRendering = MutableProperty(rootNode.render(isRootNode: true))
         self.rendering = Property(mutableRendering)
         rootNode.enableEvents()
 
@@ -81,7 +81,7 @@ public final class WorkflowHost<WorkflowType: Workflow> {
     }
 
     private func handle(output: WorkflowNode<WorkflowType>.Output) {
-        mutableRendering.value = rootNode.render()
+        mutableRendering.value = rootNode.render(isRootNode: true)
 
         if let outputEvent = output.outputEvent {
             outputEventObserver.send(value: outputEvent)
diff --git a/Workflow/Sources/WorkflowLogger.swift b/Workflow/Sources/WorkflowLogger.swift
@@ -17,7 +17,69 @@
 import os.signpost
 
 private extension OSLog {
+    /// Logging will use this log handle when enabled
     static let workflow = OSLog(subsystem: "com.squareup.Workflow", category: "Workflow")
+
+    /// The active log handle to use when logging. Defaults to the shared `.disabled` handle.
+    static var active: OSLog = .disabled
+}
+
+// MARK: -
+
+/// Namespace for specifying logging configuration data.
+public enum WorkflowLogging {}
+
+extension WorkflowLogging {
+    public struct Config {
+        /// Configuration options to control logging during a render pass.
+        public enum RenderLoggingMode {
+            /// No data will be recorded for WorkflowNode render timings.
+            case none
+
+            /// Render timings will only be recorded for root nodes in a Workflow tree.
+            case rootsOnly
+
+            /// Render timings will be recorded for all nodes in a Workflow tree.
+            /// N.B. performance may be noticeably impacted when using this option.
+            case allNodes
+        }
+
+        public var renderLoggingMode: RenderLoggingMode = .allNodes
+
+        /// When `true`, the interval spanning a WorkflowNode's lifetime will be recorded.
+        public var logLifetimes = true
+
+        /// When `true`, action events will be recorded.
+        public var logActions = true
+    }
+
+    /// Global setting to enable or disable logging.
+    /// Note, this is independent of the specified `config` value, and simply governs whether
+    /// the runtime should emit any logs.
+    ///
+    /// To enable logging, at a minimum you must set:
+    /// `WorkflowLogging.enabled = true`
+    ///
+    /// If you wish for more control over what the runtime will log, you may additionally specify
+    /// a custom value for `WorkflowLogging.config`.
+    public static var enabled: Bool {
+        get { OSLog.active === OSLog.workflow }
+        set { OSLog.active = newValue ? .workflow : .disabled }
+    }
+
+    /// Configuration options used to determine which activities are logged.
+    public static var config: Config = .rootRendersAndActions
+}
+
+extension WorkflowLogging.Config {
+    /// Logging config that will output the most information.
+    /// Will also have the most noticeable effect on performance.
+    public static let debug: Self = .init(renderLoggingMode: .allNodes, logLifetimes: true, logActions: true)
+
+    /// Logging config that will record render timings for root nodes as well as action events.
+    /// This provides a reasonable performance tradeoff if you're interested in the runtime's behavior
+    /// but don't wan to pay the price of logging everything.
+    public static let rootRendersAndActions: Self = .init(renderLoggingMode: .rootsOnly, logLifetimes: false, logActions: true)
 }
 
 // MARK: -
@@ -32,10 +94,12 @@ final class WorkflowLogger {
 
     static func logWorkflowStarted<WorkflowType>(ref: WorkflowNode<WorkflowType>) {
         if #available(iOS 12.0, macOS 10.14, *) {
-            let signpostID = OSSignpostID(log: .workflow, object: ref)
+            guard WorkflowLogging.config.logLifetimes else { return }
+
+            let signpostID = OSSignpostID(log: .active, object: ref)
             os_signpost(
                 .begin,
-                log: .workflow,
+                log: .active,
                 name: "Alive",
                 signpostID: signpostID,
                 "Workflow: %{public}@",
@@ -46,17 +110,21 @@ final class WorkflowLogger {
 
     static func logWorkflowFinished<WorkflowType>(ref: WorkflowNode<WorkflowType>) {
         if #available(iOS 12.0, macOS 10.14, *) {
-            let signpostID = OSSignpostID(log: .workflow, object: ref)
-            os_signpost(.end, log: .workflow, name: "Alive", signpostID: signpostID)
+            guard WorkflowLogging.config.logLifetimes else { return }
+
+            let signpostID = OSSignpostID(log: .active, object: ref)
+            os_signpost(.end, log: .active, name: "Alive", signpostID: signpostID)
         }
     }
 
     static func logSinkEvent<Action: WorkflowAction>(ref: AnyObject, action: Action) {
         if #available(iOS 12.0, macOS 10.14, *) {
-            let signpostID = OSSignpostID(log: .workflow, object: ref)
+            guard WorkflowLogging.config.logActions else { return }
+
+            let signpostID = OSSignpostID(log: .active, object: ref)
             os_signpost(
                 .event,
-                log: .workflow,
+                log: .active,
                 name: "Sink Event",
                 signpostID: signpostID,
                 "Event for workflow: %{public}@",
@@ -67,12 +135,20 @@ final class WorkflowLogger {
 
     // MARK: Rendering
 
-    static func logWorkflowStartedRendering<WorkflowType>(ref: WorkflowNode<WorkflowType>) {
+    static func logWorkflowStartedRendering<WorkflowType>(
+        ref: WorkflowNode<WorkflowType>,
+        isRootNode: Bool
+    ) {
         if #available(iOS 12.0, macOS 10.14, *) {
-            let signpostID = OSSignpostID(log: .workflow, object: ref)
+            guard shouldLogRenderTimingsForMode(
+                WorkflowLogging.config.renderLoggingMode,
+                isRootNode: isRootNode
+            ) else { return }
+
+            let signpostID = OSSignpostID(log: .active, object: ref)
             os_signpost(
                 .begin,
-                log: .workflow,
+                log: .active,
                 name: "Render",
                 signpostID: signpostID,
                 "Render Workflow: %{public}@",
@@ -81,10 +157,34 @@ final class WorkflowLogger {
         }
     }
 
-    static func logWorkflowFinishedRendering<WorkflowType>(ref: WorkflowNode<WorkflowType>) {
+    static func logWorkflowFinishedRendering<WorkflowType>(
+        ref: WorkflowNode<WorkflowType>,
+        isRootNode: Bool
+    ) {
         if #available(iOS 12.0, macOS 10.14, *) {
-            let signpostID = OSSignpostID(log: .workflow, object: ref)
-            os_signpost(.end, log: .workflow, name: "Render", signpostID: signpostID)
+            guard shouldLogRenderTimingsForMode(
+                WorkflowLogging.config.renderLoggingMode,
+                isRootNode: isRootNode
+            ) else { return }
+
+            let signpostID = OSSignpostID(log: .active, object: ref)
+            os_signpost(.end, log: .active, name: "Render", signpostID: signpostID)
+        }
+    }
+
+    // MARK: - Utilities
+
+    private static func shouldLogRenderTimingsForMode(
+        _ renderLoggingMode: WorkflowLogging.Config.RenderLoggingMode,
+        isRootNode: Bool
+    ) -> Bool {
+        switch WorkflowLogging.config.renderLoggingMode {
+        case .none:
+            return false
+        case .rootsOnly where !isRootNode:
+            return false
+        default:
+            return true
         }
     }
 }
diff --git a/Workflow/Sources/WorkflowNode.swift b/Workflow/Sources/WorkflowNode.swift
@@ -74,11 +74,16 @@ final class WorkflowNode<WorkflowType: Workflow> {
         onOutput?(output)
     }
 
-    func render() -> WorkflowType.Rendering {
-        WorkflowLogger.logWorkflowStartedRendering(ref: self)
+    /// Internal method that forwards the render call through the underlying `subtreeManager`,
+    /// and eventually to the client-specified `Workflow` instance.
+    /// - Parameter isRootNode: whether or not this is the root node of the tree. Note, this
+    /// is currently only used as a hint for the logging infrastructure, and is up to callers to correctly specify.
+    /// - Returns: A `Rendering` of appropriate type
+    func render(isRootNode: Bool = false) -> WorkflowType.Rendering {
+        WorkflowLogger.logWorkflowStartedRendering(ref: self, isRootNode: isRootNode)
 
         defer {
-            WorkflowLogger.logWorkflowFinishedRendering(ref: self)
+            WorkflowLogger.logWorkflowFinishedRendering(ref: self, isRootNode: isRootNode)
         }
 
         return subtreeManager.render { context in
diff --git a/Workflow/Tests/PerformanceTests.swift b/Workflow/Tests/PerformanceTests.swift
@@ -0,0 +1,125 @@
+/*
+ * Copyright 2022 Square Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+import XCTest
+
+@testable import Workflow
+
+class PerformanceTests: XCTestCase {
+    override func setUp() {
+        super.setUp()
+        WorkflowLogging.enabled = false
+    }
+
+    override func tearDown() {
+        super.tearDown()
+        WorkflowLogging.enabled = false
+    }
+
+    func test_render_wideShallowTree() throws {
+        measure {
+            let node = WorkflowNode(workflow: WideShallowParentWorkflow())
+            _ = node.render(isRootNode: true)
+        }
+    }
+
+    func test_render_narrowDeepTree() throws {
+        measure {
+            let node = WorkflowNode(workflow: NarrowDeepParentWorkflow())
+            _ = node.render(isRootNode: true)
+        }
+    }
+
+    func test_debugLogging_render_wideShallowTree() throws {
+        WorkflowLogging.enabled = true
+        WorkflowLogging.config = .debug
+
+        measure {
+            let node = WorkflowNode(workflow: WideShallowParentWorkflow())
+            _ = node.render(isRootNode: true)
+        }
+    }
+
+    func test_rootNodeLogging_render_wideShallowTree() throws {
+        WorkflowLogging.enabled = true
+        WorkflowLogging.config = .rootRendersAndActions
+
+        measure {
+            let node = WorkflowNode(workflow: WideShallowParentWorkflow())
+            _ = node.render(isRootNode: true)
+        }
+    }
+
+    func test_rootNodeLogging_render_narrowDeepTree() throws {
+        WorkflowLogging.enabled = true
+        WorkflowLogging.config = .rootRendersAndActions
+
+        measure {
+            let node = WorkflowNode(workflow: NarrowDeepParentWorkflow())
+            _ = node.render(isRootNode: true)
+        }
+    }
+}
+
+private extension PerformanceTests {
+    struct WideShallowParentWorkflow: Workflow {
+        typealias State = Void
+        typealias Rendering = Int
+
+        func render(state: Void, context: RenderContext<WideShallowParentWorkflow>) -> Int {
+            var sum = 0
+            for i in 1 ... 1000 {
+                sum += ChildWorkflow()
+                    .rendered(in: context, key: "child-\(i)")
+            }
+
+            return sum
+        }
+    }
+
+    struct NarrowDeepParentWorkflow: Workflow {
+        typealias State = Void
+        typealias Rendering = Int
+
+        func render(state: Void, context: RenderContext<NarrowDeepParentWorkflow>) -> Int {
+            var sum = 0
+            sum += ChildWorkflow(remainingChildren: 999)
+                .rendered(in: context)
+
+            return sum
+        }
+    }
+
+    struct ChildWorkflow: Workflow {
+        typealias State = Void
+        typealias Rendering = Int
+
+        var remainingChildren: UInt = 0
+
+        func render(state: Void, context: RenderContext<ChildWorkflow>) -> Int {
+            let rendering: Int
+
+            if remainingChildren > 0 {
+                rendering = ChildWorkflow(remainingChildren: remainingChildren - 1)
+                    .rendered(in: context)
+            } else {
+                rendering = 42
+            }
+
+            return rendering
+        }
+    }
+}
diff --git a/WorkflowReactiveSwift/Sources/Logger.swift b/WorkflowReactiveSwift/Sources/Logger.swift
diff --git a/WorkflowRxSwift/Sources/Logger.swift b/WorkflowRxSwift/Sources/Logger.swift

Original file line number	Diff line number	Diff line change
`@@ -406,7 +406,7 @@ extension WorkflowNode.SubtreeManager {`
`406`	`406`	`}`
`407`	`407`
`408`	`408`	`func render() -> W.Rendering {`
`409`		`- return node.render()`
	`409`	`+ return node.render(isRootNode: false)`
`410`	`410`	`}`
`411`	`411`
`412`	`412`	`func update(workflow: W, outputMap: @escaping (W.Output) -> AnyWorkflowAction<WorkflowType>, eventPipe: EventPipe) {`