[pypy-issue] Issue #2900: High CPU usage on reading from socket during urllib.request (pypy/pypy)

[Noam Meltzer]

New issue 2900: High CPU usage on reading from socket during urllib.request
https://bitbucket.org/pypy/pypy/issues/2900/high-cpu-usage-on-reading-from-socket

Noam Meltzer:

The following code will result in 100% CPU usage on pypy3 version higher than 5.5.
(with pypy3-5.5 and  CPython it works properly)

```python

import urllib.request
import sys

token = 'PUT_YOUR_TOKEN_HERE'
url = 'https://api.telegram.org/bot{}/getUpdates'.format(token)
req = urllib.request.Request(url,  data=b'{}', headers={'Content-Type': 'application/json'})

while True:
    res = urllib.request.urlopen(req, timeout=100).read()
    print(res, file=sys.stderr)
```

The code is a client for a remote server and performs long-polling.

Running strace shows that the socket is set as non-blocking and then improperly polled/read from.

As you can see in strace output below, after creating the socket, `fcntl F_SETFL` is being called to set it non blocking.

Following that a few other operations are performed and then the real problem begins:

* `read()` is called, returning EAGAIN
* `poll()` with argument `events=POLLIN|POLLOUT` is called, immediately returning as ready to write (but not read!)
* `read()` is called, only to return EAGAIN.
* the `poll()` & `read()` continued to be called in a loop yielding 100% cpu usage.


```strace
11191 socket(AF_INET, SOCK_STREAM|SOCK_CLOEXEC, IPPROTO_TCP) = 3<TCP:[180349]>
11191 fcntl(3<TCP:[180349]>, F_GETFL)   = 0x2 (flags O_RDWR)
11191 fcntl(3<TCP:[180349]>, F_SETFL, O_RDWR|O_NONBLOCK) = 0
11191 connect(3<TCP:[180349]>, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("149.154.167.220")}, 16) = -1 EINPROGRESS (Operation now in progress)
11191 poll([{fd=3<TCP:[10.31.96.137:43498->149.154.167.220:443]>, events=POLLOUT}], 1, 100000) = 1 ([{fd=3, revents=POLLOUT}])
11191 getsockopt(3<TCP:[10.31.96.137:43498->149.154.167.220:443]>, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
11191 setsockopt(3<TCP:[10.31.96.137:43498->149.154.167.220:443]>, SOL_TCP, TCP_NODELAY, [1], 4) = 0
11191 getsockopt(3<TCP:[10.31.96.137:43498->149.154.167.220:443]>, SOL_SOCKET, SO_TYPE, [1], [4]) = 0
11191 fcntl(3<TCP:[10.31.96.137:43498->149.154.167.220:443]>, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
11191 getpeername(3<TCP:[10.31.96.137:43498->149.154.167.220:443]>, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("149.154.167.220")}, [16]) = 0
11191 getpid()                          = 11191
11191 write(3<TCP:[10.31.96.137:43498->149.154.167.220:443]>, "<SNIP>", 517) = 517
11191 read(3<TCP:[10.31.96.137:43498->149.154.167.220:443]>, 0x11bf210, 7) = -1 EAGAIN (Resource temporarily unavailable)
11191 poll([{fd=3<TCP:[10.31.96.137:43498->149.154.167.220:443]>, events=POLLIN|POLLOUT}], 1, 99999) = 1 ([{fd=3, revents=POLLOUT}])
11191 read(3<TCP:[10.31.96.137:43498->149.154.167.220:443]>, 0x11bf210, 7) = -1 EAGAIN (Resource temporarily unavailable)
11191 poll([{fd=3<TCP:[10.31.96.137:43498->149.154.167.220:443]>, events=POLLIN|POLLOUT}], 1, 99998) = 1 ([{fd=3, revents=POLLOUT}])
11191 read(3<TCP:[10.31.96.137:43498->149.154.167.220:443]>, 0x11bf210, 7) = -1 EAGAIN (Resource temporarily unavailable)
11191 poll([{fd=3<TCP:[10.31.96.137:43498->149.154.167.220:443]>, events=POLLIN|POLLOUT}], 1, 99998) = 1 ([{fd=3, revents=POLLOUT}])
11191 read(3<TCP:[10.31.96.137:43498->149.154.167.220:443]>, 0x11bf210, 7) = -1 EAGAIN (Resource temporarily unavailable)
11191 poll([{fd=3<TCP:[10.31.96.137:43498->149.154.167.220:443]>, events=POLLIN|POLLOUT}], 1, 99997) = 1 ([{fd=3, revents=POLLOUT}])
11191 read(3<TCP:[10.31.96.137:43498->149.154.167.220:443]>, 0x11bf210, 7) = -1 EAGAIN (Resource temporarily unavailable)

...
many many more poll() & read()
...

11191 poll([{fd=3<TCP:[10.31.96.137:43498->149.154.167.220:443]>, events=POLLIN|POLLOUT}], 1, 99902) = 1 ([{fd=3, revents=POLLIN|POLLOUT}])
11191 mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f1e0c7bd000
11191 brk(NULL)                         = 0x11ea000
11191 brk(0x121b000)                    = 0x121b000
11191 read(3<TCP:[10.31.96.137:43498->149.154.167.220:443]>, "\26\3\3\0B\2\0", 7) = 7

...
>From here on behaviour seems normal
...
```

Intuitively I would say that the socket should not be set non-blocking on the first place (the whole request is synchronous), but if this is the normal behaviour then `poll()` should be handled more delicately (Only `POLLIN` should be set for `events).


NOTES:

1. I  was having difficulty simulating this behaviour with a local server, so it might also be related to network delays.
2. This report follows the original bug as reported here: https://github.com/python-telegram-bot/python-telegram-bot/issues/1194
3. If you'd like to recreate the bug against Telegram servers and don't want to bother on creating, I can supply a temporary token, so feel free to contact me for that.