Bug 29726

Summary: NSTimer stops if tick handler processing takes long time but only in 32-bit ARMv7 code
Product: iOS Reporter: Ales Suchac <ales>
Component: GeneralAssignee: Zoltan Varga <vargaz>
Status: VERIFIED FIXED    
Severity: normal CC: ddavletov, lluis, mono-bugs+monodevelop, mono-bugs+monotouch, parmendrak, rolf, sebastien, udhams
Priority: Normal    
Version: master   
Target Milestone: Untriaged   
Hardware: PC   
OS: Mac OS   
Tags: Is this bug a regression?: ---
Last known good build:
Attachments: TestCase.zip

Description Ales Suchac 2015-05-04 21:06:39 UTC
Description of Problem:

I have an IOS app InspectorSherlock out in the app store for 4 years. Now after conversion to unified API, built for ARMv7 + ARM64 I've found that NSTimer stops when the tick handler runs a code whose execution takes longer time than the tick. In my case, the tick period is 100 ms and the task took about 3 seconds.

What is funny is that this happens only on Apple's 32-bit CPUs, particularly A5. When running the same code on simulators or iPhone 6 everything was fine. 

Note - this NSTimer stopping never happened before, on any hardware.

I've run this in debug mode and when the timer stopped, the app actually ran so I clicked pause button in Xamarin Studio and it came out with the following call stack:

System.Threading.WaitHandle.WaitOne_internal () in 
System.Threading.WaitHandle.WaitOne (millisecondsTimeout=Value not available, exitContext=Value not available) in /Users/builder/data/lanes/1503/6481535e/source/mono/mcs/class/corlib/System.Threading/WaitHandle.cs:375
System.Threading.WaitHandle.WaitOne (millisecondsTimeout=Value not available) in /Users/builder/data/lanes/1503/6481535e/source/mono/mcs/class/corlib/System.Threading/WaitHandle.cs:388
System.Threading.Timer.Scheduler.SchedulerThread () in /Users/builder/data/lanes/1503/6481535e/source/mono/mcs/class/corlib/System.Threading/Timer.cs:395
System.Threading.Thread.StartInternal () in /Users/builder/data/lanes/1503/6481535e/source/mono/mcs/class/corlib/System.Threading/Thread.cs:696

I thought that maybe the problem had something with threading, as I do update UI from the NSTimer event handler, but:

1. It never happened before and it is not happening on any other platform but ARMv7
2. When the tick processing didn't take long, the timer kept ticking even when updating UI
3. Encapsulating the code in InvokeOnMainThread didn't fix the problem.

Steps to reproduce the problem:
Have NSTimer do some long processing inside the event handler.
Unfortunately I am under time pressure so I don't have time to develop testing app to prove my point.

How often does this happen?
Each time when you process something in NSTimer event handler which takes significantly longer than the tick period - but only on 32-bit ARM CPUs in IOS. 
This behavior emerged only after converting an existing app to unified API ARMv7 + ARM64 in Xamarin Studio 5.9 build 431. 


Additional Information:
I have a workaround: when the long processing inside the event handler finishes, I restart the timer - the following code is called from inside the handler:

                if (xferTimer != null)
                {
                    if (xferTimer.IsValid)
                        xferTimer.Invalidate();
                    xferTimer = null;
                }

                xferTimer = NSTimer.CreateRepeatingScheduledTimer(TimeSpan.FromMilliseconds(100.0), OnXferTimerTick);
Comment 1 Sebastien Pouliot 2015-05-07 17:20:06 UTC
That's strange the old (classic) 32bits and new (unified) 32bits should be identical in this case.

Your stacktrace shows .NET BCL code while you're using the native `NSTimer`, it might not be related at all.

Can you create a small test case for this ? just so we can be sure to check the right API involved.

Also if you can tell us which hardware with the iOS version affected we'll do our best to duplicate this as closely as possible. Thanks.
Comment 2 Sebastien Pouliot 2015-05-14 10:39:22 UTC
@Ales thanks for providing a test case (out of band). I can duplicate the issue locally using it.
Comment 3 Sebastien Pouliot 2015-05-14 11:10:08 UTC
It seems something is causing our internal dispatcher to be finalized - even if the NSTimer instance is still alive.

2015-05-14 10:56:48.634 InspectorSherlock[3813:1759925] NSTimerActionDispatcher .Dispose    at System.Environment.get_StackTrace () in /Users/poupou/git/xamarin/mono/mcs/class/corlib/System/Environment.cs:line 321
   at Foundation.NSTimerActionDispatcher.Dispose (Boolean disposing) in /Users/poupou/git/xamarin/maccore/src/Foundation/NSAction.cs:line 114
   at Foundation.NSObject.Finalize () in /Users/poupou/git/xamarin/maccore/src/Foundation/NSObject2.cs:line 127

Once that happens the timer becomes useless (nothing to fire into).
Comment 4 Sebastien Pouliot 2015-05-14 14:20:21 UTC
xamarin_release_trampoline (__Xamarin_NSTimerActionDispatcher Handle=0x190b3b70) retainCount=3; HasManagedRef=1 GCHandle=99
xamarin_retain_trampoline  (__Xamarin_NSTimerActionDispatcher Handle=0x190b3b70) initial retainCount=2; new retainCount=3 HadManagedRef=1 HasManagedRef=1 old GCHandle=99 new GCHandle=99
2015-05-14 14:14:35.831 InspectorSherlock[3948:1797788] NSTimerActionDispatcher.Fire 3
2015-05-14 14:14:35.832 InspectorSherlock[3948:1797788] OnXferTimerTick 419552608 = True
2015-05-14 14:14:42.650 InspectorSherlock[3948:1797820] NSTimerActionDispatcher .Dispose 1
   at System.Environment.get_StackTrace () in /Users/poupou/git/xamarin/mono/mcs/class/corlib/System/Environment.cs:line 321
   at Foundation.NSTimerActionDispatcher.Dispose (Boolean disposing) in /Users/poupou/git/xamarin/maccore/src/Foundation/NSAction.cs:line 114
   at Foundation.NSObject.Finalize () in /Users/poupou/git/xamarin/maccore/src/Foundation/NSObject2.cs:line 127

^ our retain/release trampolines are not called between the last fire event and the finalization - but we end up with a RC of 1 and (as expected) finalize the instance.

I wonder if that could related to another (life cycle) issues that Rolf is investigating ?
Comment 5 Rolf Bjarne Kvinge [MSFT] 2015-05-25 08:55:54 UTC
@Zoltan, can you have a look?

What happens is that we're not preserving the d8 register when an exception occurs, which ends up confusing native code.
Comment 6 Rolf Bjarne Kvinge [MSFT] 2015-05-25 08:56:41 UTC
Created attachment 11315 [details]
TestCase.zip
Comment 7 Rolf Bjarne Kvinge [MSFT] 2015-05-25 08:59:11 UTC
@Zoltan, this looks like an ARMv7 codegen bug somewhere.

To repro just run the test case from comment 6 on device. You should get "Tick" printed to the console repeatedly, but it's only printed once.

This is because the iOS tick processor method stores the interval in the d8 register before calling the callback, then reads it afterwards, and if the value is 0, the handler is canceled. The problem is that we overwrite whatever's in d8 with 0 when an exception occurs.
Comment 8 Rolf Bjarne Kvinge [MSFT] 2015-05-25 09:00:15 UTC
*** Bug 7410 has been marked as a duplicate of this bug. ***
Comment 9 Zoltan Varga 2015-05-25 11:01:02 UTC
Fixed in mono master 3e8becd92b93ac396e9d40228fb370c59482d738.
Comment 11 Parmendra Kumar 2015-05-27 09:40:56 UTC
I have checked this issue with monotouch-8.11.0.868  and observed that "Tick" printed to the console repeatedly.

Screeencast: http://www.screencast.com/t/FpPuxKMQveI

Hence closing this issue.

Please let me know if I have to check something else regarding this issue.

Environment info:

Xamarin.iOS : 8.11.0.868 (Enterprise Edition)
Xamarin Studio 5.9.1 (build 3)
Mono 4.0.0 ((detached/d136b79)
GTK+ 2.24.23 (Raleigh theme)
Package version: 400000143
Xcode 6.2 (6776)
Mac OS X 10.9.4