Simplify finding performance problems with WithViewStore by always showing when what re-renders

[fabstu]

It is sometimes more difficult than necessary to find what WithViewStore body excessively re-renders (the only way I know is looking at the Timing Summary from Xcode Instruments/SwiftUI/ViewBody and guessing by what else re-rendered). Why don't we augment WithViewStore.body with the following line to make it print to console each time the body is re-rendered? Performance problems become glaringly obvious. The first line of a re-render hierarchy may be the culprit for the lines after (not sure whether the assumption that parent-user of WithViewStore gets re-evaluated before child is true, but we will know..).

print("WithViewStore \(file)#\(line) <\(String(reflecting: ViewState.self)), \(String(reflecting: ViewAction.self)), ...>")

Output:

WithViewStore SwiftUICaseStudies/01-GettingStarted-Counter.swift#42 <SwiftUICaseStudies.Counter.State, SwiftUICaseStudies.Counter.Action, ...>

When a view containg the WithViewStore is reused, we get into the same issue as with using WithViewStore: seeing the type in "Timing Summary" (XCode Instruments/SwiftUI/View Body) is not enough to deduce the user of the view. For such cases, we can augment the parent view with fileID and line as well. For example CounterView:

struct CounterView: View {
  let store: StoreOf<Counter>
  let file: StaticString
  let line: UInt
  
  init(store: StoreOf<Counter>,
       file: StaticString = #fileID,
       line: UInt = #line
  ) {
    self.store = store
    self.file = file
    self.line = line
  }

  var body: some View {
    WithViewStore(self.store, observe: { $0 }, content: { viewStore in
      HStack {
        Button {
          viewStore.send(.decrementButtonTapped)
        } label: {
          Image(systemName: "minus")
        }

        Text("\(viewStore.count)")
          .monospacedDigit()

        Button {
          viewStore.send(.incrementButtonTapped)
        } label: {
          Image(systemName: "plus")
        }
      }
    },  file: file, line: line)
  }
}

which then prints the user of CounterView each time the WithViewStore re-renders.

WithViewStore SwiftUICaseStudies/01-GettingStarted-Composition-TwoCounters.swift#47 <SwiftUICaseStudies.Counter.State, SwiftUICaseStudies.Counter.Action, ...>
WithViewStore SwiftUICaseStudies/01-GettingStarted-Composition-TwoCounters.swift#55 <SwiftUICaseStudies.Counter.State, SwiftUICaseStudies.Counter.Action, ...>
WithViewStore SwiftUICaseStudies/01-GettingStarted-Composition-TwoCounters.swift#55 <SwiftUICaseStudies.Counter.State, SwiftUICaseStudies.Counter.Action, ...>
WithViewStore SwiftUICaseStudies/01-GettingStarted-Composition-TwoCounters.swift#47 <SwiftUICaseStudies.Counter.State, SwiftUICaseStudies.Counter.Action, ...>
WithViewStore SwiftUICaseStudies/01-GettingStarted-Composition-TwoCounters.swift#47 <SwiftUICaseStudies.Counter.State, SwiftUICaseStudies.Counter.Action, ...>

How this should be enabled is unclear. Options I see:

• for debug enabled by default
• some global knob
• .environment recursive
• ...

The next step to do after knowing what unexpectedly re-renders can be to add Self._printChanges().

Other ideas:

• count invocations of the body and later print them out (on some trigger) combined into a single line: 53x WithViewStore SwiftUICaseStudies/01-GettingStarted-Composition-TwoCounters.swift#47 <SwiftUICaseStudies.Counter.State, SwiftUICaseStudies.Counter.Action, ...>
• somehow augment Timing Summary to include file/line numbers
• other options?

[tgrapperon]

Hey @fabstu! This is a good idea, but are you aware of the .debug() method of WithViewStore? It does more or less what you're proposing. Maybe there are ways to improve the output though.

It doesn't mean that interesting metrics like counts and timings shouldn't be observed, but I feel they could probably be more useful if defined as general utilities, out of some WithViewStore context. For example as ViewModifier.

From my experience a few months ago, Self._printChanges() wasn't very relevant if defined in WithViewStore, and I had better success in using it explicitly from client views. But it may have changed since the last time I tried.

[fabstu]

Hey @tgrapperon, thanks!, I wasn't aware of .debug(). This could be added to the performance-blogpost To summarize for myself:

• To know why a specific WithViewStore re-renders: add .debug() to it. => prints responsible state change.
• To find out which WithViewStore instances excessively re-render: enable global re-render logging with TCA.enableWithViewStoreRerenderLogging() or add .printWithViewStoreRerendersRecursively() to the suspected view hierarchy. => prints file, line and ViewState type of re-rendered WithViewStore.
• To find out whether a specific view body re-rendered: add let _ = Self._printChanges() to the top-level view body (does not show whether any child-view body, even inside the same view body, re-rendered independently). => prints CounterView: @self changed.

Not sure about the .debug() output, seems also be acceptable. You still have to know from which WithViewStore instances performance issues come from beforehand, which isn't the case with global logging.

A ViewModifier that recursively applies .debug()/printing might be more targeted and print less garbage, although the WithViewStore culprit may be missed again. Techniques like StoreIsolate breaking.environment's recursiveness might be surprising. Although with as limited use as such techniques have, we can probably just ignore those cases.

[fabstu]

Counting invocations

I extended .debug a bit since that is the current non-global version (as @tgrapperon noted that I missed). Making .debug() a ViewModifier and adding some counting shows the following.

Diff: https://github.com/pointfreeco/swift-composable-architecture/compare/0.47.2...fabstu:swift-composable-architecture:exp-render-instrumentation?expand=1

Branch based on 0.47.2: https://github.com/fabstu/swift-composable-architecture/tree/exp-render-instrumentation

Usage:

Add .tcaSettings(.withRerenderLogging(.statistics)) to a view hierarchy containing WithViewStore, best to a slow part of the app.

Example output before:

1x WithViewStore SomeType/BarView.swift#37 <Bar.State, Bar.Action, ...>
    1x (Changed state)
      Bar.State(
        availables: [
          [0]: Bar.Available(
            id: PrefixedUUID(value: "available-_A2E25FDD-ED22-4B44-A67F-964A074C3104"),
            title: "",
            nickname: "P",
            Reader: Reader.State(
              hierarchy: Hierarchy.State(…),
              outlineScrollTo: nil,
              Viewer: BookmarkBased.State(…),
              CurrentPage: CurrentPage.State(
    -           current: 11
    +           current: 12
              ),
              currentSelection: nil
            )
          ),
          [1]: Bar.Available(…)
        ],
        chosenID: PrefixedUUID(value: "available-_A2E25FDD-ED22-4B44-A67F-964A074C3104")
      )
164x WithViewStore Hierarchy/IsActiveView.swift#23 <CurrentPage<Swift.Int>.State, CurrentPage<Swift.Int>.Action, ...>
    164x (Changed state)
      CurrentPage.State(
    -   current: 11
    +   current: 12
      )
164x WithViewStore Hierarchy/HierarchyEntryView.swift#135 <Optional<Swift.Int>, CurrentPage<Swift.Int>.Action, ...>
    164x (Changed state)
    - 11
    + 12
164x WithViewStore Reader/ReaderView.swift#97 <CurrentPage<Swift.Int>.State, CurrentPage<Swift.Int>.Action, ...>
    164x (Changed state)
      CurrentPage.State(
    -   current: 11
    +   current: 12
      )

Example output after looking up parts that shouldn't be re-rendered:

164x WithViewStore Hierarchy/IsActiveView.swift#23 <CurrentPage<Swift.Int>.State, CurrentPage<Swift.Int>.Action, ...>
    164x (Changed state)
      CurrentPage.State(
    -   current: 17
    +   current: 18
      )
164x WithViewStore Reader/ReaderView.swift#97 <CurrentPage<Swift.Int>.State, CurrentPage<Swift.Int>.Action, ...>
    164x (Changed state)
      CurrentPage.State(
    -   current: 17
    +   current: 18
      )

The whole thing is pretty illuminating. I instantly found two places that shouldn't re-render. What especially stands out is parts with the big diffs. These might have to be scoped more in the first place.

Notes

internal views not setting their Prefix and not taking file/line/prefix arguments.

Added some to

• ForEachStore
• IfLetStore
• SwitchStore (inconsistent position of file/line/prefix, sometimes in middle and sometimes at the end) (sometimes having file+fileID, while I mostly use file: StaticStirng = #fileID)

ForEachStore always printing its changes because we pass the "ForEachStore" prefix to WithViewStore

• Strategy: Have a prefix: String? = "IfLetStore"/"ForEachStore" parameter.

Startup initialization logging of "(initial state)" can be very verbose with lots of data and unique views (each with its own ID).

For example an IfLetStore having an (Initial state) of the whole thing that it watches, despite only passing down a store.

1x IfLetStore SomeType/SomeTypeView.swift#66 <Optional<ChaosNotes.PDFBar.AvailablePDF>, PDFBar.AvailablePDFAction, ...>
    1x (Initial state)
      PDFBar.AvailablePDF(
        id: PrefixedUUID(value: "available-pdf_613EE8E6-3FBC-4A16-828B-1034D342CDE6"),
[1000+ more lines for the IfLetStore]

Options:

1. We can ignore them all, but then cascading re-renders won't be as visible.
2. Combine "(Initial state)" diffs to one count without the initial state.
3. Make this configurable. <- available as a flag.
4. Hide all "(Initial state)" at startup.
5. When certain line-limit is reached, hiderest of Initial state diffs or combine rest of diffs to counters.

The flag .withInitialStateHideDiffs() cleans that up nicely.

.tcaSettings(
      .withRerenderLogging(.statistics)
      .withInitialStateHideDiffs()
)

1x WithViewStore Interleaf/ContextView.swift#53 <ItemViewState.Context, Item.Action, ...>
    1x (Initial state) [diffs hidden]
1x WithViewStore Interleaf/ContextView.swift#54 <ThreadReducer.State, ThreadReducer.Action, ...>
    1x (Initial state) [diffs hidden]
1x ForEachStore Interleaf/ItemView.swift#112 <OrderedSet<PrefixedUUID.PrefixedUUID>, PrefixedUUID, Interleaf.Item.Action), ...>
    1x (Initial state) [diffs hidden]

Ignoring .debug() due to use of prefix everywhere.

<iOS15 and <macOS12 need to start the printer manually, which is otherwise integrated in .tcaSettings with .task{}.

Had to increase min macOS version to 11 that enables else-clause for if #available.