I'm interested about NSRunLoop cycle, especially for main runloop.Via CFRunLoopObserverRef, we can know more about it :
CFRunLoopObserverRef observerRef = CFRunLoopObserverCreateWithHandler(NULL, kCFRunLoopAllActivities, YES, 0, ^(CFRunLoopObserverRef observer, CFRunLoopActivity activity) {
if (activity == kCFRunLoopBeforeTimers) {
weakSelf.runloopId += 1;
}
NSLog(@"RunloopId : %lu, Activity : %ld, %lf\n", (unsigned long)weakSelf.runloopId, activity, [[NSDate date] timeIntervalSince1970]);
});
CFRunLoopAddObserver(CFRunLoopGetMain(), observerRef, kCFRunLoopCommonModes);
We can ignore kCFRunLoopEntry & kCFRunLoopExit for main runloop, and focus on kCFRunLoopBeforeTimers, kCFRunLoopBeforeSources, kCFRunLoopBeforeWaiting and kCFRunLoopAfterWaiting.
According to The Run Loop Sequence of Events and CFRunLoop.c,
- one loop of main runloop starts at
kCFRunLoopBeforeTimers, - then
kCFRunLoopBeforeSources, - after the above two events, if nothing pending, goto sleep,
so, in my opinion, when the main loop goes to sleep, it should be idle.
Normal waiting state
Using my code above, when I open the app (in simulator) and just leave it there to keep it idle, runloop event callbacks will print out the log onto the console:
2016-03-08 21:58:33.522 CaptureJitterDemo[25272:1312010] RunloopId : 156, Activity : 2, 1457445513.522846
2016-03-08 21:58:33.523 CaptureJitterDemo[25272:1312010] RunloopId : 156, Activity : 4, 1457445513.522985
2016-03-08 21:58:33.523 CaptureJitterDemo[25272:1312010] RunloopId : 156, Activity : 32, 1457445513.523144
2016-03-08 21:58:49.002 CaptureJitterDemo[25272:1312010] RunloopId : 156, Activity : 64, 1457445529.002502
2016-03-08 21:58:49.002 CaptureJitterDemo[25272:1312010] RunloopId : 157, Activity : 2, 1457445529.002820
2016-03-08 21:58:49.003 CaptureJitterDemo[25272:1312010] RunloopId : 157, Activity : 4, 1457445529.003044
Activity : 32 means beforeWaiting, while Activity : 64 means afterWaiting, and between the two states the main callstack is like below:
It has nothing to do, but waiting.
Surprising waiting state
Occasionally, I find that something might happen between beforeWaiting & afterWaiting:
- (void)tableView:(UITableView *)tableView didSelectRowAtIndexPath:(NSIndexPath *)indexPath {
NSLog(@"begin of url request... %lf\n", [[NSDate date] timeIntervalSince1970]);
NSData *data = [NSData dataWithContentsOfURL:[NSURL URLWithString:@"https://c2.staticflickr.com/4/3771/9914251535_366536a515_h.jpg"]];
if (data) {
NSLog(@"end of url request : %lf\n", [[NSDate date] timeIntervalSince1970]);
}
}
when I select one row, the console prints:
2016-03-08 23:00:07.927 CaptureJitterDemo[25855:1334505] RunloopId : 27, Activity : 2, 1457449207.927184
2016-03-08 23:00:07.927 CaptureJitterDemo[25855:1334505] RunloopId : 27, Activity : 4, 1457449207.927399
2016-03-08 23:00:07.927 CaptureJitterDemo[25855:1334505] RunloopId : 27, Activity : 32, 1457449207.927624
2016-03-08 23:00:07.929 CaptureJitterDemo[25855:1334505] begin of url request... 1457449207.929021
2016-03-08 23:00:10.277 CaptureJitterDemo[25855:1334505] end of url request : 1457449210.276982
2016-03-08 23:00:10.278 CaptureJitterDemo[25855:1334505] RunloopId : 27, Activity : 64, 1457449210.278046
2016-03-08 23:00:10.278 CaptureJitterDemo[25855:1334505] RunloopId : 28, Activity : 2, 1457449210.278244
2016-03-08 23:00:10.278 CaptureJitterDemo[25855:1334505] RunloopId : 28, Activity : 4, 1457449210.278486
2016-03-08 23:00:10.278 CaptureJitterDemo[25855:1334505] RunloopId : 28, Activity : 32, 1457449210.278752
According to the logs, between beforeWaiting & afterWaiting, the app completed one url request task. This confuses me.
My misunderstanding at first
At first, I thought that synchronous url request on main thread would cause the main runloop goes into waiting state. But later I found that the app went into waiting state first, then the url request occurred.
So, now it is the phenomenon that after the main runloop goes into waiting state, it can still make synchronous url request without waking itself up -- kidding me?
If I move the code to viewDidAppear:
- (void)viewDidAppear:(BOOL)animated {
[super viewDidAppear:animated];
NSLog(@"begin of url request... %lf\n", [[NSDate date] timeIntervalSince1970]);
NSData *data = [NSData dataWithContentsOfURL:[NSURL URLWithString:@"https://c2.staticflickr.com/4/3771/9914251535_366536a515_h.jpg"]];
if (data) {
NSLog(@"end of url request : %lf\n", [[NSDate date] timeIntervalSince1970]);
}
}
the console prints:
2016-03-08 23:42:25.616 CaptureJitterDemo[26268:1377354] RunloopId : 0, Activity : 1, 1457451745.616474
2016-03-08 23:42:25.617 CaptureJitterDemo[26268:1377354] RunloopId : 1, Activity : 2, 1457451745.617201
2016-03-08 23:42:25.617 CaptureJitterDemo[26268:1377354] RunloopId : 1, Activity : 4, 1457451745.617346
2016-03-08 23:42:25.618 CaptureJitterDemo[26268:1377354] begin of url request... 1457451745.618176
2016-03-08 23:42:27.832 CaptureJitterDemo[26268:1377354] end of url request : 1457451747.832428
2016-03-08 23:42:27.832 CaptureJitterDemo[26268:1377354] RunloopId : 2, Activity : 2, 1457451747.832818
2016-03-08 23:42:27.832 CaptureJitterDemo[26268:1377354] RunloopId : 2, Activity : 4,
which seems more acceptable.
What I really want to do
I want to calculate the time a loop cost, on main runloop, but the idle time should not be included.
A loop means:
- If sleep not happened:
kCFRunLoopBeforeTimers->kCFRunLoopBeforeSources->kCFRunLoopBeforeTimers; - If sleep happened:
kCFRunLoopBeforeTimers->kCFRunLoopBeforeSources->kCFRunLoopBeforeWaiting->kCFRunLoopAfterWaiting->kCFRunLoopBeforeTimers;
For time cost between kCFRunLoopBeforeWaiting -> kCFRunLoopAfterWaiting:
- if it is normal waiting state, the time should be excluded, because it is really idle;
- else if it is surprising waiting state, the time should be included, because it does have things done;
Thanks for any help :)
