Investigation: timers synchronization #33

ball-hayden · 2022-04-16T17:19:22Z

Various thoughts while investigating wix/Detox#3207

Best reviewed commit-by-commit.

Thoughts and explanations are left as comments inline.

ball-hayden · 2022-04-16T17:21:17Z

DetoxSync/DetoxSync/Spies/NSTimer+DTXSpy.m

@@ -72,6 +72,9 @@ CFRunLoopTimerRef __detox_sync_CFRunLoopTimerCreate(CFAllocatorRef allocator, CF
 static CFRunLoopTimerRef (*__orig_CFRunLoopTimerCreateWithHandler)(CFAllocatorRef allocator, CFAbsoluteTime fireDate, CFTimeInterval interval, CFOptionFlags flags, CFIndex order, void (^block) (CFRunLoopTimerRef timer));
 CFRunLoopTimerRef __detox_sync_CFRunLoopTimerCreateWithHandler(CFAllocatorRef allocator, CFAbsoluteTime fireDate, CFTimeInterval interval, CFOptionFlags flags, CFIndex order, void (^block) (id timer))
 {
+	NSLog(@"🤔 CFRunLoopTimerCreateWithHandler");
+
+	// What is this doing? We don't seem to be creating a trampoline here - I feel like we should be?
 	return (__bridge_retained CFRunLoopTimerRef)[[NSTimer alloc] initWithFireDate:CFBridgingRelease(CFDateCreate(allocator, fireDate)) interval:interval repeats:interval > 0 block:block];


I don't understand why we're swizzling CFRunLoopTimerCreateWithHandler without adding any tracking for these timers (as far as I can tell).

Unless initWithFireDate somehow ends up calling CFRunLoopTimerCreate?

This happens a lot when running the Detox example app.
I don't understand what this is doing.

Unless initWithFireDate somehow ends up calling CFRunLoopTimerCreate

Probably yes. This can be easily checked by putting a breakpoint on __detox_sync_CFRunLoopTimerCreate.
https://github.com/wix/DetoxSync/tree/master/ExampleApp

ball-hayden · 2022-04-16T17:23:34Z

DetoxSync/DetoxSync/Spies/NSTimer+DTXSpy.m

 	id<DTXTimerProxy> trampoline = [DTXTimerSyncResource existingTimerProxyWithTimer:NS(timer)];
-	[trampoline untrack];
-
 	__orig_CFRunLoopRemoveTimer(rl, timer, mode);
+
+	[trampoline untrack];


I've observed that [_DTXTimerTrampoline fire:] is called after the trampoline has been untracked (and therefore dealloced).

By switching these, I was hoping that the timer would be cancelled (ensuring that the fire method is not called after untracking).

This doesn't seem to be the case, and I'm still seeing fire called after the trampoline has been untracked, but it still feels safer to me to remove the timer before untracking?

Untracking the timer only after removing it from the runloop does make sense, but I'm not sure if it matters.

[_DTXTimerTrampoline fire:] is called after the trampoline has been untracked

That's very weird. 🤔

Maybe the thread where this timer was created and the thread where the timer was called to invalidate are different?

Apple docs (invalidate()):

You must send this message from the thread on which the timer was installed. If you send this message from another thread, the input source associated with the timer may not be removed from its run loop, which could prevent the thread from exiting properly.

ball-hayden · 2022-04-16T17:24:26Z

DetoxSync/DetoxSync/Spies/NSTimer+DTXSpy.m

+- (void)dealloc
+{
+    id<DTXTimerProxy> trampoline = [DTXTimerSyncResource existingTimerProxyWithTimer:self];
+
+    if(trampoline) {
+        NSLog(@"🤦‍♂️ dealloc, but trampoline was still active: %@", self);
+        [trampoline untrack];
+    }
+}


I think adding this makes it safe to remove _DTXCleanTimersAndReturnCount (since we've then got a nicer way of calling untrack if the timer is dealloced)?

Make sense.

DetoxSync/DetoxSync/Utils/_DTXTimerTrampoline.m

ball-hayden · 2022-04-16T17:26:48Z

DetoxSync/DetoxSync/Utils/_DTXTimerTrampoline.m

@@ -86,8 +86,8 @@ - (BOOL)isDead

 - (void)dealloc
 {
-	[self untrack];


If I understand properly, the only time we should be deallocing is when the Trampoline is removed from DTXTimerSyncResource _timers?

For us to have done that, we must have called untrack already.

That's what I understand as well. I will revisit this and make sure that's indeed the case but generally I think you're right.

ball-hayden · 2022-04-16T17:27:10Z

DetoxSync/DetoxSync/Utils/_DTXTimerTrampoline.m

@@ -86,8 +86,8 @@ - (BOOL)isDead

 - (void)dealloc
 {
-	[self untrack];
-
+	NSLog(@"🤦‍♂️ trampoline dealloc: %@ (tracking: %d)", self, _tracking);


(I added this to verify the assumption above. I've not seen this called with tracking YES).

ball-hayden · 2022-04-16T17:28:30Z

DetoxSync/DetoxSync/Utils/_DTXTimerTrampoline.m

@@ -112,47 +112,24 @@ - (void)setDisplayLink:(CADisplayLink*)displayLink
 #endif
 }

- (void)fire:(id)timer
+- (void)fire


The following changes are a bit more involved.

Firstly, there's no need for the timer parameter - we already have a reference to that as an ivar.

I can understand why the timer argument is redundant.

ball-hayden · 2022-04-16T17:31:59Z

DetoxSync/DetoxSync/Utils/_DTXTimerTrampoline.m

-	//This is to ensure the timer is still valid after fire.
-	CFRunLoopRef runloop = CFRunLoopGetCurrent();
-	CFRunLoopMode mode = CFRunLoopCopyCurrentMode(runloop);
-	CFRunLoopPerformBlock(runloop, mode, ^{
-		if(CFRunLoopTimerIsValid((__bridge CFRunLoopTimerRef)timer) == NO)
-		{
-			[self untrack];
-
-			CFRelease(mode);
-
-			return;
-		}
-
-		CFRunLoopPerformBlock(runloop, mode, ^{
-			if(CFRunLoopTimerIsValid((__bridge CFRunLoopTimerRef)timer) == NO)
-			{
-				[self untrack];
-
-				CFRelease(mode);
-
-				return;
-			}
-
-			CFRelease(mode);
-		});
-	});


If I understand right, the purpose of these are to see if the timer is still valid after it has fired.

If we ask if the timer is valid inline here, CFRunLoopTimerIsValid always evaluates to true, I assume because we're still within the fire function.

Here I'm proposing a different method.

We track the invalidation and removal of timers (in NSTimer+DTXSpy.m), which means we know when a repeating timer is stopping. We also know that a timer that doesn't repeat is finished once we have called its callback (or selector).

Therefore, we can simply call untrack if we are not a recurring timer after we have called its callback.

As far as I understand, this code checks whether the timer needs to be untracked (for example, as you mentioned - in case of a non-repeating timer) immediately after finishing the fire.

Therefore, we can simply call untrack if we are not a recurring timer after we have called its callback.

Generally, this sounds right, but I'm not sure if recurring / non-recurring is our only flow. What about calling to CFRunLoopTimerInvalidate on the 3rd fire or something?

Calling CFRunLoopTimerInvalidate will result in an explicit call to untrack from the spy:

https://github.com/PlayerData/DetoxSync/blob/f5cd8cbde60311bb8e41df7c773850cd73c8f84b/DetoxSync/DetoxSync/Spies/NSTimer%2BDTXSpy.m#L108

ball-hayden · 2022-04-16T17:32:43Z

DetoxSync/DetoxSync/Utils/_DTXTimerTrampoline.m

+	if(_target && _sel) {
+		IMP impl = [_target methodForSelector:_sel];
+		void (*func)(id, SEL, NSTimer*) = (void *)impl;
+		func(_target, _sel, _timer);
+	}


This is a small tidy-up recommended by https://stackoverflow.com/a/20058585

ball-hayden · 2022-04-16T17:33:10Z

DetoxSync/DetoxSync/Utils/_DTXTimerTrampoline.m

-  return @{
-    @"fire_date": _fireDate ? [_DTXTimerTrampoline._descriptionDateFormatter stringFromDate:_fireDate] : @"none",
-    @"time_until_fire": @(_timeUntilFire),
-    @"is_recurring": @(_repeats),
-    @"repeat_interval": @(_ti)
-  };
+	return @{
+		@"fire_date": _fireDate ? [_DTXTimerTrampoline._descriptionDateFormatter stringFromDate:_fireDate] : @"none",
+		@"time_until_fire": @(_timeUntilFire),
+		@"is_recurring": @(_repeats),
+		@"repeat_interval": @(_ti)
+	};


The rest of the file is indented using tabs. Fixed for consistency (and editor happiness).

Legit 👍
To be honest, I hate tabs, but I prefer consistency over inconsistency.

asafkorem · 2022-04-17T08:41:15Z

Thanks @ball-hayden, you definitely raised some interesting points. I need to dive deep into this to have a significant input on that subject. I'll start review this later today 🙂

ball-hayden · 2022-04-18T15:06:32Z

DetoxSync/DetoxSync/Utils/_DTXTimerTrampoline.m

-	objc_setAssociatedObject(_displayLink, __DTXTimerTrampolineKey, self, OBJC_ASSOCIATION_RETAIN_NONATOMIC);
+	objc_setAssociatedObject(_displayLink, __DTXTimerTrampolineKey, self, OBJC_ASSOCIATION_RETAIN);


NONATOMIC could cause races when looking up the associated trampoline.

ball-hayden · 2022-04-18T15:15:22Z

DetoxSync/DetoxSync/Utils/_DTXTimerTrampoline.m

-	__weak NSTimer* _timer;
+	NSTimer* _timer;


Ensure that we still have a reference to the _timer object until we are done.

This might be a bad idea - I'm a bit unsure as to whether this leaves us with a circular dependency between us and the timer for releasing?

…ng) TimerTrampolines

…sues

…object

…efined

…ciated object

asafkorem · 2022-04-20T11:23:55Z

DetoxSync/DetoxSync/Utils/_DTXTimerTrampoline.m

@@ -112,47 +112,24 @@ - (void)setDisplayLink:(CADisplayLink*)displayLink
 #endif
 }

- (void)fire:(id)timer
+- (void)fire


I can understand why the timer argument is redundant.

asafkorem · 2022-04-20T11:27:48Z

DetoxSync/DetoxSync/Utils/_DTXTimerTrampoline.m

-	//This is to ensure the timer is still valid after fire.
-	CFRunLoopRef runloop = CFRunLoopGetCurrent();
-	CFRunLoopMode mode = CFRunLoopCopyCurrentMode(runloop);
-	CFRunLoopPerformBlock(runloop, mode, ^{
-		if(CFRunLoopTimerIsValid((__bridge CFRunLoopTimerRef)timer) == NO)
-		{
-			[self untrack];
-
-			CFRelease(mode);
-
-			return;
-		}
-
-		CFRunLoopPerformBlock(runloop, mode, ^{
-			if(CFRunLoopTimerIsValid((__bridge CFRunLoopTimerRef)timer) == NO)
-			{
-				[self untrack];
-
-				CFRelease(mode);
-
-				return;
-			}
-
-			CFRelease(mode);
-		});
-	});


As far as I understand, this code checks whether the timer needs to be untracked (for example, as you mentioned - in case of a non-repeating timer) immediately after finishing the fire.

Therefore, we can simply call untrack if we are not a recurring timer after we have called its callback.

Generally, this sounds right, but I'm not sure if recurring / non-recurring is our only flow. What about calling to CFRunLoopTimerInvalidate on the 3rd fire or something?

asafkorem · 2022-04-20T11:29:44Z

DetoxSync/DetoxSync/Utils/_DTXTimerTrampoline.m

+	if(!_repeats) {
+		[self untrack];
 	}


I'm not sure if this will have the same result as the previous check.

asafkorem · 2022-04-20T11:31:02Z

DetoxSync/DetoxSync/Utils/_DTXTimerTrampoline.m

-#pragma clang diagnostic push
-#pragma clang diagnostic ignored "-Warc-performSelector-leaks"
-	[_target performSelector:_sel withObject:timer];
-#pragma clang diagnostic pop


why did you removed this? I guess it was there for a reason

This is replaced by ln 131-138 - gaining a reference to impl explicitly is recommended.

I think my previous comment was lost - sorry.

It wasn't, you're right #33 (comment), forgot about this for a moment 😅

asafkorem · 2022-04-20T12:16:54Z

@ball-hayden That's very impressive. You brought up a lot of questions here, I left a few comments with thoughts back. I'll continue the review next week.

Note that I'm not very proficient in this code territory, since I wasn't involved at any point in writing it, as you can see there isn't much documentation or logical separation into commits.. this is definitely a weak spot on this massive (and impressive) project (DetoxSync) 😅

Anyway I'll try my best to help in this investigation, another note that it might take me some time to answer as we are both under-capacity and the fact that it takes time to get into things 🙂

ball-hayden · 2022-04-21T15:49:42Z

Thanks @asafkorem.

For the avoidance of doubt, I'm not expecting to merge this PR - it's entirely for discussion and ideas.

As I mentioned in wix/Detox#3207 (comment) I'm afraid I'm also having to leave this alone in work time - there isn't the business appetite to spend more time on it at the moment.

I'll continue to try and keep some thoughts out of hours though - it's an interesting problem and I'd love to know what the root cause actually is.

asafkorem · 2022-05-11T07:11:13Z

DetoxSync/DetoxSync/SyncResources/DTXUISyncResource.m

-		[self _untrackForParam:&_viewNeedsLayoutCount eventIdentifier:_DTXStringReturningBlock(identifier)];
+		[self _untrackForParam:&self->_viewNeedsLayoutCount eventIdentifier:_DTXStringReturningBlock(identifier)];


being explicit in such cases is indeed better

but except for being more explicit, is there any other goal in this change? What exactly is the fix here?

Ah, yes. Sorry. This fixes an XCode warning:
https://github.com/wix/DetoxSync/pull/33/files#diff-08fdd5ea3608159a1a2dcf8f2badd094a37e7752afd55967213368f32ae64c68L1227

asafkorem · 2022-05-11T08:02:48Z

@ball-hayden thanks again for this investigation and the refactoring suggestions! 🚀

I believe some of the fixes here can be extracted into smaller PRs.
If you'd like to do so, I would love to start merging some of the changes, like this one: 716e2a7 🙂

asafkorem · 2022-05-11T08:05:19Z

Have you tried running all the changes with detox, specifically with our tests suite?

ball-hayden commented Apr 16, 2022

View reviewed changes

DetoxSync/DetoxSync/Utils/_DTXTimerTrampoline.m Show resolved Hide resolved

ball-hayden commented Apr 16, 2022

View reviewed changes

ball-hayden mentioned this pull request Apr 16, 2022

Signal 11 crash still present after SIMCTL_CHILD_NSZombieEnabled=YES + latest Firebase version wix/Detox#3207

Open

2 tasks

asafkorem self-assigned this Apr 17, 2022

ball-hayden commented Apr 18, 2022

View reviewed changes

ball-hayden added 8 commits April 18, 2022 16:16

refactor(_DTXTimerTrampoline): Simplify [_DTXTimerTrampoline fire:]

d5de41e

style(_DTXTimerTrampoline): Correct indentation

129ed8c

doc(NSTimer+DTXSpy): What is going on?

d3c2af4

fix(NSTimer+DTXSpy): Invalidate timers before untracking (and releasi…

2100b7b

…ng) TimerTrampolines

fix(NSTimer+DTXSpy): Tidy dealloc tracking for NSTimers

b5677c7

refactor(DTXUISyncResource): Reenable IMPLICIT_RETAIN_SELF and fix is…

716e2a7

…sues

fix(_DTXTimerTrampoline): Correct removal of display link associated …

a4aa2d5

…object

refactor(_DTXTimerTrampoline): Remove unused _timerDescription var

ef92890

ball-hayden force-pushed the timer-simplify branch from 3dc80e1 to ef92890 Compare April 18, 2022 15:17

ball-hayden added 3 commits April 18, 2022 16:31

fix(DTXTimerTrampoline): HACK: Only fire timer callback if timer is d…

8b9d012

…efined

fixup! fix(_DTXTimerTrampoline): Correct removal of display link asso…

ee5c6a0

…ciated object

fix(DTXTimerTrampoline): HACK: throw if no implementation for selector

f2b47c5

asafkorem reviewed Apr 20, 2022

View reviewed changes

asafkorem changed the title ~~Timer simplify~~ Investigation: timers synchronization May 2, 2022

asafkorem reviewed May 11, 2022

View reviewed changes

		objc_setAssociatedObject(_displayLink, __DTXTimerTrampolineKey, self, OBJC_ASSOCIATION_RETAIN_NONATOMIC);
		objc_setAssociatedObject(_displayLink, __DTXTimerTrampolineKey, self, OBJC_ASSOCIATION_RETAIN);

		[self _untrackForParam:&_viewNeedsLayoutCount eventIdentifier:_DTXStringReturningBlock(identifier)];
		[self _untrackForParam:&self->_viewNeedsLayoutCount eventIdentifier:_DTXStringReturningBlock(identifier)];

Investigation: timers synchronization #33

Are you sure you want to change the base?

Investigation: timers synchronization #33

Conversation

ball-hayden commented Apr 16, 2022

Choose a reason for hiding this comment

ball-hayden Apr 18, 2022 • edited Loading

Choose a reason for hiding this comment

asafkorem Apr 20, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

asafkorem Apr 20, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ball-hayden Apr 16, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

asafkorem commented Apr 17, 2022

Choose a reason for hiding this comment

ball-hayden Apr 18, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

asafkorem commented Apr 20, 2022 • edited Loading

ball-hayden commented Apr 21, 2022

asafkorem May 11, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

asafkorem commented May 11, 2022

asafkorem commented May 11, 2022

ball-hayden Apr 18, 2022 •

edited

Loading

asafkorem Apr 20, 2022 •

edited

Loading

asafkorem Apr 20, 2022 •

edited

Loading

ball-hayden Apr 16, 2022 •

edited

Loading

ball-hayden Apr 18, 2022 •

edited

Loading

asafkorem commented Apr 20, 2022 •

edited

Loading

asafkorem May 11, 2022 •

edited

Loading