From owner-freebsd-ports@freebsd.org Thu Apr 11 14:39:32 2019 Return-Path: Delivered-To: freebsd-ports@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 6947315862C7 for ; Thu, 11 Apr 2019 14:39:32 +0000 (UTC) (envelope-from konstantin@schukraft.org) Received: from server949-han.de-nserver.de (server949-han.de-nserver.de [77.75.250.185]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 3DC5C6A489 for ; Thu, 11 Apr 2019 14:39:30 +0000 (UTC) (envelope-from konstantin@schukraft.org) Received: (qmail 757 invoked from network); 11 Apr 2019 16:39:28 +0200 X-Fcrdns: Yes Received: from host-509ff86b.1-h.de.terastrm.net (HELO laparbeit) (80.159.248.107) (smtp-auth username konstantin@schukraft.org, mechanism plain) by server949-han.de-nserver.de (qpsmtpd/0.92) with (ECDHE-RSA-AES256-GCM-SHA384 encrypted) ESMTPSA; Thu, 11 Apr 2019 16:39:28 +0200 Date: Thu, 11 Apr 2019 16:39:26 +0200 From: Konstantin Schukraft To: Jan Bramkamp Cc: freebsd-ports@freebsd.org Subject: Re: python 3 subprocess performance Message-ID: <20190411143926.5rg4jskmodt4shhi@laparbeit> References: <20190411161649.1b740d21@vm2.home.zagrebin.ru> <8f3f8413-60f2-bb03-a6b4-4f6364cdc3df@rlwinm.de> MIME-Version: 1.0 Content-Type: multipart/signed; micalg=pgp-sha256; protocol="application/pgp-signature"; boundary="kwzmq4cyo2whxe62" Content-Disposition: inline In-Reply-To: <8f3f8413-60f2-bb03-a6b4-4f6364cdc3df@rlwinm.de> User-Agent: NeoMutt/20171215 X-User-Auth: Auth by konstantin@schukraft.org through 80.159.248.107 X-Rspamd-Queue-Id: 3DC5C6A489 X-Spamd-Bar: -- Authentication-Results: mx1.freebsd.org X-Spamd-Result: default: False [-2.17 / 15.00]; TO_DN_SOME(0.00)[]; RCVD_COUNT_THREE(0.00)[3]; MX_GOOD(-0.01)[mail.schukraft.org]; RCPT_COUNT_TWO(0.00)[2]; SIGNED_PGP(-2.00)[]; FROM_EQ_ENVFROM(0.00)[]; R_DKIM_NA(0.00)[]; MIME_TRACE(0.00)[0:+,1:+]; ASN(0.00)[asn:34432, ipnet:77.75.250.0/23, country:DE]; RCVD_TLS_LAST(0.00)[]; ARC_NA(0.00)[]; NEURAL_HAM_MEDIUM(-0.87)[-0.869,0]; FROM_HAS_DN(0.00)[]; NEURAL_SPAM_SHORT(0.39)[0.391,0]; NEURAL_HAM_LONG(-0.99)[-0.985,0]; MIME_GOOD(-0.20)[multipart/signed,text/plain]; DMARC_NA(0.00)[schukraft.org]; AUTH_NA(1.00)[]; TO_MATCH_ENVRCPT_SOME(0.00)[]; RCVD_IN_DNSWL_NONE(0.00)[185.250.75.77.list.dnswl.org : 127.0.10.0]; R_SPF_NA(0.00)[]; MID_RHS_NOT_FQDN(0.50)[]; IP_SCORE(-0.00)[country: DE(-0.01)] X-BeenThere: freebsd-ports@freebsd.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Porting software to FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 11 Apr 2019 14:39:32 -0000 --kwzmq4cyo2whxe62 Content-Type: text/plain; charset=utf-8; format=flowed Content-Disposition: inline >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: 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@freebsd.org mailing list >https://lists.freebsd.org/mailman/listinfo/freebsd-ports >To unsubscribe, send any mail to "freebsd-ports-unsubscribe@freebsd.org" --kwzmq4cyo2whxe62 Content-Type: application/pgp-signature; name="signature.asc" -----BEGIN PGP SIGNATURE----- iHUEARYIAB0WIQT5hlD1gMfKZVmJgKBt4hVX4L8dwAUCXK9RnQAKCRBt4hVX4L8d wLjEAP9HSu9LxFw4msWVmXaTnL4oPCY2d2Q8vr47cNcgJVSYugD+JL32jVO+NPqw 2px/iCIvt0kUdOImWUXMu7G8koaNLQE= =rJ5k -----END PGP SIGNATURE----- --kwzmq4cyo2whxe62--