FS#61463 - GNU Screen slowdown

Attached to Project: Arch Linux
Opened by Lukas Waymann (meribold) - Saturday, 19 January 2019, 13:15 GMT
Last edited by Jan de Groot (JGC) - Thursday, 31 October 2019, 08:20 GMT
Task Type Bug Report
Category Packages: Extra
Status Closed
Assigned To No-one
Architecture All
Severity Low
Priority Normal
Reported Version
Due in Version Undecided
Due Date Undecided
Percent Complete 100%
Votes 0
Private No

Details

GNU Screen takes oddly long to start since I did a system upgrade. The screen package itself wasn't upgraded (still version 4.6.2-1).

$ time screen --version
Screen version 4.06.02 (GNU) 23-Oct-17

real 0m0.170s
user 0m0.057s
sys 0m0.112s
$ echo $?
1

I'm pretty sure this used to be instant before. (Also note that the exit status is 1.) Running screen with any other command-line options is similarly slower. This is especially annoying when using scripts that invoke screen multiple times to send commands to a screen session.

The strace of `screen --version` is interesting:

$ strace screen --version &> screen-strace.txt
$ $ du -h screen-strace.txt
37M screen-strace.txt

This is what it looks like (abridged):

execve("/usr/bin/screen", ["screen", "--version"], 0x7ffe6fae1658 /* 43 vars */) = 0
access("/etc/suid-debug", F_OK) = -1 ENOENT (No such file or directory)
brk(NULL) = 0x5570a6a60000
arch_prctl(0x3001 /* ARCH_??? */, 0x7ffc8551a8c0) = -1 EINVAL (Invalid argument)
fcntl(0, F_GETFD) = 0
fcntl(1, F_GETFD) = 0
fcntl(2, F_GETFD) = 0
access("/etc/suid-debug", F_OK) = -1 ENOENT (No such file or directory)
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=232430, ...}) = 0
mmap(NULL, 232430, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fa20bd14000
close(3) = 0
openat(AT_FDCWD, "/usr/lib/tls/x86_64/x86_64/libtinfo.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/tls/x86_64/x86_64", 0x7ffc85519b00) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/tls/x86_64/libtinfo.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/tls/x86_64", 0x7ffc85519b00) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/tls/x86_64/libtinfo.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/tls/x86_64", 0x7ffc85519b00) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/tls/libtinfo.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/tls", 0x7ffc85519b00) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/x86_64/x86_64/libtinfo.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/x86_64/x86_64", 0x7ffc85519b00) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/x86_64/libtinfo.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/x86_64", 0x7ffc85519b00) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/x86_64/libtinfo.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/x86_64", 0x7ffc85519b00) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/libtinfo.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 p\1\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=449040, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa20bd12000
mmap(NULL, 453880, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa20bca3000
mmap(0x7fa20bcba000, 241664, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x17000) = 0x7fa20bcba000
mmap(0x7fa20bcf5000, 94208, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x52000) = 0x7fa20bcf5000
mmap(0x7fa20bd0c000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x68000) = 0x7fa20bd0c000
close(3) = 0
openat(AT_FDCWD, "/usr/lib/libcrypt.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 \20\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=42912, ...}) = 0
mmap(NULL, 233824, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa20bc69000
mprotect(0x7fa20bc6a000, 36864, PROT_NONE) = 0
mmap(0x7fa20bc6a000, 24576, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1000) = 0x7fa20bc6a000
mmap(0x7fa20bc70000, 8192, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x7000) = 0x7fa20bc70000
mmap(0x7fa20bc73000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x9000) = 0x7fa20bc73000
mmap(0x7fa20bc75000, 184672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fa20bc75000
close(3) = 0
openat(AT_FDCWD, "/usr/lib/libpam.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0`\"\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=55048, ...}) = 0
mmap(NULL, 2150416, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa20ba5b000
mprotect(0x7fa20ba68000, 2093056, PROT_NONE) = 0
mmap(0x7fa20bc67000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xc000) = 0x7fa20bc67000
close(3) = 0
openat(AT_FDCWD, "/usr/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0000C\2\0\0\0\0\0"..., 832) = 832
lseek(3, 792, SEEK_SET) = 792
read(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\201\336\t\36\251c\324\233E\371SoK\5H\334"..., 68) = 68
fstat(3, {st_mode=S_IFREG|0755, st_size=2136840, ...}) = 0
lseek(3, 792, SEEK_SET) = 792
read(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\201\336\t\36\251c\324\233E\371SoK\5H\334"..., 68) = 68
lseek(3, 864, SEEK_SET) = 864
read(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32) = 32
mmap(NULL, 1848896, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa20b897000
mprotect(0x7fa20b8b9000, 1671168, PROT_NONE) = 0
mmap(0x7fa20b8b9000, 1355776, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x22000) = 0x7fa20b8b9000
mmap(0x7fa20ba04000, 311296, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16d000) = 0x7fa20ba04000
mmap(0x7fa20ba51000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b9000) = 0x7fa20ba51000
mmap(0x7fa20ba57000, 13888, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fa20ba57000
close(3) = 0
openat(AT_FDCWD, "/usr/lib/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 \20\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=14240, ...}) = 0
mmap(NULL, 16528, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa20b892000
mmap(0x7fa20b893000, 4096, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1000) = 0x7fa20b893000
mmap(0x7fa20b894000, 4096, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7fa20b894000
mmap(0x7fa20b895000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7fa20b895000
close(3) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa20b890000
arch_prctl(ARCH_SET_FS, 0x7fa20b891000) = 0
mprotect(0x7fa20ba51000, 16384, PROT_READ) = 0
mprotect(0x7fa20b895000, 4096, PROT_READ) = 0
mprotect(0x7fa20bc67000, 4096, PROT_READ) = 0
mprotect(0x7fa20bc73000, 4096, PROT_READ) = 0
mprotect(0x7fa20bd0c000, 20480, PROT_READ) = 0
mprotect(0x5570a5ede000, 4096, PROT_READ) = 0
mprotect(0x7fa20bd76000, 4096, PROT_READ) = 0
munmap(0x7fa20bd14000, 232430) = 0
prlimit64(0, RLIMIT_NOFILE, NULL, {rlim_cur=1024, rlim_max=512*1024}) = 0
close(524287) = -1 EBADF (Bad file descriptor)
close(524286) = -1 EBADF (Bad file descriptor)
close(524285) = -1 EBADF (Bad file descriptor)
...
...
(This goes on.)
...
...
close(5) = -1 EBADF (Bad file descriptor)
close(4) = -1 EBADF (Bad file descriptor)
close(3) = -1 EBADF (Bad file descriptor)
brk(NULL) = 0x5570a6a60000
brk(0x5570a6a81000) = 0x5570a6a81000
getuid() = 1000
getgid() = 100
geteuid() = 1000
getegid() = 100
fstat(1, {st_mode=S_IFREG|0644, st_size=38279899, ...}) = 0
write(1, "Screen version 4.06.02 (GNU) 23-"..., 40Screen version 4.06.02 (GNU) 23-Oct-17
) = 40
exit_group(1) = ?
+++ exited with 1 +++
This task depends upon

Closed by  Jan de Groot (JGC)
Thursday, 31 October 2019, 08:20 GMT
Reason for closing:  Fixed
Additional comments about closing:  4.7.0
Comment by Lukas Waymann (meribold) - Monday, 21 January 2019, 14:51 GMT
I tracked this down to be triggered by an upstream systemd change:

https://github.com/systemd/systemd/commit/8aeb1d3176bf90f42c469deb40c3cfdda913acf2
https://github.com/systemd/systemd/commit/09dad04c49cae3ad2b319c9b4e7773fedd34309a

systemd started setting RLIMIT_NOFILE to something much bigger than the Linux default (524288 instead of 4096, it seems). This somehow results in Screen trying to close half a million files whenever it starts (as far as I can see).

I added `DefaultLimitNOFILE=1024:4096` to my /etc/systemd/system.conf for the time being. I'd say this is an upstream issue and we can close this task (maybe GNU Screen has to be changed).
Comment by loqs (loqs) - Saturday, 09 March 2019, 00:14 GMT
Thank you meribold for raising the issue upstream [1].
Could ec90292592dd2c9d5c108390841e3df24e377ed5 be applied to the arch package to avoid screen attempting to close 524288 file descriptors on startup?
[1] https://savannah.gnu.org/bugs/?55618
Comment by Lukas Waymann (meribold) - Saturday, 09 March 2019, 05:43 GMT
I assume that would work. I also just asked in the upstream bug report about when a new release of GNU Screen that includes the fix may be available.

Loading...