When are parameters calculated, when having concatenated call: obj.F1().F2().F3( sin(x) )?

I use the streaming operators (e.g. operator<<(const char*)) for logging. In my unit tests I have a test like the following:

MyLogger oLogger;
oLogger << "charly";
oLogger << "foo" << sleep( 10 ) << "bar";
oLogger << "marcus";

First I executed a second thread, which should log at the same time. I was wondering, why between "foo" and "bar" no other log-output was generated. So I printed in each operator the current time . I expected something like this:

50 sec 137051 usec charly 
50 sec 137930 usec foo 
60 sec 138014 usec 0 
60 sec 138047 usec bar 
60 sec 138088 usec marcus 

but got this:

50 sec 137051 usec charly 
60 sec 137930 usec foo 
60 sec 138014 usec 0 
60 sec 138047 usec bar 
60 sec 138088 usec marcus 

What is wrong with the following idea:

[ 0 sec] MyLogger&开发者_Python百科; MyLogger::operator<<( "charly" ) is processed.
[ 0 sec] MyLogger& MyLogger::operator<<( "foo" ) is processed.
         The return value is used for the next function.
[ 0 sec] int sleep( 10 ) is processed - this takes 10 seconds until the return
         value is available
[10 sec] MyLogger& MyLogger::operator<<( 0 ) is processed
         ( "0" is the return value of sleep(10) )
[10 sec] MyLogger& MyLogger::operator<<( "bar" ) is processed

But for what reason ever, the MyLogger::operator<<( "foo" ) is processed after sleep(10)?

This is acceptable behaviour, as it is not specified in which order operands to "operator<<" are being evaluated, and TTBOMK gcc often does it in reverse order to get the parameters onto the stack in the right order for the next function call.

Think of it in terms of a stack machine:

push "charly"
push oLogger
call operator<<
pop
push "bar"
push 10
call sleep
push "foo"
push oLogger
call operator<<
call operator<<
call operator<<
pop