in reply to Re^4: Diagnosing blocking io (or: finding the WHY of my Open2 woes).
in thread Diagnosing blocking io (or: finding the WHY of my Open2 woes).

Call strace with the -f option to have it trace forked processes as well (i.e. the js interpreter).

Comparing the output you get with what you get when doing the same steps interactively, would certainly help to figure out what's different. In particular look for the read(0, ...) calls from the subprocess.

Replies are listed 'Best First'.
Calling strace -f
by Socrates (Acolyte) on Nov 19, 2008 at 20:21 UTC

    This appears to be the relevant output, but I'm not as familiar with strace as I'd like to be:

    mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, + 0) = 0xb7b8a000 read(0, "load(\'jslint.js\');\nfoo=0;\nEND\n", 1024) = 30 read(0, "", 1024) = 0 read(0, "", 1024) = 0 close(0) = 0 munmap(0xb7b8a000, 4096) = 0 brk(0x8092000) = 0x8092000 open("jslint.js", O_RDONLY) = 0 fstat64(0, {st_mode=S_IFREG|0644, st_size=147870, ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, + 0) = 0xb7b8a000 read(0, "// (C)2002 Douglas Crockford\n// "..., 4096) = 4096 read(0, " \"lawngreen\": true,\n "..., 4096) = 4096 read(0, "iframe: {},\n img: {\n "..., 4096) = 4096 read(0, " convertPathToHFS: true,\n "..., 4096) = 4096 brk(0x80b3000) = 0x80b3000 read(0, "ption.safe) {\n if (op"..., 4096) = 4096 read(0, " errorAt(\"Expected \'{a}\' and in"..., 4096) = 4096 read(0, ", character + j);\n "..., 4096) = 4096 read(0, " }\n "..., 4096) = 4096 read(0, " line: line,\n "..., 4096) = 4096 read(0, " q += "..., 4096) = 4096 brk(0x80d4000) = 0x80d4000 read(0, " }\n "..., 4096) = 4096 read(0, " l += 1;\n "..., 4096) = 4096 read(0, " break;\n case \'/*jsl"..., 4096) = 4096 read(0, "efault:\n warning("..., 4096) = 4096 read(0, " x.nud = (typeof f === \'funct"..., 4096) = 4096 read(0, "n);\n nonadjacent(toke"..., 4096) = 4096 brk(0x80f5000) = 0x80f5000 read(0, "SAFE.go.\', nexttoken);\n "..., 4096) = 4096 read(0, " warning(\"Expec"..., 4096) = 4096 read(0, " warning(\"Expected a "..., 4096) = 4096 read(0, "rder-top-style\': cssBorderStyle,"..., 4096) = 4096 read(0, "\', \'hidden\', \'collapse\'],\n "..., 4096) = 4096 brk(0x8116000) = 0x8116000 read(0, "== \'important\') {\n "..., 4096) = 4096 read(0, " while (nexttoken.id !== \'</\'"..., 4096) = 4096 read(0, " if (option.adsafe && stack."..., 4096) = 4096 read(0, "f (nexttoken.id && nexttoken.id."..., 4096) = 4096 read(0, " if (t.name !== n) {\n "..., 4096) = 4096 read(0, " case \'label\':\n "..., 4096) = 4096 brk(0x8137000) = 0x8137000 read(0, "\');\n syntax[\'--\'].exps = true"..., 4096) = 4096 read(0, " advance(\'.\');\n "..., 4096) = 4096 read(0, "tation();\n }\n "..., 4096) = 4096 read(0, " }\n for (;;) {\n "..., 4096) = 4096 brk(0x8158000) = 0x8158000 read(0, "ance(\')\', t);\n nospace(pr"..., 4096) = 4096 read(0, "exttoken.id === \'var\') {\n "..., 4096) = 4096 read(0, "eserve(\'let\');\n reserve(\'supe"..., 4096) = 4096 read(0, " approved[option.approved["..., 4096) = 4096 read(0, " + (isFinite(c.line) ? \' at line"..., 4096) = 4096 brk(0x8179000) = 0x8179000 read(0, "ength; i += 1) {\n var"..., 4096) = 414 read(0, "", 4096) = 0 close(0) = 0 munmap(0xb7b8a000, 4096) = 0

    And if stops here until killed with ctrl-c, at which point it says "Process X detached", and I have to hunt down and kill the js process.

    I can see where it is receiving the output from the perl script:

    read(0, "load(\'jslint.js\');\nfoo=0;\nEND\n", 1024) = 30

    And the series of reads that begin with:

    read(0, "// (C)2002 Douglas Crockford\n// "..., 4096) = 4096

    Appears to be where it loads jslint.js from the disk in blocks, but then nothing else appears to happen, which is interesting. If I execute it from the command-line, this is the output (starting from the last read() from the source file:

    read(3, "ength; i += 1) {\n var"..., 4096) = 414 read(3, "", 4096) = 0 close(3) = 0 munmap(0xb7af6000, 4096) = 0 fstat64(0, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, + 0) = 0xb7af6000 read(0, foo=bar; "foo=bar;\n", 1024) = 9 read(0, END "END\n", 1024) = 4 write(1, "jslint: No problems found.\n", 27jslint: No problems found. ) = 27 write(1, "\n", 1 ) = 1 exit_group(3) = ?

    So, it displays "read(0" from the terminal. What is that telling me, precisely? Does this mean that, once it enters into the "input=readline();" loop, it sends the read signal when in a terminal, but not otherwise? If so, I guess that's my answer.

      read(0, "load(\'jslint.js\');\nfoo=0;\nEND\n", 1024) = 30 read(0, "", 1024) = 0 read(0, "", 1024) = 0 close(0) = 0 <-- !!! munmap(0xb7b8a000, 4096) = 0 brk(0x8092000) = 0x8092000 open("jslint.js", O_RDONLY) = 0

      I think the problem is this close(0). Because of it, the file descriptor is being reused in the subsequent open("jslint.js" (as the lowest available file descriptor) when the js interpreter is reading in the jslint.js file, at the end of which it gets closed again... Anyhow, the net effect of this is that stdin (which is expected to be connected to the pipe) is no longer open when your line=readline() is trying to read from it. Thus the readline is failing, and the while (true) {...} keeps looping forever...

      Note that when being run interactively, the jslint.js file is read in via a different file descriptor, and stdin (file descriptor 0) can still be read from afterwards.

      I'd suspect the undesirable close(0) has to do with you closing the other end of the pipe ($JSWRITE) before the js interpreter starts executing the load('jslint.js'); command you sent it.  So that's where I would start fiddling... (if I really wanted to know :)

        I tried commenting out that line, and I get:
        ... ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbf99e438) = -1 EINVAL (Inval +id argument) fstat64(0, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, + 0) = 0xb7b62000 read(0, "load(\'jslint.js\');\nfoo=0;\nEND\nqu"..., 1024) = 38 read(0,

        So, it's not even to the point where it's processing the information coming from perl. It hasn't even loaded jslint.js yet. I think I get it. So let's see if I'm understanding this properly:

        While perl may be properly autoflushing, the interpreter is still buffering its read. Since the socket(?) is still open, it doesn't know to close it and flush.

        When it does close it and flush, it is acutally waiting to make use of the rest of the string ("foo=0;\nEND\n") AFTER the readline loop. So it would be as if I had done something like this (which also freezes):

        $ echo -e "load('jslint.js');\nfoo=0;\nEND\n" |/usr/bin/js

        Hence, the rock and hard place are that, if I don't close $JSWRITE in a timely manner, the interpreter won't know to flush its read buffer and continue, but if I do close $JSWRITE, there's nothing for the readline() loop to read from anymore.

        So it's not so much that my Perl code isn't outputting correctly, it's that the interpreter is accepting/buffering input in an incompatible way?