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)