[TriLUG] Why do File IO event seem to be out-of-order in strace?

[Scott Lambdin via TriLUG]

Good day -

I've mostly used strace in the past to see why processes were hanging up.
But now I am using it to see why some file locking doesn't seem to be
working in a c program.

When I traced the c program, I saw processes apparently fly through a fcntl
that they should have waited in, since another process had gotten to it
first.

I wrote a c program that forks a few processes, and if a child, open
/tmp/test.txt, lock (with wait) the file with fcntl, write a few lines of
text to the file, and then unlock it.

Again, strace seemed to show that the not-first processes did not wait in
the fcntl command as expected, but also the order of events in the trace
seemed whacky.  The writes occurred after the fcntls that unlocked the
file.

The program I wrote had printfs to track the events and they were fine :

...snip...
opened by 6398
About to lock by 6398
Locked by 6398
UnLocked by 6398
--------------------------------------------------
opened by 6397
About to lock by 6397
Locked by 6397
UnLocked by 6397
--------------------------------------------------
...snip...

What is this layer of complexity I knew not about?

--Scott

-- 

Eat like you give a damn.  Go vegan.