diff --git a/Workflow/Sources/SubtreeManager.swift b/Workflow/Sources/SubtreeManager.swift index 76711ab29..9ae65bb2c 100644 --- 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, eventPipe: EventPipe) { diff --git a/Workflow/Sources/WorkflowHost.swift b/Workflow/Sources/WorkflowHost.swift index b1029f670..2cab79e41 100644 --- a/Workflow/Sources/WorkflowHost.swift +++ b/Workflow/Sources/WorkflowHost.swift @@ -54,7 +54,7 @@ public final class WorkflowHost { 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 { } private func handle(output: WorkflowNode.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 index 51ed428dc..48bbcdae2 100644 --- 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(ref: WorkflowNode) { 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(ref: WorkflowNode) { 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(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(ref: WorkflowNode) { + static func logWorkflowStartedRendering( + ref: WorkflowNode, + 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(ref: WorkflowNode) { + static func logWorkflowFinishedRendering( + ref: WorkflowNode, + 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 index 38e592227..a2af1a51c 100644 --- a/Workflow/Sources/WorkflowNode.swift +++ b/Workflow/Sources/WorkflowNode.swift @@ -74,11 +74,16 @@ final class WorkflowNode { 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 new file mode 100644 index 000000000..2b6c5851a --- /dev/null +++ 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) -> 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) -> 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) -> 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 index 63a4a0ea1..5c89c91cd 100644 --- a/WorkflowReactiveSwift/Sources/Logger.swift +++ b/WorkflowReactiveSwift/Sources/Logger.swift @@ -16,8 +16,20 @@ import os.signpost +// Namespace for Worker logging +public enum WorkerLogging {} + +extension WorkerLogging { + public static var enabled: Bool { + get { OSLog.active === OSLog.worker } + set { OSLog.active = newValue ? .worker : .disabled } + } +} + private extension OSLog { static let worker = OSLog(subsystem: "com.squareup.WorkflowReactiveSwift", category: "Worker") + + static var active: OSLog = .disabled } // MARK: - @@ -27,7 +39,7 @@ final class WorkerLogger { init() {} @available(iOS 12.0, macOS 10.14, *) - var signpostID: OSSignpostID { OSSignpostID(log: .worker, object: self) } + var signpostID: OSSignpostID { OSSignpostID(log: .active, object: self) } // MARK: - Workers @@ -35,7 +47,7 @@ final class WorkerLogger { if #available(iOS 12.0, macOS 10.14, *) { os_signpost( .begin, - log: .worker, + log: .active, name: "Running", signpostID: self.signpostID, "Worker: %{private}@", @@ -46,7 +58,7 @@ final class WorkerLogger { func logFinished(status: StaticString) { if #available(iOS 12.0, macOS 10.14, *) { - os_signpost(.end, log: .worker, name: "Running", signpostID: signpostID, status) + os_signpost(.end, log: .active, name: "Running", signpostID: signpostID, status) } } @@ -54,7 +66,7 @@ final class WorkerLogger { if #available(iOS 12.0, macOS 10.14, *) { os_signpost( .event, - log: .worker, + log: .active, name: "Worker Event", signpostID: signpostID, "Event: %{private}@", diff --git a/WorkflowRxSwift/Sources/Logger.swift b/WorkflowRxSwift/Sources/Logger.swift index 045474c14..237aa2ba6 100644 --- a/WorkflowRxSwift/Sources/Logger.swift +++ b/WorkflowRxSwift/Sources/Logger.swift @@ -16,8 +16,20 @@ import os.signpost +// Namespace for Worker logging +public enum WorkerLogging {} + +extension WorkerLogging { + public static var enabled: Bool { + get { OSLog.active === OSLog.worker } + set { OSLog.active = newValue ? .worker : .disabled } + } +} + private extension OSLog { static let worker = OSLog(subsystem: "com.squareup.WorkflowRxSwift", category: "Worker") + + static var active: OSLog = .disabled } // MARK: - @@ -27,7 +39,7 @@ final class WorkerLogger { init() {} @available(iOS 12.0, macOS 10.14, *) - var signpostID: OSSignpostID { OSSignpostID(log: .worker, object: self) } + var signpostID: OSSignpostID { OSSignpostID(log: .active, object: self) } // MARK: - Workers @@ -35,7 +47,7 @@ final class WorkerLogger { if #available(iOS 12.0, macOS 10.14, *) { os_signpost( .begin, - log: .worker, + log: .active, name: "Running", signpostID: self.signpostID, "Worker: %{private}@", @@ -46,7 +58,7 @@ final class WorkerLogger { func logFinished(status: StaticString) { if #available(iOS 12.0, macOS 10.14, *) { - os_signpost(.end, log: .worker, name: "Running", signpostID: signpostID, status) + os_signpost(.end, log: .active, name: "Running", signpostID: signpostID, status) } } @@ -54,7 +66,7 @@ final class WorkerLogger { if #available(iOS 12.0, macOS 10.14, *) { os_signpost( .event, - log: .worker, + log: .active, name: "Worker Event", signpostID: signpostID, "Event: %{private}@",