Hi,
I recently ported an application from Unix to Win32, and I've got one problem left to solve - my diagnostic logfile is now unsorted.
Five different threads all share a common "textbook" logging subroutine...
use Fcntl qw(:flock SEEK_END); # --------------------------------------- # sub logmsg # --------------------------------------- sub logmsg { my $now = time; my $msec = int( ( $now - int($now) ) * 1000 ); my ( $sec, $min, $hour, $mday, $mon, $year, $wday, $yday, $isdst ) = + localtime(time); sub lock { flock( LOG, LOCK_EX ); # and, in case someone appended # while we were waiting... seek( LOG, 0, SEEK_END ); } sub unlock { flock( LOG, LOCK_UN ); } open LOG, ">> $logFilename"; lock(); printf LOG "%02d:%02d:%02d:%03d %s\r\n", $hour, $min, $sec, $msec, @ +_; unlock(); close(LOG); }
This worked fine on freeBSD. Even though there are multiple log messages in a single millisecond, the messages were always in perfect order. It made debugging a snap (the 5 processes do a lot of IPC). Now the log looks like this (check the timestamps):
16:57:23:238 progman: sent supervisor - progman,ctrlman,set,wort_pu +mp,off 16:57:23:240 supervisor: rcvd pidman - pidman,webman,status,hlt_du +ty,0 16:57:23:239 progman: sent supervisor - progman,ctrlman,set,boil_he +ater,off 16:57:23:240 progman: sent supervisor - progman,ctrlman,set,hlt_hea +ter,off 16:57:23:241 progman: sent supervisor - progman,ctrlman,set,hlt_ssr +,off 16:57:23:241 supervisor: sent ctrlman - pidman,webman,status,hlt_du +ty,0 16:57:23:234 ctrlman: rcvd supervisor - pidman,webman,status,hlt_du +ty,0 16:57:23:244 supervisor: sent progman - pidman,webman,status,hlt_du +ty,0 16:57:23:245 supervisor: sent webman - pidman,webman,status,hlt_du +ty,0 16:57:23:250 webman: rcvd supervisor - pidman,webman,status,hlt_du +ty,0 16:57:23:241 progman: sent supervisor - progman,ctrlman,set,boil_ss +r,off 16:57:23:246 progman: sent supervisor - progman,webman,status,hlt_d +uty,0 16:57:23:246 progman: sent supervisor - progman,webman,status,hlt_s +etpoint,0 16:57:23:246 supervisor: rcvd progman - progman,webman,status,step, +startup 16:57:23:249 supervisor: sent webman - progman,webman,status,step, +startup 16:57:23:253 webman: rcvd supervisor - progman,webman,status,step, +startup 16:57:23:250 supervisor: sent ctrlman - progman,webman,status,step, +startup 16:57:23:241 ctrlman: rcvd supervisor - progman,webman,status,step, +startup 16:57:23:247 progman: sent supervisor - progman,webman,status,hlt_m +ode,pid 16:57:23:251 progman: sent supervisor - progman,webman,status,hlt_p +ower,100 16:57:23:251 progman: sent supervisor - progman,webman,status,hlt_v +ary,1
Nothing is garbled, just out of order. The timestamp is created at the entry to the logging subroutine - before the open() and flock(). It appears that locking is working, BUT - when the lock is released, the thread (or process) that gets the lock next is not FIFO - it's random (phase of the moon?).
Unsorted log file is one thing, but Aye, here's the rub - each thread must wait a random amount of time to acquire the lock. Since this application runs hardware devices like pumps and heating elements, the concept of "random" is not in our vocabulary.
I suspect this is a problem with ActiveState 5.10.1 no-ssl binary and/or Windows, but to confuse matters, about the same time I moved from Unix to Win32, I also changed from fork-exec to threads, but I did not closely examine the logfile at the time.
Any ideas? - Thanks, Dave
In reply to Win32 - flock() not FIFO? by hennesse
| For: | Use: | ||
| & | & | ||
| < | < | ||
| > | > | ||
| [ | [ | ||
| ] | ] |