in reply to Re^2: Is this absurd, or have I not RTFM?
in thread Is this absurd, or have I not RTFM?

That smells like a buffering issue.

Data in intermediate stdio or PerlIO write buffers can become duplicated when forking. Try setting $| = 1.

Replies are listed 'Best First'.
Re^4: Is this absurd, or have I not RTFM?
by petermogensen (Sexton) on May 19, 2014 at 08:19 UTC

    Buffering doesn't explain why the two calls to DESTROY in the same process are handed different references to the same Perl object.

    I tried running with $|=1 ... it's still reproducible. If you try sufficient amount of times.

    auto-flushing can however explain why there's sometimes missing an "END DESTROY" output line. It's probably lost in a buffer when the process exits. It doesn't explain why DESTROY is called twice in the same process with different argument references to the same blessed Perl object.

      The documentation for $$ on perlvar talks about some problem with that variable being cached.

      Maybe running the program with strace could throw some light on this.

        perl5160delta talks about that , it says $$ no longer caches PID ... for some reason (sleepy) I thought petermogensen was testing on 5.16 :)

        This is interesting ... I should probably have done strace on this small example before. When I had a much larger example it gave way too much output. Anyway...

        Starting the server and attaching an strace to both the parent and the child shows the behaviour of the child:

        accept(3, 0x7fffc9d87e50, [4096]) = ? ERESTARTSYS (To be restart +ed) --- SIGINT (Interrupt) @ 0 (0) --- rt_sigreturn(0) = -1 EINTR (Interrupted system + call) rt_sigprocmask(SIG_BLOCK, [INT], [], 8) = 0 rt_sigaction(SIGINT, NULL, {0x7f2796926bf0, [], SA_RESTORER, 0x7f27965 +044a0}, 8) = 0 rt_sigprocmask(SIG_UNBLOCK, [INT], NULL, 8) = 0 write(1, "======= BEGIN DESTROY:11977====="..., 36) = 36 write(2, "SV = ", 5) = 5 write(2, "IV(0x24c39a8) at 0x24c39b8\n REF"..., 65) = 65 write(2, " RV = 0x1ffab78\n", 17) = 17 write(2, " ", 2) = ? ERESTARTSYS (To be restart +ed) --- SIGTERM (Terminated) @ 0 (0) --- rt_sigreturn(0) = -1 EINTR (Interrupted system + call) ...
        And later ...
        write(2, " ", 2) = 2 write(1, "======= BEGIN DESTROY:11977====="..., 36) = 36 write(2, "SV = ", 5) = 5 write(2, "IV(0x24c38a0) at 0x24c38b0\n REF"..., 65) = 65 write(2, " RV = 0x1ffab78\n", 17) = 17 write(2, " ", 2) = 2 write(2, "SV = ", 5) = 5 write(2, "PVHV(0x2001880) at 0x1ffab78\n "..., 75) = 75 write(2, " ", 2) = 2 write(2, " STASH = 0x2019d40", 19) = 19 write(2, "\t\"MyModule\"\n", 12) = 12 write(2, " ", 2) = 2 write(2, " ARRAY = 0x0", 13) = 13 write(2, "\n", 1) = 1 write(2, " ", 2) = 2 write(2, " KEYS = 0\n", 11) = 11 write(2, " ", 2) = 2 write(2, " FILL = 0\n", 11) = 11 write(2, " ", 2) = 2 write(2, " MAX = 7\n", 10) = 10 write(2, " ", 2) = 2 write(2, " RITER = -1\n", 13) = 13 write(2, " ", 2) = 2 write(2, " EITER = 0x0\n", 14) = 14 write(1, "============ END DESTROY:11977=="..., 39) = 39 close(3) = 0 close(6) = 0 close(4) = 0 close(5) = 0 exit_group(0) = ? Process 11977 detached

        So it really does start DESTROY twice.