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

/me nods ...

Yes, and therefore, the anomaly that stands out to me in the OP is this: 

======= BEGIN DESTROY:9980========
======= BEGIN DESTROY:9980========
============ END DESTROY:9980========
======= BEGIN DESTROY:9979========
============ END DESTROY:9979========

[download]

Now, this might not be complete, so there might well be more to it than is shown and maybe this pattern is not repeatable.   We would need to see the entire display and maybe several instances of it to see if it is basically a timing-artifact.   But I believe that I saw the same basic behavior in other follow-ups to this thread also.   The first BEGIN for pid #9980 is not followed by an END ... ever.   It’s followed by another BEGIN, which is followed by END, as is the display for the second pid #9979.   (I do not presume which one of these is actually the child and which one is the parent ... PID-assignments are assumed-random.)

In the complete display, I expect that the BEGIN and END calls should be evenly matched, regardless of the exact order in which they occur.   If they are not, then I no longer accept the premise that “the destructor is ‘being called twice.’”   (Lemma:   If it is called twice, then it should end twice.   Destructors are nothing more than de-initialization subroutines.   They should run to completion.)   If they do not, then perhaps a runtime error is being thrown that we cannot see here.   I am sensitive to the Red-Herring Effect here . . . I smell a fish.   It would be very, very easy to mis-interpret what is being presented here.   Yeah, I think that the presumption that there is something wrong with the destructor-system should well be called, for the moment at least, “absurd(ly improbable).”   Sufficiently improbable to smell like seafood.   So, what else might it be.

Replies are listed 'Best First'.
Re^4: Is this absurd, or have I not RTFM?
by morgon (Priest) on May 19, 2014 at 13:40 UTC
    I've tried it with 5.18.1 on Debian testing and I got a run that looked like this: 
    2014/05/19-15:32:58 Server closing!
======= BEGIN DESTROY:16356========
============ END DESTROY:16356========
======= BEGIN DESTROY:16355========
============ END DESTROY:16355========
======= BEGIN DESTROY:16356========
============ END DESTROY:16356========

    [download]
    So everything is balanced nicely but the destructor for 16366 ran twice.

    Could it be that the parent forks, child exits parent forks again, second child gets the same pid than the previously exited child?

    So that the identical pids actually refer to different processes? But afik pids simply increase before they wrap around so that should not be possible.

[reply]
[d/l]

      I should maybe say that I have seen that happen too... It's not 100% certain that there's an "END" missing. But mostly it is. .. and that could well change with other versions of OS/Perl/Net::Server.

      The main problem is that DESTROY is called twice. Doing an strace of the process reveals that it's called twice in the same trace.

      Also... this can happen in both parent and child (though I've never seen it in more than one process at a time)

[reply]
Re^4: Is this absurd, or have I not RTFM?
by petermogensen (Sexton) on May 19, 2014 at 13:18 UTC

    I think we have already concluded that the non-balanced BEGIN/END printouts can be explained by the process being interrupted by a signal before it reaches the code or the buffer is flushed. ... see straces above

    What puzzles me is that this all causes Perl to redo the entire destruction of the perl object - passing DESTROY a new reference to the same object.

    It might be that the shutdown of the one process causes an interrupt in the other process due to their IPC (preforking uses an IPC mechanism for managing workers). I've seen this happen hundred of times now, sometimes in the parent, sometimes in a child... but only ever in 1 process out of N workers + a parent.

    So there might be a Net::Server bug causing unorderly shutdown of the processes... but anyway... That should result in DESTROY methods not being called. Not that Perl calls the DESTROY method twice in the same process

[reply]
      passing DESTROY a new reference to the same object

      When perl finds that the ref count to some object becomes 0 it creates a new variable holding a reference to it which is then used to invoke DESTROY.

      When it has to do it twice, two variables are created.

[reply]

        Yes.... I know.

[reply]

      passing DESTROY a new reference to the same object.

      Of course it's a new reference. The object only gets destroyed when nothing refers to the object (or when in global destruction), so a reference must be created to pass to DESTROY.

[reply]
        Yes yes... I know. There's still a calling-DESTORY-twice bug though.
[reply]

In Section Seekers of Perl Wisdom