On 2016-12-10 13:21-0800 Alan W. Irwin wrote: [...] > So instead of pursuing this with inserting timing statements like you > are thinking about, instead I plan to simply insert more debug prints, > e.g., "PLMemoryMap::create: entering", PLMemoryMap::create: calling > close" in the PLMemoryMap::create and PLMemoryMap::close code. With > the idea I do a binary search to find exactly which system call is > causing that long pause. Of course, my initial result might be the > long pause might not be in PLMemoryMap at all. So we will see how > this goes, and I hope to have some results for you in an hour or so > from now.
Hi Phil: See commit 7756f60 for the tonne of new debug print statements I have inserted. With those I got what appears naively to me is a "deadlock" situation when attempting to delete m_name. (However, I emphasize naive because I don't really understand C++ that well so I may be missing something obvious). Anyhow, I hope you will have a fast look at these results and give me your comments on this "deadlock" and also my other conclusions assuming it is not a deadlock at all. First here are the results of the latest "two x01c example execution" test. software@raven> time examples/c/x01c -dev wxwidgets -np; echo "done x01c"; time examples/c/x01c -dev wxwidgets -np;echo "done x01c" PLplot library version: 5.11.1 [from -dev wxwidgets?] PLMemoryMap::close: just entering close PLMemoryMap::create: (mustNotExist) calling shm_open PLMemoryMap::create: shm_open was a success for plplotMemoryMapSNULFSEKQE PLMemoryMap::create: (mustNotExist) calling ftruncate PLMemoryMap::create: calling mmap PLMemoryMap::create: finished with call of mmap [from wxPLViewer?] PLMemoryMap::close: just entering close PLMemoryMap::create: (mustExist) calling shm_open PLMemoryMap::create: shm_open was a success for plplotMemoryMapSNULFSEKQE PLMemoryMap::create: calling mmap PLMemoryMap::create: finished with call of mmap [from -dev wxwidgets?] PLMemoryMap::close: just entering close PLMemoryMap::close: calling munmap PLMemoryMap::close: calling shm_unlink PLMemoryMap::close: shm_unlink was a success for plplotMemoryMapSNULFSEKQE PLMemoryMap::close: start deleting m_name PLMemoryMap::close: end deleting m_name real 0m0.280s user 0m0.036s sys 0m0.020s done x01c PLplot library version: 5.11.1 [from wxPLViewer] PLMemoryMap::close: just entering close PLMemoryMap::close: calling munmap PLMemoryMap::close: calling shm_unlink PLMemoryMap::close: shm_unlink error PLMemoryMap::close: No such file or directory PLMemoryMap::close: start deleting m_name PLMemoryMap::close: end deleting m_name PLMemoryMap::close: just entering close [long pause] [from -dev wxwidgets?] PLMemoryMap::close: just entering close PLMemoryMap::create: (mustNotExist) calling shm_open PLMemoryMap::create: shm_open was a success for plplotMemoryMapRZUTHPBSHB PLMemoryMap::create: (mustNotExist) calling ftruncate PLMemoryMap::create: calling mmap PLMemoryMap::create: finished with call of mmap [from wxPLViewer?] PLMemoryMap::close: just entering close PLMemoryMap::create: (mustExist) calling shm_open PLMemoryMap::create: shm_open was a success for plplotMemoryMapRZUTHPBSHB PLMemoryMap::create: calling mmap PLMemoryMap::create: finished with call of mmap [from -dev wxwidgets?] PLMemoryMap::close: just entering close PLMemoryMap::close: calling munmap PLMemoryMap::close: calling shm_unlink PLMemoryMap::close: shm_unlink was a success for plplotMemoryMapRZUTHPBSHB PLMemoryMap::close: start deleting m_name PLMemoryMap::close: end deleting m_name real 0m11.311s user 0m0.048s sys 0m0.008s done x01c [from wxPLViewer] software@raven> PLMemoryMap::close: just entering close PLMemoryMap::close: calling munmap PLMemoryMap::close: calling shm_unlink PLMemoryMap::close: shm_unlink error PLMemoryMap::close: No such file or directory PLMemoryMap::close: start deleting m_name PLMemoryMap::close: end deleting m_name PLMemoryMap::close: just entering close As you can see from the above results and the commit, I have inserted debug printout almost everywhere in PLMemoryMap::create and PLMemoryMap::close. Note I have tentatively (note question marks) identified which sections of output belong to -dev wxwidgets and which to wxPLViewer (except after the "done x01c" output it must be wxPLViewer so I have dropped the question marks in those cases). Do you agree with those identifications? Also note that several times we have PLMemoryMap::close: just entering close with nothing happening in close afterwards meaning your if statements are set up for that particular call to close in such a way that nothing is executed in close. Anyhow, the "deadlock" that concerns me is in the messages that must be purely from wxPLViewer where just before the long pause we have [from wxPLViewer] PLMemoryMap::close: just entering close PLMemoryMap::close: calling munmap PLMemoryMap::close: calling shm_unlink PLMemoryMap::close: shm_unlink error PLMemoryMap::close: No such file or directory PLMemoryMap::close: start deleting m_name PLMemoryMap::close: end deleting m_name PLMemoryMap::close: just entering close So it appears that wxPLViewer is executing its destructor, there is an error there because shm_unlink has already been called by -dev wxwidgets for that shared memory (but that is likely irrelevant, and near the end of that process it finishes deleting m_name, but then that destructor is called again afterwards. Doesn't that cause a problem or is that just naturally expected for C++ destructors? If that is expected, then that last message above corresponds to absolutely nothing happening in the (last) destructor. Which means the long pause is due to something else entirely than anything in PLMemoryMap::create or PLMemoryMap::close! Which would be some important progress in finding the cause of the long pause, but there is more work to do to nail this down. Anyhow, this time I really have pretty much come to the end of how much I can try additional print statements, but I could certainly act as a sounding board in the days ahead as you figure out the exact cause of the long pause. But you should note the long pause occurs in the -dev wxwidgets code (i.e. not PLViewer). The first debug output after that long pause is [from -dev wxwidgets?] PLMemoryMap::close: just entering close PLMemoryMap::create: (mustNotExist) calling shm_open where that PLMemoryMap::close: just entering close with nothing further happening in close is the result of the close() call at the start of PLMemoryMap::create, and the next printout occurs just before the next system call (to shm_open in this case). So these results are a clear indication the long pause is caused by something happening in the -dev wxwidgets code _before_ PLMemoryMap::create or PLMemoryMap::close are even called. So it is in that other code that you should insert debug print statements or timing commands. Alan __________________________ Alan W. Irwin Astronomical research affiliation with Department of Physics and Astronomy, University of Victoria (astrowww.phys.uvic.ca). Programming affiliations with the FreeEOS equation-of-state implementation for stellar interiors (freeeos.sf.net); the Time Ephemerides project (timeephem.sf.net); PLplot scientific plotting software package (plplot.sf.net); the libLASi project (unifont.org/lasi); the Loads of Linux Links project (loll.sf.net); and the Linux Brochure Project (lbproject.sf.net). __________________________ Linux-powered Science __________________________ ------------------------------------------------------------------------------ Developer Access Program for Intel Xeon Phi Processors Access to Intel Xeon Phi processor-based developer platforms. With one year of Intel Parallel Studio XE. Training and support from Colfax. Order your platform today.http://sdm.link/xeonphi _______________________________________________ Plplot-devel mailing list Plplot-devel@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/plplot-devel
