Date: Thu, 11 Apr 2019 17:32:42 +0200 From: Jan Bramkamp <crest@rlwinm.de> To: Konstantin Schukraft <konstantin@schukraft.org> Cc: freebsd-ports@freebsd.org Subject: Re: python 3 subprocess performance Message-ID: <9729db47-12c4-caf4-cdcf-1913dab73c8e@rlwinm.de> In-Reply-To: <20190411143926.5rg4jskmodt4shhi@laparbeit> References: <20190411161649.1b740d21@vm2.home.zagrebin.ru> <8f3f8413-60f2-bb03-a6b4-4f6364cdc3df@rlwinm.de> <20190411143926.5rg4jskmodt4shhi@laparbeit>
next in thread | previous in thread | raw e-mail | index | archive | help
The reason is that that python does something stupid (tm). It tries to close all file descriptors (except a few whitelisted ones) up to the maximum file descriptor number. It does this by asking the kernel for the maximum possible number and closing everything it doesn't want to keep. Some time later someone came up with an optimization (read the open file descriptors from /dev/fd). All of this pain and suffering is caused by good old Ulrich Drepper braindamage: https://sourceware.org/bugzilla/show_bug.cgi?id=10353. Most Linux distros have lower default file descriptor limits than FreeBSD making this workaround less painful. The correct solution would be to teach python3 about closefrom(2). On 11.04.19 16:39, Konstantin Schukraft wrote: >> 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@freebsd.org mailing list >> https://lists.freebsd.org/mailman/listinfo/freebsd-ports >> To unsubscribe, send any mail to "freebsd-ports-unsubscribe@freebsd.org"
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?9729db47-12c4-caf4-cdcf-1913dab73c8e>