Objective-C线程

Question

我到底是怎么得到这个结果的:

2012-02-15 14:00:46.008 Test[3602:f803] 1: 0
2012-02-15 14:00:46.010 Test[3602:f803] 3: 1
2012-02-15 14:00:46.011 Test[3602:f803] 4: 3
2012-02-15 14:00:46.010 Test[3602:11703] 2: 2

来自这段代码:

TestClass * test = [[TestClass alloc] init];
NSLog(@"1: %i", test.value++);
dispatch_queue_t queue = dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_HIGH, 0ul);
dispatch_async(queue, ^{
     NSLog(@"2: %i", test.value++);
});
@synchronized(test) {
     NSLog(@"3: %i", test.value++);
}
NSLog(@"4: %i", test.value++);

我的期望是:

2012-02-15 14:00:46.008 Test[3602:f803] 1: 0
2012-02-15 14:00:46.010 Test[3602:f803] 3: 1
2012-02-15 14:00:46.011 Test[3602:f803] 4: 2
2012-02-15 14:00:46.010 Test[3602:11703] 2: 3

甚至

2012-02-15 14:00:46.008 Test[3602:f803] 1: 0
2012-02-15 14:00:46.010 Test[3602:f803] 3: 1
2012-02-15 14:00:46.010 Test[3602:11703] 2: 2
2012-02-15 14:00:46.011 Test[3602:f803] 4: 3

既然 test.value 在第 2 步的日志中增加了，但它没有被记录？什么？

Answer 1

在开始调用 NSLog 和 NSLog 将字符串写入日志之间有一段时间。在那段时间它可能会被抢占，因此另一个线程可能会在 NSLog 的这个实例醒来之前潜入它的日志条目。

这是导致打印输出的可能事件序列:

1. 线程A调用NSLog(@"2: %i", test.value++);，2作为%i的参数入栈，3写入test.value
2. 线程 A 在准备日志输出的过程中被抢占
3. 主线程调用NSLog(@"4: %i", test.value++);，3作为%i的参数入栈，4写入test.value
4. 主线程将4:3写入日志，没有被抢占
5. 线程A被唤醒，从栈中取出2，格式化输出，将2:2写入日志