search

e-mission / e-mission-data-collection

Repository for our own data collection
BSD 3-Clause "New" or "Revised" License
4 stars 19 forks source link

iOS native code init takes a long time #95

Open shankari opened 8 years ago

shankari commented 8 years ago

Specially when the app is launched in the background, app init sometimes takes ~ 10-20 minutes. Here's one instance.

8246    2016-02-24 13:29:37.780600-08:00    Received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START
8247    2016-02-24 13:29:37.946080-08:00    started fine location tracking
8248    2016-02-24 13:29:38.059400-08:00    Received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START
8249    2016-02-24 13:29:38.335780-08:00    Moved from STATE_WAITING_FOR_TRIP_START to STATE_ONGOING_TRIP
8250    2016-02-24 13:29:38.358590-08:00    Received notification T_TRIP_STARTED while processing silent push notification
8251    2016-02-24 13:29:38.570830-08:00    Considering region with id = STATIONARY_GEOFENCE_LOCATION, location -121.889543, 37.331404
8252    2016-02-24 13:29:38.591660-08:00    Deleting it!!
8253    2016-02-24 13:29:38.614080-08:00    Received transition T_TRIP_STARTED in state STATE_ONGOING_TRIP
8254    2016-02-24 13:29:38.660030-08:00    Received notification T_TRIP_STARTED while processing silent push notification
8255    2016-02-24 13:29:38.682070-08:00    Received notification T_EXITED_GEOFENCE while processing silent push notification
8256    2016-02-24 13:29:38.713460-08:00    Current state of region STATIONARY_GEOFENCE_LOCATION is 2 (outside)
8257    2016-02-24 13:29:38.729120-08:00    Received OUTSIDE geofence state when currState = STATE_ONGOING_TRIP
8258    2016-02-24 13:29:38.844450-08:00    Received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP
8259    2016-02-24 13:29:39.007380-08:00    Received notification T_TRIP_RESTARTED while processing silent push notification
8260    2016-02-24 13:29:39.043600-08:00    Successfully registered remote push notifications with parse
8261    2016-02-24 13:29:39.061620-08:00    Recieved location <+37.32935173,-121.89529055> +/- 65.00m (speed -1.00 mps / course -1.00) @ 2/24/16, 1:36:37 PM Pacific Standard Time, ongoing trip = true
8262    2016-02-24 13:44:19.405650-08:00    finished init of iOS native code
8263    2016-02-24 13:44:19.508920-08:00    Application launched with LaunchOptionsLocationKey = YES
8264    2016-02-24 13:44:19.527900-08:00    tripDiaryStateMachine = (null), relaunchLocationManager = 1, recreating the state machine
8265    2016-02-24 13:44:19.584380-08:00    Restart = 1, initializing TripDiaryStateMachine with state = STATE_ONGOING_TRIP
8266    2016-02-24 13:44:19.605660-08:00    started fine location tracking

Because of this, the trip back from the tech was largely a straight line with very little data. Need to investigate why this happens.

shankari commented 8 years ago

But there was a

8247    2016-02-24 13:29:37.946080-08:00    started fine location tracking

earlier. Why didn't we start fine location tracking at that point? It looks like we really started getting updates only after the application relaunched 

8263    1.456351e+09    2016-02-24 13:44:19.508920-08:00    Application launched with LaunchOptionsLocationKey = YES
8264    1.456351e+09    2016-02-24 13:44:19.527900-08:00    tripDiaryStateMachine = (null), relaunchLocationManager = 1, recreating the state machine
8265    1.456351e+09    2016-02-24 13:44:19.584380-08:00    Restart = 1, initializing TripDiaryStateMachine with state = STATE_ONGOING_TRIP
8266    1.456351e+09    2016-02-24 13:44:19.605660-08:00    started fine location tracking
8269    1.456351e+09    2016-02-24 13:44:20.667830-08:00    Recieved location <+37.32935173,-121.89529055> +/- 65.00m (speed -1.00 mps / course -1.00) @ 2/24/16, 1:36:37 PM Pacific Standard Time, ongoing trip = true
...
shankari commented 8 years ago

These are the raw logs that I'm pulling this from. no_remote_push_withdate.log.zip

shankari commented 8 years ago

Case 1:

4850,1456175166.55,2016-02-22 12:59:06.550150-08:00,Received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START
4851,1456175166.8,2016-02-22 12:59:06.803240-08:00,started fine location tracking
...
4864,1456175167.75,2016-02-22 12:59:07.754280-08:00,"Recieved location <+37.39510094,-122.08353941> +/- 65.00m (speed -1.00 mps / course -1.00) @ 2/22/16, 1:06:06 PM Pacific Standard Time, ongoing trip = true"
4865,1456175167.8,2016-02-22 12:59:07.804420-08:00,"Recieved location <+37.39510094,-122.08353941> +/- 65.00m (speed -1.00 mps / course -1.00) @ 2/22/16, 1:06:06 PM Pacific Standard Time, ongoing trip = true"

Case 2:

5047,1456184130.18,2016-02-22 15:28:30.177300-08:00,Received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START
5048,1456184130.47,2016-02-22 15:28:30.471080-08:00,started fine location tracking
...
5057,1456184131.32,2016-02-22 15:28:31.318580-08:00,"Recieved location <+37.39518648,-122.07703151> +/- 209.00m (speed -1.00 mps / course -1.00) @ 2/22/16, 3:35:30 PM Pacific Standard Time, ongoing trip = true"
5058,1456184131.42,2016-02-22 15:28:31.415820-08:00,"Recieved location <+37.39518648,-122.07703151> +/- 209.00m (speed -1.00 mps / course -1.00) @ 2/22/16, 3:35:30 PM Pacific Standard Time, ongoing trip = true"

Case 3:

5360,1456196431.28,2016-02-22 18:53:31.276510-08:00,successfully pushed 572 entries to the server
5361,1456196431.33,2016-02-22 18:53:31.333230-08:00,Returning with fetch result = new data
5362,1456196431.37,2016-02-22 18:53:31.365170-08:00,successfully pushed 573 entries to the server
5363,1456196431.61,2016-02-22 18:53:31.605910-08:00,Returning with fetch result = new data
5364,1456196431.97,2016-02-22 18:53:31.969800-08:00,successfully pushed 576 entries to the server
5365,1456198901.71,2016-02-22 19:34:41.710320-08:00,Received transition T_NOP in state STATE_WAITING_FOR_TRIP_START
5366,1456198901.78,2016-02-22 19:34:41.783510-08:00,Received notification T_NOP while processing silent push notification
5367,1456198901.8,2016-02-22 19:34:41.804270-08:00,Trip diary state machine ignored the silent push
5368,1456198901.99,2016-02-22 19:34:41.989820-08:00,Received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START
5369,1456198902.06,2016-02-22 19:34:42.063230-08:00,started fine location tracking
...
5382,1456198903.06,2016-02-22 19:34:43.055630-08:00,"Recieved location <+37.39067787,-122.08262884> +/- 65.00m (speed -1.00 mps / course -1.00) @ 2/22/16, 7:41:42 PM Pacific Standard Time, ongoing trip = true"
5383,1456198905.09,2016-02-22 19:34:45.089690-08:00,"Recieved location <+37.39063346,-122.08281582> +/- 10.00m (speed 1.16 mps / course 273.52) @ 2/22/16, 7:41:45 PM Pacific Standard Time, ongoing trip = true"

Why the large gap between the completed push and NOP transition?

Case 4:

5424,1456200010.66,2016-02-22 19:53:10.658120-08:00,Received transition T_TRIP_ENDED in state STATE_WAITING_FOR_TRIP_START
5425,1456200010.71,2016-02-22 19:53:10.709910-08:00,Received notification T_TRIP_ENDED while processing silent push notification
5426,1456200010.75,2016-02-22 19:53:10.747670-08:00,pushAndClearUserCache called
...
5435,1456200011.07,2016-02-22 19:53:11.071590-08:00,postToHost called with url = /usercache/put -- https://e-mission.eecs.berkeley.edu
...
5436,1456200288.48,2016-02-22 19:57:48.481630-08:00,"Got error Error Domain=NSURLErrorDomain Code=-1005 ""The network connection was lost.""
...
5438,1456200288.76,2016-02-22 19:57:48.763200-08:00,Received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START
5439,1456200288.99,2016-02-22 19:57:48.992870-08:00,started fine location tracking
...
5454,1456200289.97,2016-02-22 19:57:49.972540-08:00,"Recieved location <+37.38932491,-122.08315565> +/- 74.29m (speed -1.00 mps / course -1.00) @ 2/22/16, 8:04:49 PM Pacific Standard Time, ongoing trip = true"
5455,1456200292.09,2016-02-22 19:57:52.085120-08:00,"Recieved location <+37.38962021,-122.08275489> +/- 10.00m (speed 1.14 mps / course 349.80) @ 2/22/16, 8:04:52 PM Pacific Standard Time, ongoing trip = true"

Again, large gap (almost 5 secs!) between remote call and error.

5792,1456246332.77,2016-02-23 08:45:12.770710-08:00,Received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START
5793,1456246332.97,2016-02-23 08:45:12.971280-08:00,started fine location tracking
...
5806,1456246333.93,2016-02-23 08:45:13.932780-08:00,"Recieved location <+37.39174926,-122.08296957> +/- 65.00m (speed -1.00 mps / course -1.00) @ 2/23/16, 8:52:13 AM Pacific Standard Time, ongoing trip = true"
5807,1456246339.11,2016-02-23 08:45:19.106830-08:00,"Recieved location <+37.39177767,-122.08323861> +/- 10.00m (speed 0.67 mps / course 92.11) @ 2/23/16, 8:52:19 AM Pacific Standard Time, ongoing trip = true"
shankari commented 8 years ago

Finally, the one which failed. Note that again, the CommunicationHelper from the previous remote push is invoked as part of this geofence exit callback and the app is suspended in the middle.

8224,1456347610.35,2016-02-24 12:53:10.350020-08:00,finished init of iOS native code
8225,1456347610.46,2016-02-24 12:53:10.460370-08:00,Application launched with LaunchOptionsLocationKey = NO
8226,1456347610.48,2016-02-24 12:53:10.484790-08:00,"tripDiaryStateMachine = (null), relaunchLocationManager = 0, recreating the state machine"
8227,1456347610.53,2016-02-24 12:53:10.526250-08:00,"Restart = 0, initializing TripDiaryStateMachine with state = STATE_WAITING_FOR_TRIP_START"
8228,1456347610.63,2016-02-24 12:53:10.628160-08:00,"Received remote push, about to check whether a trip has ended"
8229,1456347610.67,2016-02-24 12:53:10.665210-08:00,Received transition T_RECEIVED_SILENT_PUSH in state STATE_WAITING_FOR_TRIP_START
8230,1456347610.89,2016-02-24 12:53:10.891640-08:00,backgroundSync called8231,1456347611.1,2016-02-24 12:53:11.104630-08:00,pushAndClearUserCache called
8232,1456347611.45,2016-02-24 12:53:11.446930-08:00,CommunicationHelper.execute called!8233,1456347611.47,2016-02-24 12:53:11.465090-08:00,tryToAuthenticate called8234,1456347611.49,2016-02-24 12:53:11.492990-08:00,"ready to authenticate, checking expiration"
8235,1456347611.51,2016-02-24 12:53:11.510550-08:00,"currAuth = GTMOAuth2Authentication 0x127f70170: {refreshToken=""1/sFWC0Qy3Cvpq-4LEq6dQonUpKFdB5GeRlnmU_L97JtY""}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES"
8236,1456347611.53,2016-02-24 12:53:11.529640-08:00,"Existing auth token expired, refreshing"8237,1456347611.56,2016-02-24 12:53:11.558680-08:00,CommunicationHelper.execute called!
8238,1456347611.58,2016-02-24 12:53:11.575890-08:00,"currAuth = GTMOAuth2Authentication 0x127f70170: {refreshToken=""1/sFWC0Qy3Cvpq-4LEq6dQonUpKFdB5GeRlnmU_L97JtY""}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES"
8239,1456347611.59,2016-02-24 12:53:11.590680-08:00,"Existing auth token expired, refreshing"8240,1456347611.61,2016-02-24 12:53:11.608620-08:00,Received notification T_RECEIVED_SILENT_PUSH while processing silent push notification8241,1456347611.63,2016-02-24 12:53:11.631710-08:00,Ignoring SILENT_PUSH in the silent push handler
[app suspended]
8242,1456349797.41,2016-02-24 13:29:37.408610-08:00,CommunicationHelper.execute called!
8243,1456349797.65,2016-02-24 13:29:37.653300-08:00,"currAuth = GTMOAuth2Authentication 0x127f70170: {refreshToken=""1/sFWC0Qy3Cvpq-4LEq6dQonUpKFdB5GeRlnmU_L97JtY""}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES"
8244,1456349797.68,2016-02-24 13:29:37.680410-08:00,"Existing auth token expired, refreshing"8245,1456349797.72,2016-02-24 13:29:37.721320-08:00,"In state STATE_WAITING_FOR_TRIP_START, Recieved location <+37.33204203,-121.89037168> +/- 10.00m (speed 0.34 mps / course 236.95) @ 2/24/16, 9:18:23 AM Pacific Standard Time"
8246,1456349797.78,2016-02-24 13:29:37.780600-08:00,Received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START

Then, we start fine location tracking and get a single update before the app is suspended again.

8247,1456349797.95,2016-02-24 13:29:37.946080-08:00,started fine location tracking
8261,1456349799.06,2016-02-24 13:29:39.061620-08:00,"Recieved location <+37.32935173,-121.89529055> +/- 65.00m (speed -1.00 mps / course -1.00) @ 2/24/16, 1:36:37 PM Pacific Standard Time, ongoing trip = true"
[app suspended]
8262,1456350679.41,2016-02-24 13:44:19.405650-08:00,finished init of iOS native code
8263,1456350679.51,2016-02-24 13:44:19.508920-08:00,Application launched with LaunchOptionsLocationKey = YES

And then as part of the visit notification, the fine location tracking starts in earnest.

8259,1456349799.01,2016-02-24 13:29:39.007380-08:00,Received notification T_TRIP_RESTARTED while processing silent push notification
8260,1456349799.04,2016-02-24 13:29:39.043600-08:00,Successfully registered remote push notifications with parse
8261,1456349799.06,2016-02-24 13:29:39.061620-08:00,"Recieved location <+37.32935173,-121.89529055> +/- 65.00m (speed -1.00 mps / course -1.00) @ 2/24/16, 1:36:37 PM Pacific Standard Time, ongoing trip = true"
[app suspended]
8262,1456350679.41,2016-02-24 13:44:19.405650-08:00,finished init of iOS native code
8263,1456350679.51,2016-02-24 13:44:19.508920-08:00,Application launched with LaunchOptionsLocationKey = YES
8264,1456350679.53,2016-02-24 13:44:19.527900-08:00,"tripDiaryStateMachine = (null), relaunchLocationManager = 1, recreating the state machine"
8265,1456350679.58,2016-02-24 13:44:19.584380-08:00,"Restart = 1, initializing TripDiaryStateMachine with state = STATE_ONGOING_TRIP"
8266,1456350679.61,2016-02-24 13:44:19.605660-08:00,started fine location tracking
8267,1456350680.13,2016-02-24 13:44:20.128470-08:00,"Received visit notification = <+37.33145220,-121.88961989> +/- 30.92m (2016-02-24 17:21:01 +0000 to 2016-02-24 21:33:22 +0000)"
8268,1456350680.19,2016-02-24 13:44:20.188450-08:00,Received transition T_VISIT_ENDED in state STATE_ONGOING_TRIP
8269,1456350680.67,2016-02-24 13:44:20.667830-08:00,"Recieved location <+37.32935173,-121.89529055> +/- 65.00m (speed -1.00 mps / course -1.00) @ 2/24/16, 1:36:37 PM Pacific Standard Time, ongoing trip = true"
8270,1456350680.79,2016-02-24 13:44:20.791340-08:00,"Recieved location <+37.33000082,-121.89575416> +/- 225.17m (speed -1.00 mps / course -1.00) @ 2/24/16, 1:37:14 PM Pacific Standard Time, ongoing trip = true"

I wonder if the app was killed in the middle. There is no corresponding log message, but we are not guaranteed to have one if the app is already suspended. Or is the location update actually from the fine location tracking, or is it from the significant location changes? Or ???

applicationWillTerminate:—Lets you know that your app is being terminated. This method is not called if your app is suspended.

https://developer.apple.com/library/ios/documentation/iPhone/Conceptual/iPhoneOSProgrammingGuide/TheAppLifeCycle/TheAppLifeCycle.html

shankari commented 8 years ago

Certainly looks like app was killed because it is relaunched. Unsure what (if anything) we can do about it. 

8261,1456349799.06,2016-02-24 13:29:39.061620-08:00,"Recieved location <+37.32935173,-121.89529055> +/- 65.00m (speed -1.00 mps / course -1.00) @ 2/24/16, 1:36:37 PM Pacific Standard Time, ongoing trip = true"
[app suspended]
8262,1456350679.41,2016-02-24 13:44:19.405650-08:00,finished init of iOS native code

Note also that right before the app was killed, it appeared to get a callback to register for remote notification. And this callback was in response to an init over an hour ago.

8224,1456347610.35,2016-02-24 12:53:10.350020-08:00,finished init of iOS native code
8225,1456347610.46,2016-02-24 12:53:10.460370-08:00,Application launched with LaunchOptionsLocationKey = NO
8226,1456347610.48,2016-02-24 12:53:10.484790-08:00,"tripDiaryStateMachine = (null), relaunchLocationManager = 0, recreating the state machine"
8227,1456347610.53,2016-02-24 12:53:10.526250-08:00,"Restart = 0, initializing TripDiaryStateMachine with state = STATE_WAITING_FOR_TRIP_START"
8228,1456347610.63,2016-02-24 12:53:10.628160-08:00,"Received remote push, about to check whether a trip has ended"
[bad connection, no callback]
8258,1456349798.84,2016-02-24 13:29:38.844450-08:00,Received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP
8259,1456349799.01,2016-02-24 13:29:39.007380-08:00,Received notification T_TRIP_RESTARTED while processing silent push notification
8260,1456349799.04,2016-02-24 13:29:39.043600-08:00,Successfully registered remote push notifications with parse
8261,1456349799.06,2016-02-24 13:29:39.061620-08:00,"Recieved location <+37.32935173,-121.89529055> +/- 65.00m (speed -1.00 mps / course -1.00) @ 2/24/16, 1:36:37 PM Pacific Standard Time, ongoing trip = true"

I wonder if there is a connection - the callback has finally been delivered, so the OS determines that it can kill the app. If so, I don't see a great workaround for it. It doesn't look like this will be affected by the planned restructuring into the pluginInitialize code, and it also looks like we might not be able to come up with a workaround for it...