# Confirmed that the workaround works in practice.
I had a hang, figured out which /usr/bin/script process was eating the CPU, then issued:
head -n 1 /proc/7514/fd/4
and it continued working.
# Try to figure out what happens.
Below is after the problem was fixed (things worked well again, the terminal running /usr/bin/script has some text flowing at all times).
In another terminal I typed the commands below
{ while sleep 1 ; do date ; done } & # First, get some timestamps to see where program pauses strace head -n 1 /proc/7514/fd/4
And observed the output below (shortened):
open("/proc/7514/fd/4", O_RDONLY) = 3 read(3, jeudi 7 avril 2016, 14:30:02 (UTC+0200) jeudi 7 avril 2016, 14:30:03 (UTC+0200) jeudi 7 avril 2016, 14:30:04 (UTC+0200)
"head" sat waiting until I typed something in the terminal running /usr/bin/script.
jeudi 7 avril 2016, 14:30:05 (UTC+0200) jeudi 7 avril 2016, 14:30:06 (UTC+0200) "\n", 8192) = 1 lseek(3, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) fstat(3, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 12), ...}) = 0 fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 4), ...}) = 0 write(1, "\n", 1 ) = 1 close(3) = 0 close(1) = 0 close(2) = 0 exit_group(0) = ?
I'll compare with what happens next time /usr/bin/script hangs.
Full output
execve("/usr/bin/head", ["head", "-n", "1", "/proc/7514/fd/4"], [/* 72 vars */]) = 0 brk(NULL) = 0xde4000 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f35d956c000 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=123250, ...}) = 0 mmap(NULL, 123250, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f35d954d000 close(3) = 0 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) open("/lib/x86_64-linux-gnu/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\0`\t\2\0\0\0\0\0"..., 832) = 832 fstat(3, {st_mode=S_IFREG|0755, st_size=1868984, ...}) = 0 mmap(NULL, 3971584, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f35d8f7f000 mprotect(0x7f35d913f000, 2097152, PROT_NONE) = 0 mmap(0x7f35d933f000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1c0000) = 0x7f35d933f000 mmap(0x7f35d9345000, 14848, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f35d9345000 close(3) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f35d954c000 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f35d954b000 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f35d954a000 arch_prctl(ARCH_SET_FS, 0x7f35d954b700) = 0 mprotect(0x7f35d933f000, 16384, PROT_READ) = 0 mprotect(0x608000, 4096, PROT_READ) = 0 mprotect(0x7f35d956e000, 4096, PROT_READ) = 0 munmap(0x7f35d954d000, 123250) = 0 brk(NULL) = 0xde4000 brk(0xe05000) = 0xe05000 open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=3001856, ...}) = 0 mmap(NULL, 3001856, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f35d8ca2000 close(3) = 0 open("/usr/share/locale/locale.alias", O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=2995, ...}) = 0 read(3, "# Locale name alias data base.\n#"..., 4096) = 2995 read(3, "", 4096) = 0 close(3) = 0 open("/usr/share/locale/fr_FR/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/share/locale/fr/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/share/locale-langpack/fr_FR/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/share/locale-langpack/fr/LC_MESSAGES/coreutils.mo", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=297935, ...}) = 0 mmap(NULL, 297935, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f35d9501000 close(3) = 0 open("/usr/lib/x86_64-linux-gnu/gconv/gconv-modules.cache", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=26258, ...}) = 0 mmap(NULL, 26258, PROT_READ, MAP_SHARED, 3, 0) = 0x7f35d9565000 close(3) = 0 open("/proc/7514/fd/4", O_RDONLY) = 3 read(3, jeudi 7 avril 2016, 14:30:02 (UTC+0200) jeudi 7 avril 2016, 14:30:03 (UTC+0200) jeudi 7 avril 2016, 14:30:04 (UTC+0200) jeudi 7 avril 2016, 14:30:05 (UTC+0200) jeudi 7 avril 2016, 14:30:06 (UTC+0200) "\n", 8192) = 1 lseek(3, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) fstat(3, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 12), ...}) = 0 fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 4), ...}) = 0 write(1, "\n", 1 ) = 1 close(3) = 0 close(1) = 0 close(2) = 0 exit_group(0) = ? +++ exited with 0 +++
# Confirmed that the workaround works in practice.
I had a hang, figured out which /usr/bin/script process was eating the CPU, then issued:
head -n 1 /proc/7514/fd/4
and it continued working.
# Try to figure out what happens.
Below is after the problem was fixed (things worked well again, the terminal running /usr/bin/script has some text flowing at all times).
In another terminal I typed the commands below
{ while sleep 1 ; do date ; done } & # First, get some timestamps to see where program pauses
strace head -n 1 /proc/7514/fd/4
And observed the output below (shortened):
open("/ proc/7514/ fd/4", O_RDONLY) = 3
read(3, jeudi 7 avril 2016, 14:30:02 (UTC+0200)
jeudi 7 avril 2016, 14:30:03 (UTC+0200)
jeudi 7 avril 2016, 14:30:04 (UTC+0200)
"head" sat waiting until I typed something in the terminal running /usr/bin/script.
jeudi 7 avril 2016, 14:30:05 (UTC+0200) S_IFCHR| 0620, st_rdev= makedev( 136, 12), ...}) = 0 S_IFCHR| 0620, st_rdev= makedev( 136, 4), ...}) = 0
jeudi 7 avril 2016, 14:30:06 (UTC+0200)
"\n", 8192) = 1
lseek(3, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
fstat(3, {st_mode=
fstat(1, {st_mode=
write(1, "\n", 1
) = 1
close(3) = 0
close(1) = 0
close(2) = 0
exit_group(0) = ?
I'll compare with what happens next time /usr/bin/script hangs.
Full output
execve( "/usr/bin/ head", ["head", "-n", "1", "/proc/7514/fd/4"], [/* 72 vars */]) = 0 "/etc/ld. so.nohwcap" , F_OK) = -1 ENOENT (No such file or directory) PROT_WRITE, MAP_PRIVATE| MAP_ANONYMOUS, -1, 0) = 0x7f35d956c000 "/etc/ld. so.preload" , R_OK) = -1 ENOENT (No such file or directory) etc/ld. so.cache" , O_RDONLY|O_CLOEXEC) = 3 S_IFREG| 0644, st_size=123250, ...}) = 0 "/etc/ld. so.nohwcap" , F_OK) = -1 ENOENT (No such file or directory) lib/x86_ 64-linux- gnu/libc. so.6", O_RDONLY|O_CLOEXEC) = 3 2\1\1\3\ 0\0\0\0\ 0\0\0\0\ 3\0>\0\ 1\0\0\0` \t\2\0\ 0\0\0\0" ..., 832) = 832 S_IFREG| 0755, st_size=1868984, ...}) = 0 PROT_EXEC, MAP_PRIVATE| MAP_DENYWRITE, 3, 0) = 0x7f35d8f7f000 0x7f35d913f000, 2097152, PROT_NONE) = 0 f000, 24576, PROT_READ| PROT_WRITE, MAP_PRIVATE| MAP_FIXED| MAP_DENYWRITE, 3, 0x1c0000) = 0x7f35d933f000 5000, 14848, PROT_READ| PROT_WRITE, MAP_PRIVATE| MAP_FIXED| MAP_ANONYMOUS, -1, 0) = 0x7f35d9345000 PROT_WRITE, MAP_PRIVATE| MAP_ANONYMOUS, -1, 0) = 0x7f35d954c000 PROT_WRITE, MAP_PRIVATE| MAP_ANONYMOUS, -1, 0) = 0x7f35d954b000 PROT_WRITE, MAP_PRIVATE| MAP_ANONYMOUS, -1, 0) = 0x7f35d954a000 ARCH_SET_ FS, 0x7f35d954b700) = 0 0x7f35d933f000, 16384, PROT_READ) = 0 0x7f35d956e000, 4096, PROT_READ) = 0 0x7f35d954d000, 123250) = 0 usr/lib/ locale/ locale- archive" , O_RDONLY|O_CLOEXEC) = 3 S_IFREG| 0644, st_size=3001856, ...}) = 0 usr/share/ locale/ locale. alias", O_RDONLY|O_CLOEXEC) = 3 S_IFREG| 0644, st_size=2995, ...}) = 0 usr/share/ locale/ fr_FR/LC_ MESSAGES/ coreutils. mo", O_RDONLY) = -1 ENOENT (No such file or directory) usr/share/ locale/ fr/LC_MESSAGES/ coreutils. mo", O_RDONLY) = -1 ENOENT (No such file or directory) usr/share/ locale- langpack/ fr_FR/LC_ MESSAGES/ coreutils. mo", O_RDONLY) = -1 ENOENT (No such file or directory) usr/share/ locale- langpack/ fr/LC_MESSAGES/ coreutils. mo", O_RDONLY) = 3 S_IFREG| 0644, st_size=297935, ...}) = 0 usr/lib/ x86_64- linux-gnu/ gconv/gconv- modules. cache", O_RDONLY) = 3 S_IFREG| 0644, st_size=26258, ...}) = 0 proc/7514/ fd/4", O_RDONLY) = 3 S_IFCHR| 0620, st_rdev= makedev( 136, 12), ...}) = 0 S_IFCHR| 0620, st_rdev= makedev( 136, 4), ...}) = 0
brk(NULL) = 0xde4000
access(
mmap(NULL, 8192, PROT_READ|
access(
open("/
fstat(3, {st_mode=
mmap(NULL, 123250, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f35d954d000
close(3) = 0
access(
open("/
read(3, "\177ELF\
fstat(3, {st_mode=
mmap(NULL, 3971584, PROT_READ|
mprotect(
mmap(0x7f35d933
mmap(0x7f35d934
close(3) = 0
mmap(NULL, 4096, PROT_READ|
mmap(NULL, 4096, PROT_READ|
mmap(NULL, 4096, PROT_READ|
arch_prctl(
mprotect(
mprotect(0x608000, 4096, PROT_READ) = 0
mprotect(
munmap(
brk(NULL) = 0xde4000
brk(0xe05000) = 0xe05000
open("/
fstat(3, {st_mode=
mmap(NULL, 3001856, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f35d8ca2000
close(3) = 0
open("/
fstat(3, {st_mode=
read(3, "# Locale name alias data base.\n#"..., 4096) = 2995
read(3, "", 4096) = 0
close(3) = 0
open("/
open("/
open("/
open("/
fstat(3, {st_mode=
mmap(NULL, 297935, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f35d9501000
close(3) = 0
open("/
fstat(3, {st_mode=
mmap(NULL, 26258, PROT_READ, MAP_SHARED, 3, 0) = 0x7f35d9565000
close(3) = 0
open("/
read(3, jeudi 7 avril 2016, 14:30:02 (UTC+0200)
jeudi 7 avril 2016, 14:30:03 (UTC+0200)
jeudi 7 avril 2016, 14:30:04 (UTC+0200)
jeudi 7 avril 2016, 14:30:05 (UTC+0200)
jeudi 7 avril 2016, 14:30:06 (UTC+0200)
"\n", 8192) = 1
lseek(3, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
fstat(3, {st_mode=
fstat(1, {st_mode=
write(1, "\n", 1
) = 1
close(3) = 0
close(1) = 0
close(2) = 0
exit_group(0) = ?
+++ exited with 0 +++