Objective-C Threads

Question

How in the world did I get this result:

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

From this code:

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++);

My expectation would have been:

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

or even

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

since test.value was incremented in the log for step 2, yet it was not logged? wth?

Any log is essentially serial, so the GCD block incremented the value, but didn't get a chance to print it until an internal (somewhere in NSLog) mutex allowed it to. **Multithreaded coding is non-intuitive**. — Costique, Feb 15 '12 at 19:16
NSLog() in particular takes an exclusive lock on the logging engine. You can get somewhat more timely results using `printf()`, but your log lines may intermix. — Rob Napier, Feb 15 '12 at 19:29
While I think @Costique and @dasblinkenlight's comments are the correct answer in this case, do note that `test.value++` is wildly non-atomic (even if `test` is an "atomic" ivar). So #2 and #4 could collide and corrupt `value`. Even just `i++` isn't thread-safe in C. http://stackoverflow.com/questions/680097/ive-heard-i-isnt-thread-safe-is-i-thread-safe — Rob Napier, Feb 15 '12 at 19:34

score 6 · Accepted Answer · answered Feb 15 '12 at 19:23

6

There is time between the moment a call to NSLog is initiated and the moment when NSLog writes a string to the log. It may get pre-empted during that time, and so another thread could potentially sneak in its log entry before this instance of NSLog wakes up.

Here is a possible sequence of events that leads to your printout:

Thread A calls NSLog(@"2: %i", test.value++);, 2 goes on the stack as %i's parameter, and 3 is written to test.value
Thread A gets pre-empted in the middle of preparing log's output
Main thread calls NSLog(@"4: %i", test.value++);, 3 goes on the stack as %i's parameter, and 4 is written to test.value
Main thread writes 4: 3 to the log without being pre-empted
Thread A wakes up, takes 2 from the stack, formats its output, and writes 2: 2 to the log

answered Feb 15 '12 at 19:23

Sergey Kalinichenko

714,442
84
1,110
1,523

where's the stack for %i's parameter being held? – Matisse VerDuyn Feb 15 '12 at 19:31
1

@MatisseVerDuyn Each thread has its own stack region. This region is used by the compiled code to pass parameters to functions: the caller pushes parameters onto the stack, and the function being called pops their values off the stack (this is an oversimplification, but the full description would not fit in 500 characters). So your function pushes `@"2: %i"` and 2 onto the stack, `NSLog` picks up `@"2: %i"`, parses it, detects the `%i`, and pops 2 off the stack. – Sergey Kalinichenko Feb 15 '12 at 19:52

Objective-C Threads

1 Answers1