[issue19293] test_asyncio hanging for 1 hour

[David Edelsohn]

David Edelsohn added the comment:

AIX has an equivalent to strace (called truss). I have recorded all AIX system calls and signals for test_process_interactive, which hangs, following all children created by fock. The uncompressed file is 82MB or 939KB compressed.  The highlights are:

test_subprocess_interactive (test.test_asyncio.test_events.PollEventLoopTests) ... 
4588380:        64422135: close(3)                              = 0
4588380:        64422135: statx("/home/dje/src/cpython/Lib/test/test_asyncio/echo.py", 0x2FF20870, 128, 010) = 0
4588380:        64422135: kopen("/home/dje/src/cpython/Lib/test/test_asyncio/echo.py", O_RDONLY|O_LARGEFILE) = 3
4588380:        64422135: kioctl(3, 22528, 0x00000000, 0x00000000) Err#25 ENOTTY
4588380:        64422135: kfcntl(3, F_SETFD, 0x00000001)        = 0
4588380:        64422135: fstatx(0x00000003, 0x2FF229E8, 0x00000080, 0x00000008) = 0x00000000
4588380:        64422135: kioctl(3, 22528, 0x00000000, 0x00000000) Err#25 ENOTTY
4588380:        64422135: lseek(0x00000003, 0x00000000, 0x00000001) = 0x00000000
4588380:        64422135: kioctl(3, 22528, 0x00000000, 0x00000000) Err#25 ENOTTY
4588380:        64422135: kread(3, " i m p o r t   o s\n\n i".., 4096) = 110
4588380:        64422135: klseek(3, 4294967295, -108, 0x00000001) = 0
4588380:        64422135: klseek(3, 0, 0, 0x00000000)           = 0
4588380:        64422135: kread(3, " i m p o r t   o s\n\n i".., 4096) = 110
4588380:        64422135: kread(3, " i m p o r t   o s\n\n i".., 4096) = 0
4588380:        64422135: close(3)                              = 0
4588380:        64422135: kread(0, " P y t h o n   � � � � �".., 1024) = 7
4588380:        64422135: kwrite(0x00000001, 0x200CD0A0, 0x00000007) = 0x00000007
4588380:             0x00000000: " P y t h o n   � � � � �"..
59244954: 33161535: _poll(0x2067A970, 3, -1)            = 1
4588380:        64422135: kread(0, " � � � � � � � � � � � �".., 1024) = 0
4588380:        64422135: kwrite(0x00000001, 0x200CD0F0, 0x00000000) = 0x00000000
4588380:             0x00000000: " � � � � � � � � � � � �"..
4588380:        64422135: kread(0, " � � � � � � � � � � � �".., 1024) = 0
59244954: 33161535: __libc_sbrk(0x00000000)             = 0x20691220
4588380:        64422135: kwrite(0x00000001, 0x200CD140, 0x00000000) = 0x00000000
4588380:             0x00000000: " � � � � � � � � � � � �"..
4588380:        64422135: kread(0, " � � � � � � � � � � � �".., 1024) = 0
4588380:        64422135: kwrite(0x00000001, 0x200CD190, 0x00000000) = 0x00000000
4588380:             0x00000000: " � � � � � � � � � � � �"..
59244954: 33161535: kread(9, " P y t h o n   � � � � �".., 262144) = 7
4588380:        64422135: kread(0, " � � � � � � � � � � � �".., 1024) = 0
4588380:        64422135: kwrite(0x00000001, 0x200CD1E0, 0x00000000) = 0x00000000
4588380:             0x00000000: " � � � � � � � � � � � �"..
59244954: 33161535: _poll(0x2067A970, 3, 0)             = 0
4588380:        64422135: kread(0, " � � � � � � � � � � � �".., 1024) = 0
4588380:        64422135: kwrite(0x00000001, 0x200D66C0, 0x00000000) = 0x00000000
4588380:             0x00000000: " � � � � � � � � � � � �"..
59244954: 33161535: _poll(0x2067A970, 3, 0)             = 0
4588380:        64422135: kread(0, " � � � � � � � � � � � �".., 1024) = 0
4588380:        64422135: kwrite(0x00000001, 0x200CD0A0, 0x00000000) = 0x00000000
4588380:             0x00000000: " � � � � � � � � � � � �"..
59244954: 33161535: _poll(0x2067A970, 3, 0)             = 04588380:     64422135: kread(0, " � � � � � � � � � � � �"..
, 1024)
 = 0
4588380:        64422135: kwrite(0x00000001, 0x200CD0F0, 0x00000000) = 0x00000000
4588380:             0x00000000: " � � � � � � � � � � � �"..
4588380:        64422135: kread(0, " � � � � � � � � � � � �".., 1024) = 0
59244954: 33161535: _poll(0x2067A970, 3, 0)             = 0
4588380:        64422135: kwrite(0x00000001, 0x200CD140, 0x00000000) = 0x00000000
4588380:             0x00000000: " � � � � � � � � � � � �"..
4588380:        64422135: kread(0, " � � � � � � � � � � � �".., 1024) = 0
4588380:        64422135: kwrite(0x00000001, 0x200CD190, 0x00000000) = 0x00000000
4588380:             0x00000000: " � � � � � � � � � � � �"..
4588380:        64422135: kread(0, " � � � � � � � � � � � �".., 1024) = 0
4588380:        64422135: kwrite(0x00000001, 0x200CD1E0, 0x00000000) = 0x00000000
4588380:             0x00000000: " � � � � � � � � � � � �"..
4588380:        64422135: kread(0, " � � � � � � � � � � � �".., 1024) = 0
4588380:        64422135: kwrite(0x00000001, 0x200D66C0, 0x00000000) = 0x00000000
4588380:             0x00000000: " � � � � � � � � � � � �"..
4588380:        64422135: kread(0, " � � � � � � � � � � � �".., 1024) = 0
4588380:        64422135: kwrite(0x00000001, 0x200CD0A0, 0x00000000) = 0x00000000
4588380:             0x00000000: " � � � � � � � � � � � �"..

And it sits in this read/write loop with some intermittent _poll timeouts until I send SIGINT.

----------

_______________________________________
Python tracker <report at bugs.python.org>
<http://bugs.python.org/issue19293>
_______________________________________