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

[ASDataController] Add event logging for transaction queue flush duration #trivial #334

Merged
merged 4 commits into from
Jun 21, 2017

Conversation

hannahmbanana
Copy link
Contributor

@hannahmbanana hannahmbanana commented Jun 6, 2017

One of the most common performance problems in a Texture app occurs when a developer makes multiple edit transactions to a collection / table right after each other, before the processing of the previous operation is finished. In this case, Texture blocks on the completion of the current edit operation, even though it would have been asynchronous if the second / subsequent operation had not been started.

The ASEventLog provides the ability to capture the information on this subtle perf issue. In the -ASDataController updateWithChangeSet: method, we can time the duration of the dispatch group wait of the editing transaction queue and log both the time as well as the stack trace so the developer can see which edit operations are triggering performance issues.

@hannahmbanana hannahmbanana changed the title Add event logging for transaction queue flush duration [ASDataController] Add event logging for transaction queue flush duration Jun 6, 2017
@hannahmbanana hannahmbanana changed the title [ASDataController] Add event logging for transaction queue flush duration [ASDataController] Add event logging for transaction queue flush duration #trivial Jun 6, 2017
@@ -485,7 +486,11 @@ - (void)updateWithChangeSet:(_ASHierarchyChangeSet *)changeSet
_initialReloadDataHasBeenCalled = YES;
}

dispatch_group_wait(_editingTransactionGroup, DISPATCH_TIME_FOREVER);
NSTimeInterval transactionQueueFlushDuration;
Copy link
Member

Choose a reason for hiding this comment

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

Add an initialization, = 0.0f; This would be initialized to 0 automatically if an instance variable, but in this case it's technically needed.

@@ -498,7 +503,7 @@ - (void)updateWithChangeSet:(_ASHierarchyChangeSet *)changeSet
[self invalidateDataSourceItemCounts];

// Log events
ASDataControllerLogEvent(self, @"triggeredUpdate: %@", changeSet);
ASDataControllerLogEvent(self, @"triggeredUpdate (waited on editing queue for %@ms): %@", transactionQueueFlushDuration * 1000, changeSet);
Copy link
Member

Choose a reason for hiding this comment

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

Change %@ms to %fms

@hannahmbanana
Copy link
Contributor Author

@appleguy: The event log shows fractions of a ms, while the console log timestamp shows ~100+ms. Any ideas?

Copy link
Member

@nguyenhuy nguyenhuy left a comment

Choose a reason for hiding this comment

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

Nice diff!

@nguyenhuy nguyenhuy merged commit 2dca3e5 into TextureGroup:master Jun 21, 2017
@hannahmbanana
Copy link
Contributor Author

@nguyenhuy - FYI, this logging may be incorrect - I suspect it's understating the number of ms. @appleguy - did you have a chance to take a look at some test values?

bernieperez pushed a commit to AtomTickets/Texture that referenced this pull request Apr 25, 2018
…tion #trivial (TextureGroup#334)

* Add event logging for transaction queue flush duration

* address @appleguy's comments

* Improve formatting of Event Log messages

* Small indentation fix in ASDataController
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants