Re: Severe performance degradation on Linux

Hi,

On Tue, Jan 6, 2015 at 4:00 PM, Michael Meeks <michael.meeks@collabora.com>
wrote:
>         Hit page-down in 'less' - and when you see the time-stamp 'jump'
(ie.
> we missed 20 seconds ;-) on the left - then that's the interesting bit.
I page-down-scrolled through the output twice, but cannot find any
multi-second gaps that large; the largest one I can find is where we jump
from '1420550763.815456' to '1420550767.680846' (see attachment). But I
dont think that this is the smoking gun you were hoping for ?


> > Are the large amounts of 'futex(FUTEX_WAIT_PRIVATE) /
> > futex(FUTEX_WAKE_PRIVATE)' expected behavior in this case ?
>
>         Yes - quite expected - and yes we take locks and release them
just for
> fun all over the place: then again, we shouldn't take contended locks a
> lot so should avoid the syscall there mostly which is in itself odd -
> but I doubt that that is related to your problem.
Well you seem to know what youre talking about most of the time so I guess
that, until I finally learn to code for myself, ill take your word for it.
;)
It's just that to the untrained eye, 49265 calls of FUTEX_WAIT_PRIVATE and
73749 calls of FUTEX_WAKE_PRIVATE seem like an awful lot of locking
business. Thanks for taking the time to explain that is expected though.



- Maarten

3991  1420550762.866360 bind(19, {sa_family=AF_INET, sin_port=htons(2002), 
sin_addr=inet_addr("127.0.0.1")}, 16) = 0
3991  1420550762.866388 listen(19, 128) = 0
3991  1420550762.866431 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 20
3991  1420550762.866446 fcntl(20, F_GETFD) = 0
3991  1420550762.866454 fcntl(20, F_SETFD, FD_CLOEXEC) = 0
3991  1420550762.866476 accept(19,  <unfinished ...>
3986  1420550762.879642 <... poll resumed> ) = 0 (Timeout)
3986  1420550762.879658 poll([{fd=6, events=POLLIN}], 1, 4294967295 <unfinished ...>
3989  1420550763.810816 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
3989  1420550763.810922 futex(0x2a235d0, FUTEX_WAKE_PRIVATE, 1) = 0
3989  1420550763.811013 
mkdir("/home/buildslave/source/libo-core/instdir/program/../program/../user", 0777) = -1 EEXIST 
(File exists)
3989  1420550763.811158 
open("/home/buildslave/source/libo-core/instdir/program/../program/../user/xn26n6", 
O_RDWR|O_CREAT|O_EXCL, 0600) = 22
3989  1420550763.811329 fstat(22, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
3989  1420550763.811391 fcntl(22, F_SETLK, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0
3989  1420550763.811473 pread(22, "", 4096, 0) = 0
3989  1420550763.811933 pwrite(22, "<?xml version=\"1.0\" encoding=\"UTF-8\"?>\n<oor:items 
xmlns:oor=\"http://openoffice.org/2001/registry\"; xmlns:xs=\"http://www.w3.org/2001/XM
LSchema\" xmlns:xsi=\"http://www.w3.org/2001/XMLSchema-instance\";>\n<item 
oor:path=\"/org.openoffice.Office.Common/Misc\"><prop o"..., 4096, 0) = 4096
3989  1420550763.812051 pread(22, "", 4096, 4096) = 0
3989  1420550763.812237 pwrite(22, "Linguistic/ServiceManager/SpellCheckerList\"><prop 
oor:name=\"en-MW\" oor:op=\"fuse\" oor:type=\"oor:string-list\"><value><it>org.openoffice.
lingu.MySpellSpellChecker</it></value></prop></item>\n<item 
oor:path=\"/org.openoffice.Office.Linguistic/ServiceManager/Spel"..., 4096, 4096) = 4096
3989  1420550763.812298 pread(22, "", 4096, 8192) = 0
3989  1420550763.812462 pwrite(22, "uistic/ServiceManager/LastFoundSpellCheckers\"><prop 
oor:name=\"en-BS\" oor:op=\"fuse\" oor:type=\"oor:string-list\"><value><it>org.openoffic
e.lingu.MySpellSpellChecker</it></value></prop></item>\n<item 
oor:path=\"/org.openoffice.Office.Linguistic/ServiceManager/La"..., 4096, 8192) = 4096
3989  1420550763.812519 pread(22, "", 4096, 12288) = 0
3989  1420550763.812805 pwrite(22, "llChecker</it></value></prop></item>\n<item 
oor:path=\"/org.openoffice.Office.Linguistic/ServiceManager/LastFoundSpellCheckers\"><prop oor:na
me=\"en-ZA\" oor:op=\"fuse\" 
oor:type=\"oor:string-list\"><value><it>org.openoffice.lingu.MySpellSpellChecker</it></value></"...,
 4096, 12288) = 4096
3989  1420550763.812888 pread(22, "", 4096, 16384) = 0
3989  1420550763.813064 pwrite(22, "nager/HyphenatorList\"><prop oor:name=\"en-SG\" oor:op=\"fuse\" 
oor:type=\"oor:string-list\"><value><it>org.openoffice.lingu.LibHnjHyphenator
</it></value></prop></item>\n<item 
oor:path=\"/org.openoffice.Office.Linguistic/ServiceManager/HyphenatorList\"><prop oor:nam"..., 
4096, 16384) = 4096
3989  1420550763.813120 pread(22, "", 4096, 20480) = 0
3989  1420550763.813287 pwrite(22, "or:op=\"fuse\" 
oor:type=\"oor:string-list\"><value><it>org.openoffice.lingu.LibHnjHyphenator</it></value></prop></item>\n<item
 oor:path=\"/or
g.openoffice.Office.Linguistic/ServiceManager/LastFoundHyphenators\"><prop oor:name=\"en-NA\" 
oor:op=\"fuse\" oor:type=\"oor:st"..., 4096, 20480) = 4096
3989  1420550763.813343 pread(22, "", 4096, 24576) = 0
3989  1420550763.813507 pwrite(22, "hesaurus</it></value></prop></item>\n<item 
oor:path=\"/org.openoffice.Office.Linguistic/ServiceManager/ThesaurusList\"><prop oor:name=\"en-IE
\" oor:op=\"fuse\" 
oor:type=\"oor:string-list\"><value><it>org.openoffice.lingu.new.Thesaurus</it></value></prop></item>\n<it"...,
 4096, 24576) = 4096
3989  1420550763.813562 pread(22, "", 4096, 28672) = 0
3989  1420550763.813807 pwrite(22, 
"\"><value><it>org.openoffice.lingu.new.Thesaurus</it></value></prop></item>\n<item 
oor:path=\"/org.openoffice.Office.Linguistic/ServiceManage
r/LastFoundThesauri\"><prop oor:name=\"en-AU\" oor:op=\"fuse\" 
oor:type=\"oor:string-list\"><value><it>org.openoffice.lingu.n"..., 4096, 28672) = 4096
3989  1420550763.813888 pread(22, "", 4096, 32768) = 0
3989  1420550763.814119 pwrite(22, "uistic/ServiceManager/LastFoundThesauri\"><prop 
oor:name=\"en-ZA\" oor:op=\"fuse\" 
oor:type=\"oor:string-list\"><value><it>org.openoffice.lingu.new.Thesaurus</it></value></prop></item>\n<item
 oor:path=\"/org.openoffice.Office.Linguistic/ServiceManager/LastFoundThes"..., 4096, 32768) = 4096
3989  1420550763.814179 pread(22, "", 4096, 36864) = 0
3989  1420550763.814314 pwrite(22, 
"th=\"/org.openoffice.Office.UI.WriterWindowState/UIElements/States/org.openoffice.Office.UI.WindowState:WindowStateType['private:resource/toolbar/standardbar']\"><prop
 oor:name=\"Visible\" oor:op=\"fuse\"><value>true</value></prop></item>\n<item 
oor:path=\"/org.op"..., 2265, 36864) = 2265
3989  1420550763.814383 close(22)       = 0
3989  1420550763.814559 
rename("/home/buildslave/source/libo-core/instdir/program/../program/../user/xn26n6", 
"/home/buildslave/source/libo-core/instdir/program/../program/../user/registrymodifications.xcu") = 0
3989  1420550763.815325 madvise(0x7f15f1b73000, 8368128, MADV_DONTNEED) = 0
3989  1420550763.815381 _exit(0)        = ?
3989  1420550763.815456 +++ exited with 0 +++
3972  1420550767.680846 <... select resumed> ) = 0 (Timeout)
3972  1420550767.685452 open("/usr/lib64/libreoffice/ure/lib/libuuresolverlo.so", 
O_RDONLY|O_CLOEXEC) = 7
3972  1420550767.685580 read(7, 
"\177ELF\2\1\1\3\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\30z\0\0\0\0\0\0\0\0\0\0@\0008\0\7\0@\0\35\0\34\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,b\0\0\0\0\0\0,b\0\0\0\0\0\0\0\0
 \0\0\0\0\0\1\0\0\0\6\0\0\0\200g\0\0\0\0\0\0\200g \0\0\0\0\0\200g 
\0\0\0\0\0\250\n\0\0\0\0\0\0X\v\0\0\0\0\0\0\0\0 \0\0\0\0\0\2\0\0\0\6\0\0\0Xm\0\0\0\0\0\0Xm 
\0\0\0\0\0Xm 
\0\0\0\0\0@\2\0\0\0\0\0\0@\2\0\0\0\0\0\0\10\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\310\1\0\0\0\0\0\0\310\1\0\0\0\0\0\0"...,
 832) = 832
3972  1420550767.685654 fstat(7, {st_mode=S_IFREG|0755, st_size=33112, ...}) = 0
3972  1420550767.685724 mmap(NULL, 2126552, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 7, 0) = 
0x7f79607e3000
3972  1420550767.685789 mprotect(0x7f79607ea000, 2093056, PROT_NONE) = 0
3972  1420550767.685849 mmap(0x7f79609e9000, 8192, PROT_READ|PROT_WRITE, 
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 7, 0x6000) = 0x7f79609e9000
3972  1420550767.686058 close(7)        = 0
3972  1420550767.686366 mprotect(0x7f79609e9000, 4096, PROT_READ) = 0
3972  1420550767.687674 open("/usr/lib64/libreoffice/ure/lib/libiolo.so", O_RDONLY|O_CLOEXEC) = 7
3972  1420550767.687786 read(7, 
"\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\"\1\0\0\0\0\0@\0\0\0\0\0\0\0008}\4\0\0\0\0\0\0\0\0\0@\0008\0\7\0@\0\35\0\34\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'\337\3\0\0\0\0\0'\337\3\0\0\0\0\0\0\0
 
\0\0\0\0\0\1\0\0\0\6\0\0\0008\342\3\0\0\0\0\0008\342#\0\0\0\0\0008\342#\0\0\0\0\0\320i\0\0\0\0\0\0\340k\0\0\0\0\0\0\0\0
 \0\0\0\0\0\2\0\0\0\6\0\0\0 =\4\0\0\0\0\0 =$\0\0\0\0\0 
=$\0\0\0\0\0@\2\0\0\0\0\0\0@\2\0\0\0\0\0\0\10\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\310\1\0\0\0\0\0\0\310\1\0\0\0\0\0\0"...,
 832) = 832
3972  1420550767.687863 fstat(7, {st_mode=S_IFREG|0755, st_size=296056, ...}) = 0
3972  1420550767.688029 mmap(NULL, 2379288, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 7, 0) = 
0x7f796059e000
3972  1420550767.688091 mprotect(0x7f79605dc000, 2097152, PROT_NONE) = 0
3972  1420550767.688152 mmap(0x7f79607dc000, 28672, PROT_READ|PROT_WRITE, 
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 7, 0x3e000) = 0x7f79607dc000
3972  1420550767.688305 close(7)        = 0
3972  1420550767.688710 mprotect(0x7f79607dc000, 24576, PROT_READ) = 0
3972  1420550767.689187 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 7
3972  1420550767.689274 fcntl(7, F_GETFD) = 0
3972  1420550767.689318 fcntl(7, F_SETFD, FD_CLOEXEC) = 0
3972  1420550767.689425 open("/etc/resolv.conf", O_RDONLY|O_CLOEXEC) = 8
3972  1420550767.689498 fstat(8, {st_mode=S_IFREG|0644, st_size=72, ...}) = 0
3972  1420550767.689552 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 
0x7f7963236000
3972  1420550767.689610 read(8, "# Generated by NetworkManager\nsearch fritz.box\nnameserver 
192.168.178.1\n", 4096) = 72
3972  1420550767.689676 read(8, "", 4096) = 0
3972  1420550767.689721 close(8)        = 0
3972  1420550767.689904 munmap(0x7f7963236000, 4096) = 0
3972  1420550767.689996 socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 8
3972  1420550767.690053 connect(8, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 
ENOENT (No such file or directory)
3972  1420550767.690146 close(8)        = 0
3972  1420550767.690199 socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 8
3972  1420550767.690269 connect(8, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 
ENOENT (No such file or directory)
3972  1420550767.690332 close(8)        = 0
3972  1420550767.690405 open("/etc/host.conf", O_RDONLY|O_CLOEXEC) = 8
3972  1420550767.690463 fstat(8, {st_mode=S_IFREG|0644, st_size=9, ...}) = 0
3972  1420550767.690511 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 
0x7f7963236000
3972  1420550767.690563 read(8, "multi on\n", 4096) = 9
3972  1420550767.690622 read(8, "", 4096) = 0
3972  1420550767.690664 close(8)        = 0
3972  1420550767.690704 munmap(0x7f7963236000, 4096) = 0
3972  1420550767.690777 futex(0x7f796b65c044, FUTEX_WAKE_PRIVATE, 2147483647) = 0
3972  1420550767.690861 open("/etc/hosts", O_RDONLY|O_CLOEXEC) = 8
3972  1420550767.691016 fstat(8, {st_mode=S_IFREG|0644, st_size=158, ...}) = 0
3972  1420550767.691066 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 
0x7f7963236000
3972  1420550767.691117 read(8, "127.0.0.1   localhost localhost.localdomain localhost4 
localhost4.localdomain4\n::1         localhost localhost.localdomain localhost6 localhost: