python 3 subprocess performance

[Konstantin Schukraft]

>Please run python under truss -f. Does it try to close(2) all possible
>file descriptors? Does the runtime decrease if fdescfs is mounted at
>/dev/fd?
truss -f -p 17407

17407: read(5,0x1265d2e9120,50000)               = 0 (0x0)
17407: close(5)                                  = 0 (0x0)
17407: lseek(3,0x0,SEEK_CUR)                     ERR#29 'Illegal seek'
17407: fstat(3,{ mode=p--------- ,inode=1610971,size=0,blksize=4096 }) = 0 (0x0)
17407: read(3,"FreeBSD midgard 12.0-STABLE-HBSD"...,8192) = 88 (0x58)
17407: read(3,0x1265ceda078,8104)                = 0 (0x0)
17407: close(3)                                  = 0 (0x0)
17407: wait4(1948,{ EXITED,val=0 },0x0,0x0)      = 1948 (0x79c)
17407: write(1,"63\n",3)                         = 3 (0x3)
17407: pipe2(0x63857dad22e8,O_CLOEXEC)           = 0 (0x0)
17407: fstat(3,{ mode=p--------- ,inode=1610975,size=0,blksize=4096 }) = 0 (0x0)
17407: ioctl(3,TIOCGETA,0x63857dad21a0)          ERR#25 'Inappropriate ioctl for device'
17407: lseek(3,0x0,SEEK_CUR)                     ERR#29 'Illegal seek'
17407: pipe2(0x63857dad21e8,O_CLOEXEC)           = 0 (0x0)
17407: sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGILL|SIGTRAP|SIGABRT|SIGEMT|SIGFPE|SIGKILL|SIGBUS|SIGSEGV|SIGSYS|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|
SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
97164: <new process>
17407: fork()                                    = 97164 (0x17b8c)
97164: thr_self(0x1265c7e9000)                   = 0 (0x0)
17407: sigprocmask(SIG_SETMASK,{ },0x0)          = 0 (0x0)
97164: sigprocmask(SIG_SETMASK,{ },0x0)          = 0 (0x0)
97164: close(3)                                  = 0 (0x0)
97164: close(5)                                  = 0 (0x0)
17407: close(6)                                  = 0 (0x0)
97164: dup2(4,1)                                 = 1 (0x1)
17407: close(4)                                  = 0 (0x0)
97164: dup2(4,2)                                 = 2 (0x2)
97164: sigprocmask(SIG_SETMASK,{ SIGHUP|SIGINT|SIGQUIT|SIGILL|SIGTRAP|SIGABRT|SIGEMT|SIGFPE|SIGKILL|SIGBUS|SIGSEGV|SIGSYS|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPRO
F|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
97164: sigaction(SIGPIPE,{ SIG_DFL 0x0 ss_t },{ SIG_IGN 0x0 ss_t }) = 0 (0x0)
97164: sigprocmask(SIG_SETMASK,{ },0x0)          = 0 (0x0)
97164: sigprocmask(SIG_SETMASK,{ SIGHUP|SIGINT|SIGQUIT|SIGILL|SIGTRAP|SIGABRT|SIGEMT|SIGFPE|SIGKILL|SIGBUS|SIGSEGV|SIGSYS|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPRO
F|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
97164: sigaction(SIGXFSZ,{ SIG_DFL 0x0 ss_t },{ SIG_IGN 0x0 ss_t }) = 0 (0x0)
97164: sigprocmask(SIG_SETMASK,{ },0x0)          = 0 (0x0)
97164: fstatat(AT_FDCWD,"/dev",{ mode=dr-xr-xr-x ,inode=2,size=512,blksize=4096 },0x0) = 0 (0x0)
97164: fstatat(AT_FDCWD,"/dev/fd",{ mode=dr-xr-xr-x ,inode=135,size=512,blksize=4096 },0x0) = 0 (0x0)
97164: getrlimit(RLIMIT_NOFILE,{ cur=940563,max=940563 }) = 0 (0x0)
97164: close(3)                                  ERR#9 'Bad file descriptor'
97164: close(4)                                  = 0 (0x0)
97164: close(5)                                  ERR#9 'Bad file descriptor'
97164: close(7)                                  ERR#9 'Bad file descriptor'
97164: close(8)                                  ERR#9 'Bad file descriptor'
97164: close(9)                                  ERR#9 'Bad file descriptor'

The last error repeats several 10000 times.

Mounting fdescfs does indeed speed python3 up to python2 levels.

>On 11.04.19 15:16, Alexander Zagrebin wrote:
>> Hi!
>>
>> I've noticed the subprocess performance issue with python 3.
>> For example, this simple script takes just 0,15 second to complete
>> with python 2.7, but more than 5 sec with python 3.6:
>>
>> import subprocess
>>
>> for i in range(100):
>>     p = subprocess.Popen(['uname', '-a'], stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
>>     (stdoutdata, stderrdata) = p.communicate()
>>
>> Profiling with the cProfile shows, that this excessive 5 seconds was
>> wasted in the "{built-in method posix.read}"
>>
>> Could anybody confirm this issue?
>>
>_______________________________________________
>freebsd-ports at freebsd.org mailing list
>https://lists.freebsd.org/mailman/listinfo/freebsd-ports
>To unsubscribe, send any mail to "freebsd-ports-unsubscribe at freebsd.org"
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 228 bytes
Desc: not available
URL: <http://lists.freebsd.org/pipermail/freebsd-ports/attachments/20190411/2699cf6d/attachment.sig>