Proposal for pkg-message for python 3.x ports

[pmhausen]

Dear python port maintainers,

I discovered an odd performance problem with python 3.6 on servers with
large amounts of memory.

You can find all the details in a thread of the help at python.org
mailinglist with subject

"Python bug? Closing *all* file descriptors on fork() instead of only open ones?"

Unfortunately I cannot get at the list archives. Otherwise I would have sent
you a direct link.

Short version: since python 3.3 (if my google-fu worked) python tries to
close all open file descriptors in the child after fork(). Since there is
no standard POSIX compliant way to do this for *open* descriptors only,
it tries to use /dev/fd on FreeBSD and if that is not available it closes
*all* descriptors (resulting in ERR#9 for the majority). On a 64 bit FreeBSD
11 system with 128 GB of RAM the auto-tuned kern.maxfilesperproc
is between 3 and 4 million. That's a heck of a lot of system calls for each
fork() ;-)

I suggest adding a hint to mount fdescfs and add it to /etc/fstab in the
pkg-message for the affected python ports.

I'll attach my first message to the list below. The solution is to mount /dev/fd.

Kind regards,
Patrick
-----------------------
Hi, all,

last week we encountered an odd behaviour of a particular python application
on a freshly deployed server. The application in question is: https://github.com/iocage/iocage

On our test system (SMALLBOX) everything seemed to be working fine while on
the new designated production system (BIGBOX) every invocation of iocage was
incredibly slow …

This was suprising since BIGBOX features 20 cores, 128 GB of RAM, SSD only
while SMALLBOX is a run-off-the-mill server with 4 cores, 16 GB of RAM and
spinning drives we used for development.

I finally found that the problem may not lie with iocage. To reproduce with just python installed:

SMALLBOX:
$ uname -a
FreeBSD testhost.proserver.punkt.de 11.0-RELEASE-p10 FreeBSD 11.0-RELEASE-p10 #2 r317823: Fri May  5 11:41:45 CEST 2017     root at testhost.proserver.punkt.de:/usr/obj/usr/src/sys/VIMAGE  amd64
$ python3.6 -V
Python 3.6.1
$ time pip3 list
[…]
real	0m0.982s
user	0m0.614s
sys	0m0.370s

BIGBOX:
$ uname -a
FreeBSD ph002.proserver.punkt.de 11.0-RELEASE-p10 FreeBSD 11.0-RELEASE-p10 #2 r317823: Fri May  5 10:55:27 CEST 2017     root at ph002.proserver.punkt.de:/usr/obj/usr/src/sys/VIMAGE  amd64
$ python3.6 -V
Python 3.6.1
$ time pip3 list
real	0m4.140s
user	0m1.242s
sys	0m2.900s

Well … something’s fishy. After double checking OS and python versions, SSD configuration, CPU
and I/O load, being a sysadmin and not really a developer I decided to use truss to have a look at
what the systems were actually *doing*.

Result: on every fork of a python process we get:
77906: close(4)                                  ERR#9 'Bad file descriptor'
77906: close(5)                                  ERR#9 'Bad file descriptor'
77906: close(6)                                  ERR#9 'Bad file descriptor'
77906: close(7)                                  ERR#9 'Bad file descriptor'
77906: close(9)                                  ERR#9 'Bad file descriptor'
77906: close(10)                                 ERR#9 'Bad file descriptor'
77906: close(11)                                 ERR#9 'Bad file descriptor‘
[… continued for literally millions of calls ...]

I’m perfectly familiar with the concept of closing *open* file descriptors on fork/exec but closing
*all* of them regardless of whether they are in use or not means that on the two systems we
get this number of system calls:

SMALLBOX:
$ truss -f pip3 list 2>&1 | grep 'ERR#9' | wc -l
1877703

BIGBOX:
$ truss -f pip3 list 2>&1 | grep 'ERR#9' | wc -l
15082323

Which rather nicely corresponds to the number of file descriptors per process on each system
multiplied by 4, since the initial python process seems to fork 4 times to get the pip3 job done:

SMALLBOX:
$ sysctl kern.maxfilesperproc
kern.maxfilesperproc: 469431
$ dc
469431 4 * p
1877724

BIGBOX:
$ sysctl kern.maxfilesperproc
kern.maxfilesperproc: 3770586
$ dc
3770586 4 * p
15082344

OK - obviously even on a system like BIGBOX 15 million invocations of close() take a couple
of seconds. And this will get worse with 256 or 512 GB of RAM since kernel tables will
dynamically increase accordingly.

What now? Is this a bug? It should be sufficient to close descriptors 0 to 3 after fork. Which
is precisely what the invoking shell does before exec()ing python3.6 …

Thanks in advance for any hints
Patrick