[MLton] MLton.TextIO.mkstemps

Matthew Fluet fluet at cs.cornell.edu
Fri Dec 1 13:47:25 PST 2006


> Could you strace the simultaneous compiles of mlnlffigen to see what's
> going on?

I have a plausible explaination for some of the observed behavior.

I have three simultaneous 'make tools' going, and all three have errors in 
the link stage:

PROC1:
ktrace -i -t cn mlton @MLton max-heap 512m -- -target self -native-split 1 -default-ann 'sequenceNonUnit warn' mlnlffigen.mlb
i686-apple-darwin8-gcc-4.0.1: /tmp/file4ofPIQ.o: No such file or directory
call to system failed with exit status 1:

PROC2:
ktrace -i -t cn mlton @MLton max-heap 512m -- -target self -native-split 1 -default-ann 'sequenceNonUnit warn' mlnlffigen.mlb
/usr/bin/ld: multiple definitions of symbol _f_28
/tmp/filemTweS8.o definition of _f_28 in section (__TEXT,__text)
/tmp/fileo9zyUP.o definition of _f_28 in section (__TEXT,__text)
collect2: ld returned 1 exit status
call to system failed with exit status 1:

PROC3:
ktrace -i -t cn mlton @MLton max-heap 512m -- -target self -native-split 1 -default-ann 'sequenceNonUnit warn' mlnlffigen.mlb
i686-apple-darwin8-gcc-4.0.1: /tmp/fileo9zyUP.o: No such file or directory
call to system failed with exit status 1:

At the end of this message is the ktrace/kdump relevant to fileo9zyUP.o; 
the number after the process name is the absolute time of the trace point 
(a nice feature of ktrace/kdump).

In this situation, the assembler is clearly to blame; when directed to 
output to an existing file, the assembler unlinks the file and then opens 
the (new) file, leaving a window for another process to grab the filename 
for its use.

Here is the fine-grained detail, ordered by absolute time, where the 
leading (N) indicates that the trace point came from the PROC<N> run:

(2) 2939 as       1165003845.198909 CALL  stat(0xbfffec18,0xbfffe898)
(2) 2939 as       1165003845.198913 NAMI  "/tmp/fileo9zyUP.o"
(2) 2939 as       1165003845.198924 RET   stat 0
(2) 2939 as       1165003845.198929 CALL  unlink(0xbfffec18)
(2) 2939 as       1165003845.198932 NAMI  "/tmp/fileo9zyUP.o"
(2) 2939 as       1165003845.199078 RET   unlink 0
(2) 2939 as       1165003845.199085 CALL  open(0xbfffec18,0x601,0x1b6)
(3)  817 mlton-compile 1165003845.199086 CALL  open(0x3116c84,0xa01,0x180)
(2) 2939 as       1165003845.199090 NAMI  "/tmp/fileo9zyUP.o"
(3)  817 mlton-compile 1165003845.199094 NAMI  "/tmp/fileo9zyUP.o"
(3)  817 mlton-compile 1165003845.199276 RET   open 5
(3)  817 mlton-compile 1165003845.199281 CALL  ioctl(0x5,FIODTYPE,0xbfffde4c)
(3)  817 mlton-compile 1165003845.199286 RET   ioctl -1 errno 25 Inappropriate ioctl for device
(3)  817 mlton-compile 1165003845.199313 CALL  ioctl(0x5,TIOCGETA,0xbfffde20)
(3)  817 mlton-compile 1165003845.199317 RET   ioctl -1 errno 25 Inappropriate ioctl for device
(3)  817 mlton-compile 1165003845.199321 CALL  fstat(0x5,0xbaaf80)
(3)  817 mlton-compile 1165003845.199336 RET   fstat 0
(2) 2939 as       1165003845.199347 NAMI  "/tmp/fileo9zyUP.o"
(3)  817 mlton-compile 1165003845.199348 CALL  lseek(0x5,0,0x1)
(3)  817 mlton-compile 1165003845.199353 RET   lseek 0
(2) 2939 as       1165003845.199400 RET   open 5
(2) 2939 as       1165003845.199408 CALL  write(0x5,0x78000,0xf64)
(2) 2939 as       1165003845.199446 RET   write 3940/0xf64
(2) 2939 as       1165003845.199451 CALL  close(0x5)
(2) 2939 as       1165003845.199461 RET   close 0
(3)  817 mlton-compile 1165003845.199850 CALL  close(0x5)
(3)  817 mlton-compile 1165003845.199930 RET   close 0

You can see that the assembler's call to open (with O_WRONLY | O_CREAT | 
O_TRUNC) and mlton's call to open (with O_WRONLY | O_CREAT | O_EXCL) are 
nearly simultaneous; in particular, mlton's call to open returns well 
before the assembler's call, so the presumably the assembler's invocation 
of open sees an existing file.

Although Apple uses a modified version of an ancient GNU assembler, this 
behavior is still around in the recent versions; On my linux box, I get 
the following:

[fluet at localhost tmp]$ strace -f -o strace.out gcc -c -o plugh.o z.c
[fluet at localhost tmp]$ cat strace.out
...
4370  stat("plugh.o", {st_mode=S_IFREG|0644, st_size=4616, ...}) = 0
4370  lstat("plugh.o", {st_mode=S_IFREG|0644, st_size=4616, ...}) = 0
4370  unlink("plugh.o")                 = 0
4370  open("plugh.o", O_RDWR|O_CREAT|O_TRUNC, 0666) = 3
...

I know I've done many simultaneous invocations of mlton and 'make all' on 
my (Opteron) linux box; I don't know why I've never encountered it there 
and can reproduce it (fairly) easily on my MacPro.

The bad news: This still doesn't explain my original posting, where the 
contention was on '/tmp/file6snPhX.15.c'.  The .c files that arise during 
a compilation are only opened for reading by gcc.  Now, mlton does open 
the .c file for writing twice: once via open with O_WRONLY | O_CREAT | 
O_EXCL to grab the filename and then once via open with O_WRONLY | O_CREAT 
| O_TRUNC to write the contents, but we never unlink it until after the 
call to the linker returns and we're cleaning up all intermediate files.


Longer ktrace/kdump output:

PROC1:
...
    634 mlton-compile 1165003848.426430 CALL  open(0x311b53c,0xa01,0x180)
    634 mlton-compile 1165003848.426433 NAMI  "/tmp/fileo9zyUP.o"
    634 mlton-compile 1165003848.426439 RET   open -1 errno 17 File exists
...

PROC2:
...
    724 mlton-compile 1165003845.165000 CALL  open(0x311a424,0xa01,0x180)
    724 mlton-compile 1165003845.165008 NAMI  "/tmp/fileo9zyUP.o"
    724 mlton-compile 1165003845.166025 RET   open 5
    724 mlton-compile 1165003845.166032 CALL  ioctl(0x5,FIODTYPE,0xbfffde4c)
    724 mlton-compile 1165003845.166037 RET   ioctl -1 errno 25 Inappropriate ioctl for device
    724 mlton-compile 1165003845.166041 CALL  ioctl(0x5,TIOCGETA,0xbfffde20)
    724 mlton-compile 1165003845.166044 RET   ioctl -1 errno 25 Inappropriate ioctl for device
    724 mlton-compile 1165003845.166048 CALL  fstat(0x5,0xbaaf80)
    724 mlton-compile 1165003845.166078 RET   fstat 0
    724 mlton-compile 1165003845.166090 CALL  lseek(0x5,0,0x1)
    724 mlton-compile 1165003845.166094 RET   lseek 0
    724 mlton-compile 1165003845.166597 CALL  close(0x5)
    724 mlton-compile 1165003845.166608 RET   close 0
...
   2939 as       1165003845.198909 CALL  stat(0xbfffec18,0xbfffe898)
   2939 as       1165003845.198913 NAMI  "/tmp/fileo9zyUP.o"
   2939 as       1165003845.198924 RET   stat 0
   2939 as       1165003845.198929 CALL  unlink(0xbfffec18)
   2939 as       1165003845.198932 NAMI  "/tmp/fileo9zyUP.o"
   2939 as       1165003845.199078 RET   unlink 0
   2939 as       1165003845.199085 CALL  open(0xbfffec18,0x601,0x1b6)
   2939 as       1165003845.199090 NAMI  "/tmp/fileo9zyUP.o"
   2939 as       1165003845.199347 NAMI  "/tmp/fileo9zyUP.o"
   2939 as       1165003845.199400 RET   open 5
   2939 as       1165003845.199408 CALL  write(0x5,0x78000,0xf64)
   2939 as       1165003845.199446 RET   write 3940/0xf64
   2939 as       1165003845.199451 CALL  close(0x5)
   2939 as       1165003845.199461 RET   close 0
...
   3574 i686-apple-darwi 1165003848.384211 CALL  access(0xbfffcfdb,0)
   3574 i686-apple-darwi 1165003848.384214 NAMI  "/tmp/fileo9zyUP.o"
   3574 i686-apple-darwi 1165003848.384218 RET   access 0
...
   3578 ld       1165003849.528330 CALL  open(0xbfffc626,0,0)
   3578 ld       1165003849.528334 NAMI  "/tmp/fileo9zyUP.o"
   3578 ld       1165003849.528342 RET   open 9
   3578 ld       1165003849.528345 CALL  fstat(0x9,0x660c0)
   3578 ld       1165003849.528349 RET   fstat 0
   3578 ld       1165003849.528374 CALL  close(0x9)
   3578 ld       1165003849.528379 RET   close 0
   3578 ld       1165003849.528418 CALL  write(0x2,0xbfff9bf0,0xd)
   3578 ld       1165003849.528461 RET   write 13/0xd
   3578 ld       1165003849.528467 CALL  write(0x2,0xbfff9c20,0x24)
   3578 ld       1165003849.528471 RET   write 36/0x24
   3578 ld       1165003849.528475 CALL  write(0x2,0xbfff9bf0,0x1)
   3578 ld       1165003849.528479 RET   write 1
   3578 ld       1165003849.528484 CALL  write(0x2,0xbfff9ba0,0x12)
   3578 ld       1165003849.528489 RET   write 18/0x12
   3578 ld       1165003849.528494 CALL  write(0x2,0xbfff9bc0,0x2f)
   3578 ld       1165003849.528498 RET   write 47/0x2f
   3578 ld       1165003849.528502 CALL  write(0x2,0xbfff9ba0,0x12)
   3578 ld       1165003849.528506 RET   write 18/0x12
   3578 ld       1165003849.528511 CALL  write(0x2,0xbfff9bc0,0x2f)
   3578 ld       1165003849.528539 RET   write 47/0x2f
...
    724 mlton-compile 1165003851.215862 CALL  access(0x311bc20,0)
    724 mlton-compile 1165003851.215866 NAMI  "/tmp/fileo9zyUP.o"
    724 mlton-compile 1165003851.215873 RET   access 0
    724 mlton-compile 1165003851.215876 CALL  unlink(0x311bc48)
    724 mlton-compile 1165003851.215909 NAMI  "/tmp/fileo9zyUP.o"
    724 mlton-compile 1165003851.216006 RET   unlink 0
...

PROC3:
...
    817 mlton-compile 1165003845.199086 CALL  open(0x3116c84,0xa01,0x180)
    817 mlton-compile 1165003845.199094 NAMI  "/tmp/fileo9zyUP.o"
    817 mlton-compile 1165003845.199276 RET   open 5
    817 mlton-compile 1165003845.199281 CALL  ioctl(0x5,FIODTYPE,0xbfffde4c)
    817 mlton-compile 1165003845.199286 RET   ioctl -1 errno 25 Inappropriate ioctl for device
    817 mlton-compile 1165003845.199313 CALL  ioctl(0x5,TIOCGETA,0xbfffde20)
    817 mlton-compile 1165003845.199317 RET   ioctl -1 errno 25 Inappropriate ioctl for device
    817 mlton-compile 1165003845.199321 CALL  fstat(0x5,0xbaaf80)
    817 mlton-compile 1165003845.199336 RET   fstat 0
    817 mlton-compile 1165003845.199348 CALL  lseek(0x5,0,0x1)
    817 mlton-compile 1165003845.199353 RET   lseek 0
    817 mlton-compile 1165003845.199850 CALL  close(0x5)
    817 mlton-compile 1165003845.199930 RET   close 0
...
   2947 as       1165003845.231873 CALL  stat(0xbfffec18,0xbfffe898)
   2947 as       1165003845.231877 NAMI  "/tmp/fileo9zyUP.o"
   2947 as       1165003845.231888 RET   stat 0
   2947 as       1165003845.231893 CALL  unlink(0xbfffec18)
   2947 as       1165003845.231896 NAMI  "/tmp/fileo9zyUP.o"
   2947 as       1165003845.232053 RET   unlink 0
   2947 as       1165003845.232058 CALL  open(0xbfffec18,0x601,0x1b6)
   2947 as       1165003845.232062 NAMI  "/tmp/fileo9zyUP.o"
   2947 as       1165003845.232172 RET   open 5
   2947 as       1165003845.232177 CALL  write(0x5,0x78000,0x778)
   2947 as       1165003845.232200 RET   write 1912/0x778
   2947 as       1165003845.232205 CALL  close(0x5)
   2947 as       1165003845.232214 RET   close 0
...
   4870 i686-apple-darwi 1165003858.239429 CALL  access(0xbfffc65d,0)
   4870 i686-apple-darwi 1165003858.239431 NAMI  "/tmp/fileo9zyUP.o"
   4870 i686-apple-darwi 1165003858.239457 RET   access -1 errno 2 No such file or directory
   4870 i686-apple-darwi 1165003858.239477 CALL  write(0x2,0xbfffad10,0x1e)
   4870 i686-apple-darwi 1165003858.239597 RET   write 30/0x1e
   4870 i686-apple-darwi 1165003858.239611 CALL  write(0x2,0xbfffad40,0x2c)
   4870 i686-apple-darwi 1165003858.239621 RET   write 44/0x2c
   4870 i686-apple-darwi 1165003858.239627 CALL  write(0x2,0xa0001cb3,0x1)
   4870 i686-apple-darwi 1165003858.239633 RET   write 1
...
    817 mlton-compile 1165003858.670080 CALL  access(0x3119fd8,0)
    817 mlton-compile 1165003858.670083 NAMI  "/tmp/fileo9zyUP.o"
    817 mlton-compile 1165003858.670111 RET   access -1 errno 2 No such file or directory
...




More information about the MLton mailing list