ACE Tutorial 018
The FIFO Nature of ACE_Token

That's it for the code, now let's take a quick look at some output. The first set of output is from the Token test, the second is Mutex test. Notice how the threads are evenly utilized in the Token test. Each thread gets to see exactly two messages. There's also an interesting side-effect that the messages are processed in order. (You can't rely on that, it just happend in this particular run.)

With the Mutex test, however, we see that the first thread gets no less than 1/2 of all messages. In fact, if we didn't have the governor in svc() it might have gotten them all!

Why does this happen?

Primarily because of time slicing. Even though each thread takes time to do work (1 second in our test), it can still own the timeslice when it gets back to the mutex acquire. Since the other threads are still switched out, the current thread regets the lock and continues. On the other hand, the ACE_Token is very careful about the order in which the acquisition is allowed and more evenly distributes the work.

Play around with the sleep() call in svc(). You'll find that as you decrease it, there is more chance that even the Token test will do most of its work in one thread. You're still at the mercy of the OS time slicing. In reality, though, it will take a moment or two for work to be done. The end goal isn't necessarily to distribute the work evenly over all threads but, rather, to distribute it evenly among available threads. The distinction is subtle but important. 

(21386|1024|15:26:32.366520)	Test (Token) created
1 (21386|1025|15:26:32.390340)	Test::svc() Entry
2 (21386|2050|15:26:32.408330)	Test::svc() Entry
3 (21386|3075|15:26:32.427363)	Test::svc() Entry
4 (21386|4100|15:26:32.447285)	Test::svc() Entry
5 (21386|5125|15:26:32.482479)	Test::svc() Entry
1 (21386|1025|15:26:32.498583)	Test::svc() received message #1 (Message Number 0)
2 (21386|2050|15:26:33.517770)	Test::svc() received message #1 (Message Number 1)
3 (21386|3075|15:26:34.537701)	Test::svc() received message #1 (Message Number 2)
4 (21386|4100|15:26:35.557675)	Test::svc() received message #1 (Message Number 3)
5 (21386|5125|15:26:36.577650)	Test::svc() received message #1 (Message Number 4)
1 (21386|1025|15:26:37.597689)	Test::svc() received message #2 (Message Number 5)
2 (21386|2050|15:26:38.607689)	Test::svc() received message #2 (Message Number 6)
3 (21386|3075|15:26:39.617675)	Test::svc() received message #2 (Message Number 7)
4 (21386|4100|15:26:40.637653)	Test::svc() received message #2 (Message Number 8)
5 (21386|5125|15:26:41.657637)	Test::svc() received message #2 (Message Number 9)

(21386|1024|15:26:42.679919)	Test (Mutex) created
1 (21386|6150|15:26:42.700301)	Test::svc() Entry
2 (21386|7175|15:26:42.737413)	Test::svc() Entry
3 (21386|8200|15:26:42.754241)	Test::svc() Entry
4 (21386|9225|15:26:42.772122)	Test::svc() Entry
5 (21386|10250|15:26:42.788867)	Test::svc() Entry
1 (21386|6150|15:26:42.806260)	Test::svc() received message #1 (Message Number 0)
1 (21386|6150|15:26:43.807539)	Test::svc() received message #2 (Message Number 5)
1 (21386|6150|15:26:44.817569)	Test::svc() received message #3 (Message Number 6)
1 (21386|6150|15:26:45.827571)	Test::svc() received message #4 (Message Number 7)
1 (21386|6150|15:26:46.837581)	Test::svc() received message #5 (Message Number 8)
2 (21386|7175|15:26:47.847908)	Test::svc() received message #1 (Message Number 1)
2 (21386|7175|15:26:48.857555)	Test::svc() received message #2 (Message Number 9)
4 (21386|9225|15:26:49.867991)	Test::svc() received message #1 (Message Number 3)
3 (21386|8200|15:26:50.887559)	Test::svc() received message #1 (Message Number 2)
5 (21386|10250|15:26:51.898275)	Test::svc() received message #1 (Message Number 4)

[Tutorial Index] [Continue This Tutorial]