Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add os_signpost logs for render() and Workflow and Worker lifecycle #1134

Merged
merged 9 commits into from
May 8, 2020
22 changes: 20 additions & 2 deletions swift/Workflow/Sources/SubtreeManager.swift
Original file line number Diff line number Diff line change
Expand Up @@ -204,7 +204,11 @@ extension WorkflowNode.SubtreeManager {
func makeSink<Action>(of actionType: Action.Type) -> Sink<Action> where Action: WorkflowAction, WorkflowType == Action.WorkflowType {
let reusableSink = sinkStore.findOrCreate(actionType: Action.self)

let signpostRef = SignpostRef()

let sink = Sink<Action> { action in
WorkflowLogger.logSinkEvent(ref: signpostRef, action: action)

reusableSink.handle(action: action)
}

Expand Down Expand Up @@ -407,11 +411,25 @@ extension WorkflowNode.SubtreeManager {
self.outputMap = outputMap
super.init(eventPipe: eventPipe)

let signpostRef = SignpostRef()
WorkflowLogger.logWorkerStartedRunning(ref: signpostRef, workerType: W.self)

signalProducer
.take(during: lifetime)
.observe(on: QueueScheduler.workflowExecution)
.startWithValues { [weak self] output in
self?.handle(output: output)
.start { [weak self] event in
switch event {
case .value(let output):
WorkflowLogger.logWorkerOutput(ref: signpostRef, workerType: W.self)

self?.handle(output: output)
Copy link
Contributor

@JustinDSN JustinDSN May 5, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does it make sense to log an event to indicate a worker emitted a value and it's about to be handled? So you would see that the worker emitted the event, and then it was mapped and handled by a sink?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe move the logging to a different function. logWorkerState(event:)?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm exploring using .on(…) in the stream (similar to what .logEvents does). I'll update this soon.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Did the .on(..) work out?

case .completed:
WorkflowLogger.logWorkerFinishedRunning(ref: signpostRef, status: "Completed")
case .interrupted:
WorkflowLogger.logWorkerFinishedRunning(ref: signpostRef, status: "Interrupted")
case .failed:
WorkflowLogger.logWorkerFinishedRunning(ref: signpostRef, status: "Failed")
}
}
}

Expand Down
98 changes: 98 additions & 0 deletions swift/Workflow/Sources/WorkflowLogger.swift
Original file line number Diff line number Diff line change
@@ -0,0 +1,98 @@
/*
* Copyright 2020 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 os.signpost

fileprivate extension OSLog {
static let workflow = OSLog(subsystem: "com.squareup.Workflow", category: "Workflow")
static let worker = OSLog(subsystem: "com.squareup.Workflow", category: "Worker")
}

// MARK: -

/// Simple class that can be used to create signpost IDs based on an object pointer.
final class SignpostRef {
init() {}
}

final class WorkflowLogger {
// MARK: Workflows

static func logWorkflowStarted<WorkflowType>(ref: WorkflowNode<WorkflowType>) {
if #available(iOS 12.0, macOS 10.14, *) {
let signpostID = OSSignpostID(log: .workflow, object: ref)
os_signpost(.begin, log: .workflow, name: "Alive", signpostID: signpostID,
"Workflow: %{public}@", String(describing: WorkflowType.self))
}
}

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)
}
}

static func logSinkEvent<Action: WorkflowAction>(ref: AnyObject, action: Action) {
if #available(iOS 12.0, macOS 10.14, *) {
let signpostID = OSSignpostID(log: .workflow, object: ref)
os_signpost(.event, log: .workflow, name: "Sink Event", signpostID: signpostID,
"Event for workflow: %{public}@", String(describing: Action.WorkflowType.self))
}
}

// MARK: Rendering

static func logWorkflowStartedRendering<WorkflowType>(ref: WorkflowNode<WorkflowType>) {
if #available(iOS 12.0, macOS 10.14, *) {
let signpostID = OSSignpostID(log: .workflow, object: ref)
os_signpost(.begin, log: .workflow, name: "Render", signpostID: signpostID,
"Render Workflow: %{public}@", String(describing: WorkflowType.self))
}
}

static func logWorkflowFinishedRendering<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: "Render", signpostID: signpostID)
}
}

// MARK: - Workers

static func logWorkerStartedRunning<WorkerType>(ref: AnyObject, workerType: WorkerType.Type) {
if #available(iOS 12.0, macOS 10.14, *) {
let signpostID = OSSignpostID(log: .worker, object: ref)
os_signpost(.begin, log: .worker, name: "Running", signpostID: signpostID,
"Worker: %{public}@", String(describing: WorkerType.self))
}
}

static func logWorkerFinishedRunning(ref: AnyObject, status: StaticString) {
if #available(iOS 12.0, macOS 10.14, *) {
let signpostID = OSSignpostID(log: .worker, object: ref)
os_signpost(.end, log: .worker, name: "Running", signpostID: signpostID, status)
}
}

static func logWorkerOutput<WorkerType: Worker>(ref: AnyObject, workerType: WorkerType.Type) {
if #available(iOS 12.0, macOS 10.14, *) {
let signpostID = OSSignpostID(log: .worker, object: ref)
os_signpost(.event, log: .worker, name: "Worker Event", signpostID: signpostID,
"Event: %{public}@", String(describing: WorkerType.self))
}
}
}
12 changes: 12 additions & 0 deletions swift/Workflow/Sources/WorkflowNode.swift
Original file line number Diff line number Diff line change
Expand Up @@ -34,11 +34,17 @@ final class WorkflowNode<WorkflowType: Workflow> {
self.workflow = workflow
self.state = workflow.makeInitialState()

WorkflowLogger.logWorkflowStarted(ref: self)

subtreeManager.onUpdate = { [weak self] output in
self?.handle(subtreeOutput: output)
}
}

deinit {
WorkflowLogger.logWorkflowFinished(ref: self)
}

/// Handles an event produced by the subtree manager
private func handle(subtreeOutput: SubtreeManager.Output) {
let output: Output
Expand Down Expand Up @@ -71,6 +77,12 @@ final class WorkflowNode<WorkflowType: Workflow> {
}

func render() -> WorkflowType.Rendering {
WorkflowLogger.logWorkflowStartedRendering(ref: self)

defer {
WorkflowLogger.logWorkflowFinishedRendering(ref: self)
}

return subtreeManager.render { context in
workflow
.render(
Expand Down