Coder Social home page Coder Social logo

Too many calls to futex about swift-nio HOT 15 CLOSED

apple avatar apple commented on May 20, 2024 2
Too many calls to futex

from swift-nio.

Comments (15)

toffaletti avatar toffaletti commented on May 20, 2024 1

I introduced pthreads just to be sure:

root@1ba3a0b6d2c0:/code# cat epoll.c 
#include <sys/epoll.h>
#include <pthread.h>

static void *start(void *arg) {
    for (int i=0; i<10; i++) {
        int fd = epoll_create(1);
        epoll_wait(fd, 0, 0, 0);
    }
    return 0;
}

int main() {
    pthread_t thread;
    pthread_create(&thread, 0, start, 0);
    pthread_join(thread, 0);
    return 0;
}
root@1ba3a0b6d2c0:/code# clang -pthread epoll.c 
root@1ba3a0b6d2c0:/code# strace -s 1024 -f -tT ./a.out
22:03:51 execve("./a.out", ["./a.out"], [/* 11 vars */]) = 0 <0.002773>
22:03:51 brk(NULL)                      = 0xb81000 <0.000168>
22:03:51 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) <0.000044>
22:03:51 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) <0.000124>
22:03:51 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 <0.000055>
22:03:51 fstat(3, {st_mode=S_IFREG|0644, st_size=18870, ...}) = 0 <0.000230>
22:03:51 mmap(NULL, 18870, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fce60f39000 <0.000470>
22:03:51 close(3)                       = 0 <0.000312>
22:03:51 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) <0.000311>
22:03:51 open("/lib/x86_64-linux-gnu/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3 <0.000384>
22:03:51 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260`\0\0\0\0\0\0@\0\0\0\0\0\0\0\210\23\2\0\0\0\0\0\0\0\0\0@\0008\0\t\0@\0)\0&\0\6\0\0\0\5\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0\370\1\0\0\0\0\0\0\370\1\0\0\0\0\0\0\10\0\0\0\0\0\0\0\3\0\0\0\4\0\0\0\2206\1\0\0\0\0\0\2206\1\0\0\0\0\0\2206\1\0\0\0\0\0\34\0\0\0\0\0\0\0\34\0\0\0\0\0\0\0\20\0\0\0\0\0\0\0\1\0\0\0\5\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\204y\1\0\0\0\0\0\204y\1\0\0\0\0\0\0\0 \0\0\0\0\0\1\0\0\0\6\0\0\0x{\1\0\0\0\0\0x{!\0\0\0\0\0x{!\0\0\0\0\0(\7\0\0\0\0\0\0\260H\0\0\0\0\0\0\0\0 \0\0\0\0\0\2\0\0\0\6\0\0\0P}\1\0\0\0\0\0P}!\0\0\0\0\0P}!\0\0\0\0\0000\2\0\0\0\0\0\0000\2\0\0\0\0\0\0\10\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0008\2\0\0\0\0\0\0008\2\0\0\0\0\0\0008\2\0\0\0\0\0\0D\0\0\0\0\0\0\0D\0\0\0\0\0\0\0\4\0\0\0\0\0\0\0P\345td\4\0\0\0\2606\1\0\0\0\0\0\2606\1\0\0\0\0\0\2606\1\0\0\0\0\0\214\10\0\0\0\0\0\0\214\10\0\0\0\0\0\0\4\0\0\0\0\0\0\0Q\345td\6\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\20\0\0\0\0\0\0\0R\345td\4\0\0\0x{\1\0\0\0\0\0x{!\0\0\0\0\0x{!\0\0\0\0\0\210\4\0\0\0\0\0\0\210\4\0\0\0\0\0\0\1\0\0\0\0\0\0\0\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\316\27\340#T\"e\374\21\331\274\217SK\264\360pI=0\4\0\0\0\20\0\0\0\1\0\0\0GNU\0\0\0\0\0\2\0\0\0\6\0\0\0 \0\0\0\0\0\0\0\345\1\0\0W\0\0\0 \0\0\0\v\0\0\0\31#\2\261\1\10\20\2@@a\370\3\10\10\25\200 \0\0\0\0\200\300\321Q\0\0\0\22\353\3020D\0\10\20A\0\2\0\2\f\1\200\v\221\1\330\240\r\240@\230 \244\200\21\n\202-l@g\214V\24\0\224 \200$H\200P(\1\22\f\311B\240\220\22\10\f \2ZdA\245c\4@\n\n\n\0\2009\1(\314D\204\201\300\22\10(\fD\0\0\0\200Q\10\200\35\4B\320\2608A\0\1\0\0\265\0300\0\200`\2\20\"\0\tA\20\1\5\0P(\251\22G(\0\0\202\4\230@\4\0\20\340T\0\2@\2\2\20\3010f\26\200\0", 832) = 832 <0.000511>
22:03:51 fstat(3, {st_mode=S_IFREG|0755, st_size=138696, ...}) = 0 <0.000057>
22:03:51 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fce60f38000 <0.000038>
22:03:51 mmap(NULL, 2212904, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fce60afc000 <0.000175>
22:03:51 mprotect(0x7fce60b14000, 2093056, PROT_NONE) = 0 <0.000482>
22:03:51 mmap(0x7fce60d13000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x17000) = 0x7fce60d13000 <0.000815>
22:03:51 mmap(0x7fce60d15000, 13352, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fce60d15000 <0.000049>
22:03:51 close(3)                       = 0 <0.000236>
22:03:51 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) <0.000034>
22:03:51 open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 <0.000046>
22:03:51 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\t\2\0\0\0\0\0@\0\0\0\0\0\0\0\270r\34\0\0\0\0\0\0\0\0\0@\0008\0\n\0@\0H\0G\0\6\0\0\0\5\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0000\2\0\0\0\0\0\0000\2\0\0\0\0\0\0\10\0\0\0\0\0\0\0\3\0\0\0\4\0\0\0`f\31\0\0\0\0\0`f\31\0\0\0\0\0`f\31\0\0\0\0\0\34\0\0\0\0\0\0\0\34\0\0\0\0\0\0\0\20\0\0\0\0\0\0\0\1\0\0\0\5\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\20\373\33\0\0\0\0\0\20\373\33\0\0\0\0\0\0\0 \0\0\0\0\0\1\0\0\0\6\0\0\0\300\7\34\0\0\0\0\0\300\7<\0\0\0\0\0\300\7<\0\0\0\0\0`O\0\0\0\0\0\0\340\221\0\0\0\0\0\0\0\0 \0\0\0\0\0\2\0\0\0\6\0\0\0\240;\34\0\0\0\0\0\240;<\0\0\0\0\0\240;<\0\0\0\0\0\340\1\0\0\0\0\0\0\340\1\0\0\0\0\0\0\10\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0p\2\0\0\0\0\0\0p\2\0\0\0\0\0\0p\2\0\0\0\0\0\0D\0\0\0\0\0\0\0D\0\0\0\0\0\0\0\4\0\0\0\0\0\0\0\7\0\0\0\4\0\0\0\300\7\34\0\0\0\0\0\300\7<\0\0\0\0\0\300\7<\0\0\0\0\0\20\0\0\0\0\0\0\0x\0\0\0\0\0\0\0\10\0\0\0\0\0\0\0P\345td\4\0\0\0|f\31\0\0\0\0\0|f\31\0\0\0\0\0|f\31\0\0\0\0\0\274T\0\0\0\0\0\0\274T\0\0\0\0\0\0\4\0\0\0\0\0\0\0Q\345td\6\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\20\0\0\0\0\0\0\0R\345td\4\0\0\0\300\7\34\0\0\0\0\0\300\7<\0\0\0\0\0\300\7<\0\0\0\0\0@8\0\0\0\0\0\0@8\0\0\0\0\0\0\1\0\0\0\0\0\0\0\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\2658\32Ey\6\322y\0078\"\245\316\262LK\376\371M\333\4\0\0\0\20\0\0\0\1\0\0\0GNU\0\0\0\0\0\2\0\0\0\6\0\0\0 \0\0\0\0\0\0\0\363\3\0\0\n\0\0\0\0\1\0\0\16\0\0\0\0000\20D\240 \2\1\210\3\346\220\305E\214\0\304\0\10\0\5\204\0`\300\200\0\r\212\f\0\4\20\0\210@2\10*@\210T<, \0162H&\204\300\214\4\10\0\2\2\16\241\254\32\4f\300\0\3002\0\300\0P\1 \201\10\204\v  ($\0\4 Z\0\20X\200\312DB(\0\6\200\20\30B\0 @\200\0IP\0Q\212@\22\0\0\0\0\10\0\0\21\20", 832) = 832 <0.000021>
22:03:51 fstat(3, {st_mode=S_IFREG|0755, st_size=1868984, ...}) = 0 <0.000020>
22:03:51 mmap(NULL, 3971488, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fce60732000 <0.000143>
22:03:51 mprotect(0x7fce608f2000, 2097152, PROT_NONE) = 0 <0.000027>
22:03:51 mmap(0x7fce60af2000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1c0000) = 0x7fce60af2000 <0.000054>
22:03:51 mmap(0x7fce60af8000, 14752, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fce60af8000 <0.000022>
22:03:51 close(3)                       = 0 <0.000026>
22:03:51 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fce60f37000 <0.000024>
22:03:51 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fce60f36000 <0.000022>
22:03:51 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fce60f35000 <0.000101>
22:03:51 arch_prctl(ARCH_SET_FS, 0x7fce60f36700) = 0 <0.000019>
22:03:51 mprotect(0x7fce60af2000, 16384, PROT_READ) = 0 <0.000046>
22:03:51 mprotect(0x7fce60d13000, 4096, PROT_READ) = 0 <0.000022>
22:03:51 mprotect(0x600000, 4096, PROT_READ) = 0 <0.000033>
22:03:51 mprotect(0x7fce60f3e000, 4096, PROT_READ) = 0 <0.000190>
22:03:51 munmap(0x7fce60f39000, 18870)  = 0 <0.000103>
22:03:51 set_tid_address(0x7fce60f369d0) = 1750 <0.000011>
22:03:51 set_robust_list(0x7fce60f369e0, 24) = 0 <0.000014>
22:03:51 rt_sigaction(SIGRTMIN, {0x7fce60b01b50, [], SA_RESTORER|SA_SIGINFO, 0x7fce60b0d390}, NULL, 8) = 0 <0.000012>
22:03:51 rt_sigaction(SIGRT_1, {0x7fce60b01be0, [], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x7fce60b0d390}, NULL, 8) = 0 <0.000010>
22:03:51 rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0 <0.000083>
22:03:51 getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0 <0.000023>
22:03:51 mmap(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7fce5ff31000 <0.000014>
22:03:51 brk(NULL)                      = 0xb81000 <0.000011>
22:03:51 brk(0xba2000)                  = 0xba2000 <0.000024>
22:03:51 mprotect(0x7fce5ff31000, 4096, PROT_NONE) = 0 <0.000091>
22:03:51 clone(child_stack=0x7fce60730ff0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fce607319d0, tls=0x7fce60731700, child_tidptr=0x7fce607319d0) = 1751 <0.000202>
22:03:51 futex(0x7fce607319d0, FUTEX_WAIT, 1751, NULLstrace: Process 1751 attached
 <unfinished ...>
[pid  1751] 22:03:51 set_robust_list(0x7fce607319e0, 24) = 0 <0.000111>
[pid  1751] 22:03:51 epoll_create(1)    = 3 <0.000179>
[pid  1751] 22:03:51 epoll_wait(3, NULL, 0, 0) = -1 EINVAL (Invalid argument) <0.000162>
[pid  1751] 22:03:51 epoll_create(1)    = 4 <0.000238>
[pid  1751] 22:03:51 epoll_wait(4, NULL, 0, 0) = -1 EINVAL (Invalid argument) <0.000166>
[pid  1751] 22:03:51 epoll_create(1)    = 5 <0.000231>
[pid  1751] 22:03:51 epoll_wait(5, NULL, 0, 0) = -1 EINVAL (Invalid argument) <0.000163>
[pid  1751] 22:03:51 epoll_create(1)    = 6 <0.000625>
[pid  1751] 22:03:51 epoll_wait(6, NULL, 0, 0) = -1 EINVAL (Invalid argument) <0.000202>
[pid  1751] 22:03:51 epoll_create(1)    = 7 <0.000158>
[pid  1751] 22:03:51 epoll_wait(7, NULL, 0, 0) = -1 EINVAL (Invalid argument) <0.000375>
[pid  1751] 22:03:51 epoll_create(1)    = 8 <0.000150>
[pid  1751] 22:03:51 epoll_wait(8, NULL, 0, 0) = -1 EINVAL (Invalid argument) <0.000187>
[pid  1751] 22:03:51 epoll_create(1)    = 9 <0.000143>
[pid  1751] 22:03:51 epoll_wait(9, NULL, 0, 0) = -1 EINVAL (Invalid argument) <0.000129>
[pid  1751] 22:03:51 epoll_create(1)    = 10 <0.000210>
[pid  1751] 22:03:51 epoll_wait(10, NULL, 0, 0) = -1 EINVAL (Invalid argument) <0.000217>
[pid  1751] 22:03:51 epoll_create(1)    = 11 <0.000163>
[pid  1751] 22:03:51 epoll_wait(11, NULL, 0, 0) = -1 EINVAL (Invalid argument) <0.000197>
[pid  1751] 22:03:51 epoll_create(1)    = 12 <0.000102>
[pid  1751] 22:03:51 epoll_wait(12, NULL, 0, 0) = -1 EINVAL (Invalid argument) <0.000169>
[pid  1751] 22:03:51 madvise(0x7fce5ff31000, 8368128, MADV_DONTNEED) = 0 <0.000105>
[pid  1751] 22:03:51 exit(0)            = ?
[pid  1750] 22:03:51 <... futex resumed> ) = 0 <0.015823>
[pid  1750] 22:03:51 exit_group(0)      = ?
[pid  1751] 22:03:51 +++ exited with 0 +++
22:03:51 +++ exited with 0 +++

The futex here is the pthread_join.

from swift-nio.

toffaletti avatar toffaletti commented on May 20, 2024

I have a minimal reproducer in a branch https://github.com/toffaletti/swift-nio/blob/wtfutex/Sources/WTFutex/main.swift

from swift-nio.

toffaletti avatar toffaletti commented on May 20, 2024

Got it:

root@1ba3a0b6d2c0:/code# gdb ./.build/x86_64-unknown-linux/debug/WTFutex
GNU gdb (Ubuntu 7.11.1-0ubuntu1~16.5) 7.11.1
Copyright (C) 2016 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./.build/x86_64-unknown-linux/debug/WTFutex...done.
(gdb) catch syscall 202
...
Catchpoint 1 (returned from syscall futex), 0x00007ffff7414ac0 in futex_wake (private=0, processes_to_wake=2147483647, 
    futex_word=0x5da878 <globalinit_33_355B02204025CF64BE88BEACDD727F65_token2>) at ../sysdeps/unix/sysv/linux/futex-internal.h:231
231	in ../sysdeps/unix/sysv/linux/futex-internal.h
(gdb) bt
#0  0x00007ffff7414ac0 in futex_wake (private=0, processes_to_wake=2147483647, futex_word=0x5da878 <globalinit_33_355B02204025CF64BE88BEACDD727F65_token2>)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:231
#1  __pthread_once_slow (once_control=0x5da878 <globalinit_33_355B02204025CF64BE88BEACDD727F65_token2>, init_routine=0x7ffff6d34ac0 <__once_proxy>) at pthread_once.c:127
#2  0x00007ffff7a4397f in swift_once () from /usr/lib/swift/linux/libswiftCore.so
#3  0x0000000000558727 in _T07WTFutex7EventFdO11EFD_CLOEXECSifau () at /code/Sources/WTFutex/main.swift:66
#4  0x0000000000557464 in main () at /code/Sources/WTFutex/main.swift:126

WTFutex/main.swift:66

internal enum EventFd {
    public static let EFD_CLOEXEC = CNIOLinux.EFD_CLOEXEC <--

Every static let is causing a futex from pthread_once to support once semantics. This seems non-optimal for direct assignments.

from swift-nio.

toffaletti avatar toffaletti commented on May 20, 2024

@jckarter @gparker42 Anything to be done about this? SwiftNIO is using static let all over the place wanting something like constexpr but incurring cost of swift::swift_once on every access.

https://github.com/apple/swift/blob/3d178be169dd42b85f505ee1502232610535e4a3/stdlib/public/runtime/Once.cpp#L49

from swift-nio.

toffaletti avatar toffaletti commented on May 20, 2024

swift build -Xswiftc '-whole-module-optimization' -Xswiftc '-O'

Optimization seems to eliminate all futex calls in the reduced repro, but I still see a lot of futex calls in NIOHTTP1Server responding to a request:

1400  05:03:56 epoll_ctl(6, EPOLL_CTL_ADD, 10, {EPOLLIN|EPOLLERR|EPOLLRDHUP, {u32=10, u64=10}}) = 0 <0.000016>
1400  05:03:56 epoll_wait(6, [{EPOLLIN, {u32=10, u64=10}}], 64, -1) = 1 <0.000013>                                                                                             
1400  05:03:56 futex(0x55f11a5fca60, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000013>
1400  05:03:56 read(10, "GET / HTTP/1.1\r\nHost: localhost:8888\r\nUser-Agent: curl/7.47.0\r\nAccept: */*\r\n\r\n", 1024) = 78 <0.000017>
1400  05:03:56 futex(0x7f6818b387f8, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000012>
1400  05:03:56 mprotect(0x7f6808021000, 24576, PROT_READ|PROT_WRITE) = 0 <0.000016>
1400  05:03:56 futex(0x7f6818b387e8, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000012>
1400  05:03:56 futex(0x7f6818b05a10, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000012>
1400  05:03:56 futex(0x55f11a5fc978, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000012>
1400  05:03:56 futex(0x55f11a5fca58, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000011>
1400  05:03:56 writev(10, [{"HTTP/1.1 200 OK\r\ncontent-length: 12\r\n\r\n", 39}, {"Hello World!", 12}], 2) = 51 <0.000069>
1400  05:03:56 epoll_wait(6, [{EPOLLIN|EPOLLRDHUP, {u32=10, u64=10}}], 64, -1) = 1 <0.000017>
1400  05:03:56 read(10, "", 1024)       = 0 <0.000014>
1400  05:03:56 futex(0x55f11a5fc9d0, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000012>
1400  05:03:56 epoll_ctl(6, EPOLL_CTL_DEL, 10, 0x7f68149138f0) = 0 <0.000014>
1400  05:03:56 futex(0x55f11a5fc9f0, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000012>
1400  05:03:56 close(10)                = 0 <0.000070>
1400  05:03:56 futex(0x55f11a5f12a0, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000012>
1400  05:03:56 clock_gettime(CLOCK_MONOTONIC, {318156, 179407969}) = 0 <0.000015>

from swift-nio.

toffaletti avatar toffaletti commented on May 20, 2024

Looks like swift_getGenericMetadata is causing a futex instantiating public final class HTTPRequestDecoder: HTTPDecoder<HTTPServerRequestPart>:

Thread 2 "NIO-ELT-#0" hit Catchpoint 4 (call to syscall futex), 0x00007ffff7bc8ac0 in futex_wake (private=0, processes_to_wake=2147483647, 
    futex_word=0x5555556f83c8 <_T08NIOHTTP18HTTPPartOMP+40>) at ../sysdeps/unix/sysv/linux/futex-internal.h:231
231	../sysdeps/unix/sysv/linux/futex-internal.h: No such file or directory.
(gdb) bt
#0  0x00007ffff7bc8ac0 in futex_wake (private=0, processes_to_wake=2147483647, futex_word=0x5555556f83c8 <_T08NIOHTTP18HTTPPartOMP+40>)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:231
#1  __pthread_once_slow (once_control=0x5555556f83c8 <_T08NIOHTTP18HTTPPartOMP+40>, init_routine=0x7ffff6dfaac0 <__once_proxy>) at pthread_once.c:127
#2  0x00007ffff7680b4a in swift_getGenericMetadata () from /usr/lib/swift/linux/libswiftCore.so
#3  0x0000555555656a28 in _T08NIOHTTP18HTTPPartOMa ()
#4  0x000055555563b091 in ?? ()
#5  0x00007ffff7bc8a99 in __pthread_once_slow (once_control=0x555555702c18, init_routine=0x7ffff6dfaac0 <__once_proxy>) at pthread_once.c:116
#6  0x00007ffff768916f in swift_once () from /usr/lib/swift/linux/libswiftCore.so
#7  0x00005555556367e9 in _T08NIOHTTP118HTTPRequestDecoderCACycfC () at /code/Sources/NIOHTTP1/HTTPDecoder.swift:121
#8  _T03NIO15ChannelPipelineC8NIOHTTP1E21addHTTPServerHandlersAA15EventLoopFutureCyytGSb5first_tF (first=..., self=...) at /code/Sources/NIOHTTP1/HTTPDecoder.swift:121
#9  0x0000555555663214 in _T014NIOHTTP1Server3NIO15EventLoopFutureCyytGAB7Channel_pcfU1_ () at /code/Sources/NIOHTTP1Server/main.swift:401
#10 0x0000555555599c5e in _T03NIO7Channel_pAA15EventLoopFutureCyytGIegxo_AaB_pAEIegir_TRTA () at /code/Sources/NIO/EventLoop.swift:45
#11 0x000055555559b889 in _T03NIO7Channel_pAA15EventLoopFutureCyytGIegxo_AaB_pAEIegir_TRTA.87 ()
#12 0x0000555555599c94 in _T03NIO7Channel_pAA15EventLoopFutureCyytGIegir_AaB_pAEIegxo_TRTA () at /code/Sources/NIO/EventLoop.swift:45
#13 0x0000555555599ccf in _T03NIO15ServerBootstrapC13AcceptHandler33_C131C0126670CF68D8B594DDFAE0CE57LLC11channelReadyAA07ChannelE7ContextC3ctx_AA6NIOAnyV4datatFAA15EventLoopFutureCyytGycfU0_TA () at /code/Sources/NIO/Bootstrap.swift:208
#14 0x0000555555599cf1 in _T03NIO15EventLoopFutureCyytGIego_ytADIegio_TRTA () at /code/Sources/NIO/EventLoop.swift:45
#15 0x00005555555d7cf0 in _T03NIO15EventLoopFutureC4thenACyqd__Gs12StaticStringV4file_Su4lineAExctlFAA12CallbackList33_1CAEE0056AB83634CE1A29DE57BC300CLLVycfU_yt_ytTg5 ()
    at /code/Sources/NIO/EventLoopFuture.swift:385
#16 0x0000555555599d19 in _T03NIO15EventLoopFutureC4thenACyqd__Gs12StaticStringV4file_Su4lineAExctlFAA12CallbackList33_1CAEE0056AB83634CE1A29DE57BC300CLLVycfU_yt_ytTg5TA ()
    at /code/Sources/NIO/EventLoop.swift:45
#17 0x00005555555ddc9f in _T03NIO12CallbackList33_1CAEE0056AB83634CE1A29DE57BC300CLLV4_runyyFTf4x_n () at /code/Sources/NIO/EventLoopFuture.swift:82
#18 0x00005555555d6f44 in _T03NIO16EventLoopPromiseV8_resolve33_1CAEE0056AB83634CE1A29DE57BC300CLLyAA0bC11FutureValueAELLOyxG5value_tFyycfU_Sb_Tg5Tm ()
    at /code/Sources/NIO/EventLoopFuture.swift:620
#19 0x00005555555d6de0 in _T03NIO16EventLoopPromiseV8_resolve33_1CAEE0056AB83634CE1A29DE57BC300CLLyAA0bC11FutureValueAELLOyxG5value_tFyycfU_Sb_Tg5 ()
    at /code/Sources/NIO/EventLoopFuture.swift:620
#20 0x00005555555e77e1 in _T03NIO16EventLoopPromiseV8_resolve33_1CAEE0056AB83634CE1A29DE57BC300CLLyAA0bC11FutureValueAELLOyxG5value_tFyycfU_yt_Tg5TA ()
#21 0x00005555555c1d8c in _T0Ieg_ytytIegir_TR ()
#22 0x00005555555cdab1 in _T0Ieg_ytytIegir_TRTA ()
#23 0x00005555555c903e in _T03NIO19withAutoReleasePool33_D5D78C61B22284700B9BD1ACFBC25157LLxxyKcKlFyt_Tg5 () at /code/Sources/NIO/EventLoop.swift:520
#24 _T03NIO19SelectableEventLoopC3runyyKF (self=...) at /code/Sources/NIO/EventLoop.swift:527
#25 0x00005555555d109a in _T03NIO27MultiThreadedEventLoopGroupC014setupThreadAnddE033_D5D78C61B22284700B9BD1ACFBC25157LLAA010SelectabledE0CSS4name_yAA0H0Cc11initializertFZyAJcfU_Tf4gnnnn_n () at /code/Sources/NIO/EventLoop.swift:667
#26 0x00005555555d32a2 in _T03NIO27MultiThreadedEventLoopGroupC014setupThreadAnddE033_D5D78C61B22284700B9BD1ACFBC25157LLAA010SelectabledE0CSS4name_yAA0H0Cc11initializertFZyAJcfU_TA () at /code/Sources/NIO/Utilities.swift:34
#27 0x000055555562b11f in _T03NIO6ThreadCIegx_ACytIegir_TR ()
#28 0x00005555555d32c1 in _T03NIO6ThreadCIegx_ACytIegir_TRTA () at /code/Sources/NIO/Utilities.swift:34
#29 0x000055555562b58c in _T03NIO6ThreadC11spawnAndRunySSSg4name_yACc4bodytFZSvSgAHcfU_ () at /code/Sources/NIO/Thread.swift:105
#30 0x000055555562b5c9 in _T03NIO6ThreadC11spawnAndRunySSSg4name_yACc4bodytFZSvSgAHcfU_To ()
#31 0x00007ffff7bc16ba in start_thread (arg=0x7ffff3d8f700) at pthread_create.c:333
#32 0x00007ffff656141d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

The rest seem to be in SwiftNIO from the lock protecting SelectableEventLoop.scheduledTasks:

Thread 2 "NIO-ELT-#0" hit Catchpoint 4 (returned from syscall futex), __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
135	../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S: No such file or directory.
(gdb) bt
#0  __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1  0x00007ffff7bc3dbd in __GI___pthread_mutex_lock (mutex=0x7fffe4000a10) at ../nptl/pthread_mutex_lock.c:80
#2  0x00005555556341dd in _T021NIOConcurrencyHelpers4LockC4lockyyFTm () at /code/Sources/NIOConcurrencyHelpers/lock.swift:45
#3  0x00005555556341a0 in _T021NIOConcurrencyHelpers4LockC4lockyyF () at /code/Sources/NIOConcurrencyHelpers/lock.swift:45
#4  0x00005555555cbc29 in _T03NIO19SelectableEventLoopC9schedule033_D5D78C61B22284700B9BD1ACFBC25157LLyAA13ScheduledTaskAELLCF (task=..., self=...)
    at /code/Sources/NIO/EventLoop.swift:402
#5  _T03NIO19SelectableEventLoopC7executeyyycFTf4gn_n (task=..., self=...) at /code/Sources/NIO/EventLoop.swift:395
#6  0x00005555555c9d8e in _T03NIO19SelectableEventLoopC7executeyyycF ()
#7  _T03NIO19SelectableEventLoopCAA0cD0A2aDP7executeyyycFTW () at /code/Sources/NIO/EventLoop.swift:394
#8  0x00005555555df762 in _T03NIO15EventLoopFutureC13_whenComplete33_1CAEE0056AB83634CE1A29DE57BC300CLLyAA12CallbackListAELLVycFyt_Tg5Tf4gn_n (callback=...)
    at /code/Sources/NIO/EventLoopFuture.swift:546
#9  _T03NIO15EventLoopFutureC13_whenComplete33_1CAEE0056AB83634CE1A29DE57BC300CLLyAA12CallbackListAELLVycFyt_Tg5 (callback=...) at /code/Sources/NIO/EventLoopFuture.swift:542
#10 _T03NIO15EventLoopFutureC11whenSuccessyyxcFyt_Tg5 () at /code/Sources/NIO/EventLoopFuture.swift:570
#11 _T03NIO15EventLoopFutureC3mapACyqd__Gs12StaticStringV4file_Su4lineqd__xctlFyt_ytTg5Tf4nngn_n (file=..., line=..., callback=..., self=...)
    at /code/Sources/NIO/EventLoopFuture.swift:474
#12 0x0000555555620bd8 in _T03NIO15EventLoopFutureC3mapACyqd__Gs12StaticStringV4file_Su4lineqd__xctlFyt_ytTg5 () at /code/Sources/NIO/SocketChannel.swift:1088
#13 _T03NIO19ServerSocketChannelC12channelRead0yAA6NIOAnyVF (data=...) at /code/Sources/NIO/SocketChannel.swift:1088
#14 0x000055555561d51e in _T03NIO17BaseSocketChannelCyxGAA0D4CoreA2aEP12channelRead0yAA6NIOAnyVFTW ()
#15 0x00005555555b06e0 in _T03NIO18TailChannelHandler33_EEC863903996E9F191EBAFEB0FB0DFDDLLC11channelReadyAA0cD7ContextC3ctx_AA6NIOAnyV4datatF (ctx=..., data=...)
    at /code/Sources/NIO/ChannelPipeline.swift:811
#16 _T03NIO18TailChannelHandler33_EEC863903996E9F191EBAFEB0FB0DFDDLLCAA01_c7InboundD0A2aEP11channelReadyAA0cD7ContextC3ctx_AA6NIOAnyV4datatFTW ()
    at /code/Sources/NIO/ChannelPipeline.swift:810
#17 0x00005555555af80c in _T03NIO21ChannelHandlerContextC06invokeB4Read33_EEC863903996E9F191EBAFEB0FB0DFDDLLyAA6NIOAnyVF (data=..., self=...)
    at /code/Sources/NIO/ChannelPipeline.swift:1096
#18 0x0000555555599dbd in _T03NIO15ServerBootstrapC13AcceptHandler33_C131C0126670CF68D8B594DDFAE0CE57LLC11channelReadyAA07ChannelE7ContextC3ctx_AA6NIOAnyV4datatFyycfU1_TA ()
    at /code/Sources/NIO/ChannelPipeline.swift:909
#19 0x00005555555c1d8c in _T0Ieg_ytytIegir_TR ()
#20 0x0000555555599df1 in _T0Ieg_ytytIegir_TRTA () at /code/Sources/NIO/EventLoop.swift:45
#21 0x00005555555e7881 in _T0xytIegir_xIegi_r__lTRyt_3NIO7Channel_pTG5TA ()
#22 0x00005555555e8869 in _T0xytIegir_xIegi_r__lTRyt_ytTG5TA ()
#23 0x00005555555e6e52 in _T03NIO15EventLoopFutureC11whenSuccessyyxcFAA12CallbackList33_1CAEE0056AB83634CE1A29DE57BC300CLLVycfU_yt_Tg5TA ()
    at /code/Sources/NIO/EventLoopFuture.swift:572
#24 0x00005555555a822f in _T03NIO12CallbackList33_1CAEE0056AB83634CE1A29DE57BC300CLLVIego_ytADIegir_TR ()
#25 0x00005555555e1441 in _T03NIO12CallbackList33_1CAEE0056AB83634CE1A29DE57BC300CLLVIego_ytADIegir_TRTA ()
#26 0x00005555555e7fb9 in _T03NIO12CallbackList33_1CAEE0056AB83634CE1A29DE57BC300CLLVIego_ytADIegir_TRTA.692 ()
#27 0x00005555555dda80 in _T03NIO12CallbackList33_1CAEE0056AB83634CE1A29DE57BC300CLLV4_runyyFTf4x_n () at /code/Sources/NIO/EventLoopFuture.swift:106
#28 0x00005555555d6f44 in _T03NIO16EventLoopPromiseV8_resolve33_1CAEE0056AB83634CE1A29DE57BC300CLLyAA0bC11FutureValueAELLOyxG5value_tFyycfU_Sb_Tg5Tm ()
    at /code/Sources/NIO/EventLoopFuture.swift:620
#29 0x00005555555d6de0 in _T03NIO16EventLoopPromiseV8_resolve33_1CAEE0056AB83634CE1A29DE57BC300CLLyAA0bC11FutureValueAELLOyxG5value_tFyycfU_Sb_Tg5 ()
    at /code/Sources/NIO/EventLoopFuture.swift:620
#30 0x00005555555e77e1 in _T03NIO16EventLoopPromiseV8_resolve33_1CAEE0056AB83634CE1A29DE57BC300CLLyAA0bC11FutureValueAELLOyxG5value_tFyycfU_yt_Tg5TA ()
#31 0x00005555555c1d8c in _T0Ieg_ytytIegir_TR ()
#32 0x00005555555cdab1 in _T0Ieg_ytytIegir_TRTA ()
#33 0x00005555555c903e in _T03NIO19withAutoReleasePool33_D5D78C61B22284700B9BD1ACFBC25157LLxxyKcKlFyt_Tg5 () at /code/Sources/NIO/EventLoop.swift:520
#34 _T03NIO19SelectableEventLoopC3runyyKF (self=...) at /code/Sources/NIO/EventLoop.swift:527
---Type <return> to continue, or q <return> to quit---
#35 0x00005555555d109a in _T03NIO27MultiThreadedEventLoopGroupC014setupThreadAnddE033_D5D78C61B22284700B9BD1ACFBC25157LLAA010SelectabledE0CSS4name_yAA0H0Cc11initializertFZyAJcfU_Tf4gnnnn_n () at /code/Sources/NIO/EventLoop.swift:667
#36 0x00005555555d32a2 in _T03NIO27MultiThreadedEventLoopGroupC014setupThreadAnddE033_D5D78C61B22284700B9BD1ACFBC25157LLAA010SelectabledE0CSS4name_yAA0H0Cc11initializertFZyAJcfU_TA () at /code/Sources/NIO/Utilities.swift:34
#37 0x000055555562b11f in _T03NIO6ThreadCIegx_ACytIegir_TR ()
#38 0x00005555555d32c1 in _T03NIO6ThreadCIegx_ACytIegir_TRTA () at /code/Sources/NIO/Utilities.swift:34
#39 0x000055555562b58c in _T03NIO6ThreadC11spawnAndRunySSSg4name_yACc4bodytFZSvSgAHcfU_ () at /code/Sources/NIO/Thread.swift:105
#40 0x000055555562b5c9 in _T03NIO6ThreadC11spawnAndRunySSSg4name_yACc4bodytFZSvSgAHcfU_To ()
#41 0x00007ffff7bc16ba in start_thread (arg=0x7ffff3d8f700) at pthread_create.c:333
#42 0x00007ffff656141d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

(gdb) bt
#0  __lll_unlock_wake () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:371
#1  0x00007ffff7bc54ff in __pthread_mutex_unlock_usercnt (decr=1, mutex=0x7fffe4000a10) at pthread_mutex_unlock.c:55
#2  __GI___pthread_mutex_unlock (mutex=0x7fffe4000a10) at pthread_mutex_unlock.c:314
#3  0x00005555556341dd in _T021NIOConcurrencyHelpers4LockC4lockyyFTm () at /code/Sources/NIOConcurrencyHelpers/lock.swift:45
#4  0x00005555556341c0 in _T021NIOConcurrencyHelpers4LockC6unlockyyF () at /code/Sources/NIOConcurrencyHelpers/lock.swift:45
#5  0x00005555555cbc8d in _T03NIO19SelectableEventLoopC9schedule033_D5D78C61B22284700B9BD1ACFBC25157LLyAA13ScheduledTaskAELLCF (task=..., self=...)
    at /code/Sources/NIO/EventLoop.swift:404

from swift-nio.

Lukasa avatar Lukasa commented on May 20, 2024

This is definitely worth diving into to see if we can elide the calls to futex, but I don't think this is the highest priority right now: in general futexes are fast, particularly where there is relatively little contention on them as in the case of a channel handler init.

I'm going to reach out to some folks on the Swift team and see if they have any particular thoughts on whether we can avoid this, but I suspect it's basically unavoidable for generic classes like HTTPDecoder.

from swift-nio.

Lukasa avatar Lukasa commented on May 20, 2024

(Naturally it goes without saying that the futex around scheduledTasks is unavoidable in the current implementation. At some point we'll want to investigate the performance profile of a lock-free heap, but that's not necessarily a guaranteed win either.)

from swift-nio.

jckarter avatar jckarter commented on May 20, 2024

Does the futex happen on every access, or only the first? We could consider using dispatch_once for one-time initializations like we do on Darwin, which should not have any barrier after the initialization happens. If you're writing static lets that are constants, and the optimizer is not turning them into static initializations, then please file optimizer bugs too.

from swift-nio.

gparker42 avatar gparker42 commented on May 20, 2024

Yes, it would help if you could distinguish between futex accesses during launch time or at first use, versus futex accesses during steady-state operation. Both are worth investigating to improve performance, but the latter would be a more significant problem.

from swift-nio.

toffaletti avatar toffaletti commented on May 20, 2024

Thanks, I will work on teasing those apart. The issue I'm running into now is that I have to use an optimized build which makes debugging a bit more difficult and I haven't figured out a way to make gdb only pause execution on the futex calls in the thread I care about and pausing on all threads calls to futex seems to introduce different behavior because of timeouts and various timing issues. I might need to resort to a different tool.

from swift-nio.

weissi avatar weissi commented on May 20, 2024

We should look into this

from swift-nio.

allright avatar allright commented on May 20, 2024

I think this is the over side of this issue:
#894

from swift-nio.

weissi avatar weissi commented on May 20, 2024

@Lukasa et al: I think we can close this issue. I recently made some perf analysis at work and I counted every single syscall in a program that doesn't use wait().

Program

let group = MultiThreadedEventLoopGroup(numberOfThreads: Int(CommandLine.arguments.dropFirst().first!)!)
defer {
    try! group.syncShutdownGracefully()
}

let allDone = group.next().makePromise(of: Int.self)

func doIt(allDone: EventLoopPromise<Int>, n: Int, accumulator: Int) {
    guard n > 0 else {
        allDone.succeed(accumulator)
        return
    }

    group.next().makeSucceededFuture(1).flatMap { one in
        group.next().makeSucceededFuture(one + 1)
    }.flatMap { two in
        group.next().makeSucceededFuture(two + 1)
    }.flatMap { three in
        group.next().makeSucceededFuture(three + 1)
    }.flatMap { four in
        group.next().makeSucceededFuture(four + 1)
    }.whenSuccess { sum in
        group.next().execute {
            doIt(allDone: allDone, n: n - 1, accumulator: accumulator + sum)
        }
    }
}

doIt(allDone: allDone, n: 10_000, accumulator: 0)
print(try allDone.futureResult.wait())

and the results were:

  • for 1 thread (no needless hopping)
# perf stat -e 'syscalls:sys_enter_*' .build/release/TestProgram 1 | grep -E '[0-9]{3,}'
50000
             20023      syscalls:sys_enter_clock_gettime
       0.189682700 seconds time elapsed
       0.068381000 seconds user
       0.111246000 seconds sys

the clock_gettime only appears here because this was in Docker for Mac where the VSDO'd clock_gettime is disabled because of hypervisor deficiencies...

  • for 4 threads (ie. lots of useless hopping
# perf stat -e 'syscalls:sys_enter_*' .build/release/TestProgram 4 | grep -E '[0-9]{3,}'
50000
             79613      syscalls:sys_enter_epoll_wait
             79631      syscalls:sys_enter_read
             79613      syscalls:sys_enter_write
            200046      syscalls:sys_enter_clock_gettime
       7.557578300 seconds time elapsed
       0.821708000 seconds user
       5.878427000 seconds sys

the read/write here are for the eventfd

from swift-nio.

Lukasa avatar Lukasa commented on May 20, 2024

Happy to close this.

from swift-nio.

Related Issues (20)

Recommend Projects

  • React photo React

    A declarative, efficient, and flexible JavaScript library for building user interfaces.

  • Vue.js photo Vue.js

    🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.

  • Typescript photo Typescript

    TypeScript is a superset of JavaScript that compiles to clean JavaScript output.

  • TensorFlow photo TensorFlow

    An Open Source Machine Learning Framework for Everyone

  • Django photo Django

    The Web framework for perfectionists with deadlines.

  • D3 photo D3

    Bring data to life with SVG, Canvas and HTML. 📊📈🎉

Recommend Topics

  • javascript

    JavaScript (JS) is a lightweight interpreted programming language with first-class functions.

  • web

    Some thing interesting about web. New door for the world.

  • server

    A server is a program made to process requests and deliver data to clients.

  • Machine learning

    Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.

  • Game

    Some thing interesting about game, make everyone happy.

Recommend Org

  • Facebook photo Facebook

    We are working to build community through open source technology. NB: members must have two-factor auth.

  • Microsoft photo Microsoft

    Open source projects and samples from Microsoft.

  • Google photo Google

    Google ❤️ Open Source for everyone.

  • D3 photo D3

    Data-Driven Documents codes.