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 = NSObject()
Copy link
Contributor

Choose a reason for hiding this comment

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

Wonder if we should create a type which has the log... events and acts as a ref instead of creating an arbitrary object to act as ref.

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 not overly-concerned about it. We could make the log... calls member functions instead of static functions (and use the object as the object we use to look up the signpost ID. We'd have to figure out how to plumb that object around to the various places that need it.

I think this is fine for now. Thoughts?

Copy link
Contributor

Choose a reason for hiding this comment

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

I meant, creating something like:

class SignpostRef: AnyObject {
  func log(...)
}

But, this is just a nit, feel free to ship as-is!


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 = NSObject()
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, output: output)

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)
case .interrupted:
WorkflowLogger.logWorkerFinishedRunning(ref: signpostRef, status: "Interrupted")
case .failed:
WorkflowLogger.logWorkerFinishedRunning(ref: signpostRef, status: "Failed")
}
}
}

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

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>(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: %@", String(describing: action))
}
}

// 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? = nil) {
if #available(iOS 12.0, macOS 10.14, *) {
let signpostID = OSSignpostID(log: .worker, object: ref)
if let status = status {
os_signpost(.end, log: .worker, name: "Running", signpostID: signpostID, status)
} else {
os_signpost(.end, log: .worker, name: "Running", signpostID: signpostID)
}
}
}

static func logWorkerOutput<Output>(ref: AnyObject, output: Output) {
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: %@", String(describing: output))
}
}
}
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