Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Asynchronous remove_writer and remove_reader. #61

Closed
mayfield opened this issue Nov 20, 2016 · 12 comments
Closed

Asynchronous remove_writer and remove_reader. #61

mayfield opened this issue Nov 20, 2016 · 12 comments

Comments

@mayfield
Copy link

  • e7bedb8:
  • Python 3.5.2:
  • Linux 4.8.6:

I notice that remove_reader and remove_writer are asynchronous with respect to when the file descriptor is actually removed from its epoll set (linux terminology). This is a byproduct of how libuv works.

This is different from the asyncio module and causes troubles with at least dup() based FDs. Namely serving static files with aiohttp under uvloop will induce a 100% CPU loop inside libuv because it can't remove the FD. Strace attached..

18:25:45.050832 open("/home/mayfield/project/aiocluster/aiocluster/diag/ui/node_modules/semantic-ui-css/semantic.css", O_RDONLY|O_CLOEXEC) = 24 <0.000031>
18:25:45.050911 ioctl(24, FIOCLEX)      = 0 <0.000018>
18:25:45.050970 fstat(24, {st_mode=S_IFREG|0775, st_size=752358, ...}) = 0 <0.000019>
18:25:45.051036 ioctl(24, TCGETS, 0x7ffd90f38cb0) = -1 ENOTTY (Inappropriate ioctl for device) <0.000019>
18:25:45.051104 lseek(24, 0, SEEK_CUR)  = 0 <0.000020>
18:25:45.051853 fcntl(23, F_DUPFD_CLOEXEC, 0) = 25 <0.000024>
18:25:45.051972 ioctl(25, FIONBIO, [0]) = 0 <0.000018>
18:25:45.052067 write(1, "\nCREATED", 8) = 8 <0.000039>
18:25:45.052225 getsockname(25, {sa_family=AF_INET, sin_port=htons(7878), sin_addr=inet_addr("192.168.17.147")}, [16]) = 0 <0.000023>
18:25:45.052336 getpeername(25, {sa_family=AF_INET, sin_port=htons(50857), sin_addr=inet_addr("192.168.17.179")}, [16]) = 0 <0.000022>
18:25:45.052443 write(1, " 25 <socket.socket fd=25, family"..., 159) = 159 <0.000026>
18:25:45.052521 ioctl(25, FIONBIO, [1]) = 0 <0.000017>
18:25:45.052603 sendto(25, "HTTP/1.1 200 OK\r\nContent-Type: t"..., 184, 0, NULL, 0) = 184 <0.000068>
18:25:45.052777 sendfile(25, 24, [0] => [143352], 752358) = 143352 <0.000083>
18:25:45.052970 getsockname(25, {sa_family=AF_INET, sin_port=htons(7878), sin_addr=inet_addr("192.168.17.147")}, [16]) = 0 <0.000019>
18:25:45.053048 getpeername(25, {sa_family=AF_INET, sin_port=htons(50857), sin_addr=inet_addr("192.168.17.179")}, [16]) = 0 <0.000017>
18:25:45.053131 write(1, "ADD 25 <socket.socket fd=25, fam"..., 144) = 144 <0.000024>
18:25:45.053228 epoll_ctl(6, EPOLL_CTL_ADD, 25, {EPOLLIN, {u32=4294967295, u64=18446744073709551615}}) = 0 <0.000021>
18:25:45.053289 epoll_ctl(6, EPOLL_CTL_DEL, 25, 0x7ffd90f38db0) = 0 <0.000048>
18:25:45.053384 ioctl(25, FIONBIO, [1]) = 0 <0.000021>
18:25:45.053499 epoll_ctl(6, EPOLL_CTL_ADD, 25, {EPOLLOUT, {u32=25, u64=25}}) = 0 <0.000022>
18:25:45.053584 epoll_wait(6, [], 1024, 0) = 0 <0.000019>
18:25:45.053651 epoll_wait(6, [{EPOLLOUT, {u32=25, u64=25}}], 1024, 43) = 1 <0.015515>
18:25:45.069554 getsockname(25, {sa_family=AF_INET, sin_port=htons(7878), sin_addr=inet_addr("192.168.17.147")}, [16]) = 0 <0.000181>
18:25:45.070023 getpeername(25, {sa_family=AF_INET, sin_port=htons(50857), sin_addr=inet_addr("192.168.17.179")}, [16]) = 0 <0.000158>
18:25:45.070464 write(1, "REMOVE! 25 <socket.socket fd=25,"..., 148) = 148 <0.000069>
18:25:45.070709 sendfile(25, 24, [143352] => [273672], 609006) = 130320 <0.000131>
18:25:45.071063 getsockname(25, {sa_family=AF_INET, sin_port=htons(7878), sin_addr=inet_addr("192.168.17.147")}, [16]) = 0 <0.000026>
18:25:45.071258 getpeername(25, {sa_family=AF_INET, sin_port=htons(50857), sin_addr=inet_addr("192.168.17.179")}, [16]) = 0 <0.000113>
18:25:45.071623 write(1, "ADD 25 <socket.socket fd=25, fam"..., 144) = 144 <0.000179>
18:25:45.071947 epoll_ctl(6, EPOLL_CTL_ADD, 25, {EPOLLIN, {u32=4294967295, u64=18446744073709551615}}) = -1 EEXIST (File exists) <0.000065>
18:25:45.072065 epoll_ctl(6, EPOLL_CTL_DEL, 25, 0x7ffd90f368d0) = 0 <0.000031>
18:25:45.072139 ioctl(25, FIONBIO, [1]) = 0 <0.000018>
18:25:45.072225 epoll_ctl(6, EPOLL_CTL_ADD, 25, {EPOLLOUT, {u32=25, u64=25}}) = 0 <0.000022>
18:25:45.072302 epoll_wait(6, [], 1024, 24) = 0 <0.024234>
18:25:45.097030 epoll_wait(6, [], 1024, 0) = 0 <0.000166>
18:25:45.097609 epoll_ctl(6, EPOLL_CTL_ADD, 15, {EPOLLIN, {u32=4294967295, u64=18446744073709551615}}) = -1 EEXIST (File exists) <0.000145>
18:25:45.098014 epoll_ctl(6, EPOLL_CTL_DEL, 15, 0x7ffd90f39590) = 0 <0.000049>
18:25:45.098193 ioctl(15, FIONBIO, [1]) = 0 <0.000030>
18:25:45.098361 epoll_ctl(6, EPOLL_CTL_ADD, 15, {EPOLLIN, {u32=15, u64=15}}) = 0 <0.000085>
18:25:45.098540 epoll_wait(6, [], 1024, 0) = 0 <0.000018>
18:25:45.098630 epoll_wait(6, [{EPOLLOUT, {u32=25, u64=25}}], 1024, 99) = 1 <0.004728>
18:25:45.103551 getsockname(25, {sa_family=AF_INET, sin_port=htons(7878), sin_addr=inet_addr("192.168.17.147")}, [16]) = 0 <0.000026>
18:25:45.103711 getpeername(25, {sa_family=AF_INET, sin_port=htons(50857), sin_addr=inet_addr("192.168.17.179")}, [16]) = 0 <0.000022>
18:25:45.103850 write(1, "REMOVE! 25 <socket.socket fd=25,"..., 148) = 148 <0.000039>
18:25:45.103979 sendfile(25, 24, [273672] => [403992], 478686) = 130320 <0.000060>
18:25:45.104165 getsockname(25, {sa_family=AF_INET, sin_port=htons(7878), sin_addr=inet_addr("192.168.17.147")}, [16]) = 0 <0.000018>
18:25:45.104260 getpeername(25, {sa_family=AF_INET, sin_port=htons(50857), sin_addr=inet_addr("192.168.17.179")}, [16]) = 0 <0.000019>
18:25:45.104367 write(1, "ADD 25 <socket.socket fd=25, fam"..., 144) = 144 <0.000026>
18:25:45.104473 epoll_ctl(6, EPOLL_CTL_ADD, 25, {EPOLLIN, {u32=4294967295, u64=18446744073709551615}}) = -1 EEXIST (File exists) <0.000017>
18:25:45.104541 epoll_ctl(6, EPOLL_CTL_DEL, 25, 0x7ffd90f368d0) = 0 <0.000023>
18:25:45.104601 ioctl(25, FIONBIO, [1]) = 0 <0.000016>
18:25:45.104678 epoll_ctl(6, EPOLL_CTL_ADD, 25, {EPOLLOUT, {u32=25, u64=25}}) = 0 <0.000022>
18:25:45.104769 epoll_wait(6, [{EPOLLOUT, {u32=25, u64=25}}], 1024, 93) = 1 <0.057713>
18:25:45.162769 getsockname(25, {sa_family=AF_INET, sin_port=htons(7878), sin_addr=inet_addr("192.168.17.147")}, [16]) = 0 <0.000030>
18:25:45.162926 getpeername(25, {sa_family=AF_INET, sin_port=htons(50857), sin_addr=inet_addr("192.168.17.179")}, [16]) = 0 <0.000026>
18:25:45.163065 write(1, "REMOVE! 25 <socket.socket fd=25,"..., 148) = 148 <0.000036>
18:25:45.163203 sendfile(25, 24, [403992] => [534312], 348366) = 130320 <0.000060>
18:25:45.163391 getsockname(25, {sa_family=AF_INET, sin_port=htons(7878), sin_addr=inet_addr("192.168.17.147")}, [16]) = 0 <0.000017>
18:25:45.163484 getpeername(25, {sa_family=AF_INET, sin_port=htons(50857), sin_addr=inet_addr("192.168.17.179")}, [16]) = 0 <0.000017>
18:25:45.163583 write(1, "ADD 25 <socket.socket fd=25, fam"..., 144) = 144 <0.000025>
18:25:45.163711 epoll_ctl(6, EPOLL_CTL_ADD, 25, {EPOLLIN, {u32=4294967295, u64=18446744073709551615}}) = -1 EEXIST (File exists) <0.000021>
18:25:45.163792 epoll_ctl(6, EPOLL_CTL_DEL, 25, 0x7ffd90f368d0) = 0 <0.000019>
18:25:45.163850 ioctl(25, FIONBIO, [1]) = 0 <0.000016>
18:25:45.163927 epoll_ctl(6, EPOLL_CTL_ADD, 25, {EPOLLOUT, {u32=25, u64=25}}) = 0 <0.000020>
18:25:45.163989 epoll_wait(6, [{EPOLLOUT, {u32=25, u64=25}}], 1024, 33) = 1 <0.017369>
18:25:45.181732 getsockname(25, {sa_family=AF_INET, sin_port=htons(7878), sin_addr=inet_addr("192.168.17.147")}, [16]) = 0 <0.000050>
18:25:45.181960 getpeername(25, {sa_family=AF_INET, sin_port=htons(50857), sin_addr=inet_addr("192.168.17.179")}, [16]) = 0 <0.000026>
18:25:45.182252 write(1, "REMOVE! 25 <socket.socket fd=25,"..., 148) = 148 <0.000049>
18:25:45.182423 sendfile(25, 24, [534312] => [664632], 218046) = 130320 <0.000133>
18:25:45.182797 getsockname(25, {sa_family=AF_INET, sin_port=htons(7878), sin_addr=inet_addr("192.168.17.147")}, [16]) = 0 <0.000027>
18:25:45.183088 getpeername(25, {sa_family=AF_INET, sin_port=htons(50857), sin_addr=inet_addr("192.168.17.179")}, [16]) = 0 <0.000164>
18:25:45.183530 write(1, "ADD 25 <socket.socket fd=25, fam"..., 144) = 144 <0.000143>
18:25:45.183813 epoll_ctl(6, EPOLL_CTL_ADD, 25, {EPOLLIN, {u32=4294967295, u64=18446744073709551615}}) = -1 EEXIST (File exists) <0.000022>
18:25:45.183929 epoll_ctl(6, EPOLL_CTL_DEL, 25, 0x7ffd90f368d0) = 0 <0.000167>
18:25:45.184256 ioctl(25, FIONBIO, [1]) = 0 <0.000048>
18:25:45.184526 epoll_ctl(6, EPOLL_CTL_ADD, 25, {EPOLLOUT, {u32=25, u64=25}}) = 0 <0.000142>
18:25:45.184805 epoll_wait(6, [{EPOLLOUT, {u32=25, u64=25}}], 1024, 13) = 1 <0.012150>
18:25:45.197446 getsockname(25, {sa_family=AF_INET, sin_port=htons(7878), sin_addr=inet_addr("192.168.17.147")}, [16]) = 0 <0.000051>
18:25:45.197749 getpeername(25, {sa_family=AF_INET, sin_port=htons(50857), sin_addr=inet_addr("192.168.17.179")}, [16]) = 0 <0.000114>
18:25:45.198159 write(1, "REMOVE! 25 <socket.socket fd=25,"..., 148) = 148 <0.000166>
18:25:45.198559 sendfile(25, 24, [664632] => [752358], 87726) = 87726 <0.000114>
18:25:45.198925 getsockname(25, {sa_family=AF_INET, sin_port=htons(7878), sin_addr=inet_addr("192.168.17.147")}, [16]) = 0 <0.000020>
18:25:45.199062 getpeername(25, {sa_family=AF_INET, sin_port=htons(50857), sin_addr=inet_addr("192.168.17.179")}, [16]) = 0 <0.000026>
18:25:45.199239 write(1, "CLOSE 25 <socket.socket fd=25, f"..., 146) = 146 <0.000049>
18:25:45.199385 write(1, "\n", 1)       = 1 <0.000025>
18:25:45.199494 close(25)               = 0 <0.000021>
18:25:45.199595 close(24)               = 0 <0.000024>
18:25:45.200256 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2403, ...}) = 0 <0.000032>
18:25:45.200889 write(2, "[\33[34m2016-11-19 18:25:45,200\33[0"..., 333) = 333 <0.000031>
18:25:45.201266 epoll_wait(6, [], 1024, 0) = 0 <0.000036>
18:25:45.201492 epoll_ctl(6, EPOLL_CTL_ADD, 15, {EPOLLIN, {u32=4294967295, u64=18446744073709551615}}) = -1 EEXIST (File exists) <0.000025>
18:25:45.201601 epoll_ctl(6, EPOLL_CTL_DEL, 15, 0x7ffd90f39590) = 0 <0.000036>
18:25:45.201713 ioctl(15, FIONBIO, [1]) = 0 <0.000026>
18:25:45.201844 epoll_ctl(6, EPOLL_CTL_ADD, 15, {EPOLLIN, {u32=15, u64=15}}) = 0 <0.000026>
18:25:45.201949 epoll_wait(6, [], 1024, 0) = 0 <0.000018>
18:25:45.202011 epoll_wait(6, [{EPOLLOUT, {u32=25, u64=25}}], 1024, 81) = 1 <0.008192>
18:25:45.210303 epoll_ctl(6, EPOLL_CTL_DEL, 25, 0x7ffd90f37060) = -1 EBADF (Bad file descriptor) <0.000101>
18:25:45.210532 epoll_wait(6, [{EPOLLOUT, {u32=25, u64=25}}], 1024, 72) = 1 <0.000178>
18:25:45.210950 epoll_ctl(6, EPOLL_CTL_DEL, 25, 0x7ffd90f37060) = -1 EBADF (Bad file descriptor) <0.000159>
18:25:45.211247 epoll_wait(6, [{EPOLLOUT, {u32=25, u64=25}}], 1024, 63) = 1 <0.000064>
18:25:45.211420 epoll_ctl(6, EPOLL_CTL_DEL, 25, 0x7ffd90f37060) = -1 EBADF (Bad file descriptor) <0.000045>
18:25:45.211531 epoll_wait(6, [{EPOLLOUT, {u32=25, u64=25}}], 1024, 54) = 1 <0.000048>
18:25:45.211620 epoll_ctl(6, EPOLL_CTL_DEL, 25, 0x7ffd90f37060) = -1 EBADF (Bad file descriptor) <0.000018>
18:25:45.211675 epoll_wait(6, [{EPOLLOUT, {u32=25, u64=25}}], 1024, 45) = 1 <0.000022>

I could go into more detail about this but it's rather complex and I believe there are a number of issues you could tie back to the fact that remove_* isn't syncronous as it is with the stdlib implementation of EventLoop.

@1st1
Copy link
Member

1st1 commented Nov 20, 2016

I'm not sure I understand why this 100% CPU loop happens. From the libuv docs:

The user should not close a file descriptor while it is being polled by an active poll handle. This can cause the handle to report an error, but it might also start polling another socket. However the fd can be safely closed immediately after a call to uv_poll_stop() or uv_close().

It seems that if you call remove_reader and remove_writer before closing the FD epoll errors that your strace dump shows should not happen...

I could go into more detail about this but it's rather complex and I believe there are a number of issues you could tie back to the fact that remove_* isn't syncronous as it is with the stdlib implementation of EventLoop.

I'd really appreciate if you could share your view on this.

@1st1
Copy link
Member

1st1 commented Nov 20, 2016

Also, we can probably use uv_backend_fd() to do some manual operations with epoll/kqueue.

@mayfield
Copy link
Author

Hi Yury,

I believe the CPU is being burned in the libuv poll here,

https://github.com/libuv/libuv/blob/v1.x/src/unix/linux-core.c#L327-L348

That in itself may be a libuv bug but I have less experience with their community to say for certain.

From what I've gathered epoll is susceptible to confusion when you feed it a dup() FD, then close the dup() based FD but leave the original file description open. As far as epoll is concerned the file description (not descriptor) pointed to by the dup() based FD is still open, so it may trigger events for an FD that is no longer valid; Attempts to use EPOLL_CTL_DEL on that FD will fail as you can see in the strace output.

Some context from epoll(7)..

Q6 Will closing a file descriptor cause it to be removed from all epoll sets automatically?

A6 Yes, but be aware of the following point. A file descriptor is a reference to an open file description (see open(2)). Whenever a file descriptor is duplicated via dup(2),
dup2(2), fcntl(2) F_DUPFD, or fork(2), a new file descriptor referring to the same open file description is created. An open file description continues to exist until all
file descriptors referring to it have been closed. A file descriptor is removed from an epoll set only after all the file descriptors referring to the underlying open file
description have been closed (or before if the file descriptor is explicitly removed using epoll_ctl(2) EPOLL_CTL_DEL). This means that even after a file descriptor that is
part of an epoll set has been closed, events may be reported for that file descriptor if other file descriptors referring to the same underlying file description remain open.

Regarding calling remove_* first: In this case it is being called first, but the underlying epoll_ctl(EPOLL_CTL_DEL) runs later due to the mechanics of libuv. I think it's flagged for removal and handled later in another context but I didn't deep dive into that to be honest.

The python code that produced this result is from aiohttp and the only setup required was to serve a single, but large, file over a link that will cause os.sendfile to raise BlockingIOError.

https://github.com/KeepSafe/aiohttp/blob/master/aiohttp/file_sender.py#L103-L110

As you can see, that code will always call remove_writer before calling socket.close but if you look closely at the strace output you will see that close() runs first.

@mayfield
Copy link
Author

Here is a simplified test that will reproduce the issue.

import os
import uvloop

loop = uvloop.EventLoopPolicy().get_event_loop()
rfd, wfd = os.pipe()
wfd2 = os.dup(wfd)

def on_write_event():
    loop.remove_writer(wfd2)
    os.close(wfd2)

loop.add_writer(wfd2, on_write_event)
loop.run_forever()

@mayfield mayfield changed the title Asyncronous remove_writer and remove_reader. Asynchronous remove_writer and remove_reader. Nov 20, 2016
@1st1
Copy link
Member

1st1 commented Nov 20, 2016

Seems that we can manually call epoll_ctl in remove_reader/remove_writer after the libuv poll handler is closed. Looks like it should be safe.

@saghul Is this something we should fix in libuv somehow?

@1st1
Copy link
Member

1st1 commented Nov 22, 2016

@mayfield Justin, 641c26c should fix the issue. Could you please review that commit and test if it actually fixes the issue (it does look like it fixes it). I can make a new release tomorrow.

@mayfield
Copy link
Author

My test cases are passing now. Thank you very much @1st1!

@1st1
Copy link
Member

1st1 commented Nov 22, 2016

BTW, do you have any idea how to write a unittest for this in uvloop?

@mayfield
Copy link
Author

I've been just using time.process_time() to check CPU usage after letting the loop run for a second. I wouldn't be comfortable putting that into a unittest but here it is for reference..

import asyncio
import os
import time
import uvloop

loop = uvloop.EventLoopPolicy().get_event_loop()
rfd, wfd = os.pipe()
wfd2 = os.dup(wfd)

def on_write_event():
    print("   START REMOVE")
    loop.remove_writer(wfd2)
    print("   DONE REMOVE - START CLOSE")
    os.close(wfd2)
    print("   DONE CLOSE")

loop.add_writer(wfd2, on_write_event)
ct = time.process_time()
loop.run_until_complete(asyncio.sleep(0.100, loop=loop))
loop_cputime = time.process_time() - ct
assert loop_cputime < 0.050, 'libuv is running hot!'

@1st1
Copy link
Member

1st1 commented Nov 24, 2016

I wouldn't be comfortable putting that into a unittest but here it is for reference..

Yeah, process_time isn't going to be reliable. I've added a direct regression test of epoll/fd. Will make a release shortly.

@1st1
Copy link
Member

1st1 commented Dec 1, 2016

Closing this one, should be fixed in v0.6.7.

@1st1 1st1 closed this as completed Dec 1, 2016
@srikawnth
Copy link

Is this fix added in C library of libuv as well?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants