How to enforce thread locking on threads with out of sync clocks (objective-c)

Question

basically I got two threads running.. one broadcasts music via a network (let's call it broadcaster).. the other communicates with clients to know when to start broadcasting, play music etc.. (runs on main)

The broadcasting thread keeps on running even while the server is talking to the client, there is only one part when I want to pause the broadcaster thread, and that's when I want to send a packet to the client to start playing music (ie I want both server and client to play in sync)..

I've used pretty much everything (ie NSLocks, pthread_mutex_t and pthread_cond_t, thread sleep etc).. but I keep on running on this scenario:

basically I succeed in locking out the broadcaster thread.. but it always creeps in a command that seems to have a different clock setting

notice the logs:

12:02:59.288 Snap[30700:7a0f] broadcaster--> sending packet number 69 to all peers
12:02:59.294 Snap[30700:7a0f] broadcaster--> going through packets loop
12:02:59.306 Snap[30700:707] communicator--> SERVER: WILL LOCK BROADCASTING
12:02:59.312 Snap[30700:707] communicator--> we are inside serverReceivedPacket
12:02:59.314 Snap[30700:707] communicator--> SERVER: JUST RECEIVED A PRIMED PACKET!
12:02:59.316 Snap[30700:707]communicator-->  we are inside allPlayersArePrimed and we got 2 players
12:02:59.318 Snap[30700:707] communicator--> CLIENT: players are primed!



12:02:59.320 Snap[30700:707] communicator--> all players are primed now!.. pausing broadcast
12:02:59.322 Snap[30700:707] communicator--> will fire music player
12:02:59.311 Snap[30700:7a0f] broadcaster--> sending packet number 70 to all peers
12:02:59.335 Snap[30700:707] communicator--> SERVER: about to play [UNLOCK]
12:02:59.452 Snap[30700:7a0f] broadcaster--> going through packets loop
12:02:59.454 Snap[30700:7a0f] broadcaster--> sending packet number 71 to all peers

my problem is specifically with this line:

12:02:59.311 Snap[30700:7a0f] broadcaster--> sending packet number 70 to all peers

if you follow the broadcaster thread logs.. you'll see that its last log statement stopped at 12:02:59.288, then it was locked out.. but before the communicator unlocked the lock.. the broadcaster threw in a command at 12:02:59.311.. although it came after a communicator command that was later in time!

I've seen this scenario repeat time and time again.. and I don't know how to address it?

here is some of the code:

instance variable shared with both communicator and broadcaster:

@implementation Game
{
    ... 

    NSLock *broadcastLock;

}

communicator:

    case PacketTypeClientPrimed:
    {

        player.isPrimed = true;  
        if (_state == GameStateWaitingForPrimed && [self allPlayersArePrimed])
        {
            [Logger Log:@"SERVER: WILL LOCK BROADCASTING"];
            broadcastLock = [[NSLock alloc] init];
            [broadcastLock lock];

            _broadCastState = BroadCastStatePaused;
            [hostViewController.musicPlayer skipToBeginning];

            Packet *packet = [Packet packetWithType:PacketTypePlayMusicNow];                

            NSError *error;
            NSLog(@"all players are primed now!.. pausing broadcast ");
            [_session sendDataToAllPeers:[packet data] withDataMode:GKSendDataUnreliable error:&error];
            NSLog(@"will fire music player");

            [self performSelector:@selector(startMusic:) withObject:hostViewController.musicPlayer afterDelay:0.01];
            _state =  GameStatePlayBackCommenced;
        }
    }

....

-(void)startMusic:(MPMusicPlayerController *)player 
{
    NSLog(@"SERVER: about to play [UNLOCK]");
    [player play];
    _broadCastState = BroadCastStateInProgress;
    [broadcastLock unlock];
}

broadcaster:

-(void)broadcastSample
{
    [broadcastLock lock];

        CMSampleBufferRef sample;
        sample = [readerOutputcopyNextSampleBuffer];            
        ....                        

        for (int i = 0; i < inNumberPackets; ++i)
        {
            // ..
            // setup audio packet
            // ..
            if ((packetSpaceRemaining < (dataSize + AUDIO_STREAM_PACK_DESC_SIZE)) || 
                (packetDescrSpaceRemaining < AUDIO_STREAM_PACK_DESC_SIZE))
            {
                if (![self encapsulateAndShipPacket:packet packetDescriptions:packetDescriptions packetID:assetOnAirID])
                    break;
            }                        
        }

    [broadcastLock unlock];
}

Did you try to use GCD semaphores instead? http://developer.apple.com/library/ios/#documentation/Performance/Reference/GCD_libdispatch_Ref/Reference/reference.html — Resh32, Nov 22 '12 at 14:53
Also are you using the same lock between the two threads? broadcastLock = [[NSLock alloc] init]; Maybe you should do this once outside these methods. Use GCD dispatch_once to ensure uniqueness. — Resh32, Nov 22 '12 at 14:59
@Resh32 I'm definitely using the same lock between the two threads (i updated my question to reflect that).. a lot of people are telling me that NSLog is just too expensive and inefficient for multi threading diagnostics.. so trying to solve this problem is beyond NSLock or GCD semaphores etc.. that being said.. suggested solutions include storing all the logs onto a variable and dumping it before the program exists.. introducing locks to ensure things happen at the order i want them.. putting nsasserts rather than logs etc etc.. — abbood, Nov 22 '12 at 17:40
for more details on my comment see end of comments on this post http://stackoverflow.com/a/12454761/766570 — abbood, Nov 22 '12 at 17:40

Hot Licks · Accepted Answer · 2012-11-22T17:54:12.763

1

Why are you allocating the lock object dynamically? When the broadcaster thread goes through there's no lock object, so it doesn't lock it. Then the lock is allocated and locked in the communicator thread (which can't tell the broadcaster has already entered its critical region), and the two run in parallel.

You should allocate the lock object globally, and it should persist from before the time either thread might attempt to enter its critical region.

edited Nov 22 '12 at 17:54

answered Nov 22 '12 at 17:34

Hot Licks

47,103
17
93
151

you got it man.. but i still maintain what was said in the comments above.. which is that there is an inherent problem with NSLogs when it comes to concurrency diagnostics.. thanks though :) – abbood Nov 22 '12 at 18:33
Yes and no. NSLog actually locks the output file while writing, so that messages will not be interleaved. But I wouldn't rely on it sequencing messages exactly right. – Hot Licks Nov 22 '12 at 18:39

How to enforce thread locking on threads with out of sync clocks (objective-c)

1 Answers1

Linked