Re: Severe performance degradation on Linux

Hi Maarten,

On Wed, 2015-01-07 at 09:21 +0100, Maarten Hoes wrote:
> Two more things I noticed, though again Im not sure how relevant those
> are, it's probably nothing :

        So the thing you're looking for looks often like this:

3986  1420550762.879658 poll([{fd=6, events=POLLIN}], 1, 4294967295 <unfinished ...>
3986  1420550767.916824 <... poll resumed> ) = 1 ([{fd=6, revents=POLLIN}])

        Which is from your log; the poll that timed out just before it is
~irrelevant we tend to do a zero timeout (non-blocking) poll before we
do a blocking one for one reason and another - ignore that.

        The question is - what is this fd 6 we are polling on - I searched
backwards in your log for ') = 6$' and got:
>
3986  1420550762.752026 
open("/home/buildslave/source/libo-core/instdir/program/../program/bootstraprc", O_RDONLY|O_EXCL 
<unfinished ...>
3986  1420550762.752085 <... open resumed> ) = 6

        Which is nonsense - since we immediately close that fd again. So then I
looked for socket = and pipe:

3986  1420550762.753764 pipe( <unfinished ...>
3986  1420550762.753808 <... pipe resumed> [6, 7]) = 0

        Which seems to be in this context:

3986  1420550762.753207 lstat("/home/buildslave/source/libo-core/instdir/program", 
{st_mode=S_IFDIR|0775, st_size=20480, ...}) = 0
3986  1420550762.753235 lstat("/home/buildslave/source/libo-core/instdir/program/libvcllo.so", 
{st_mode=S_IFREG|0775, st_size=8609416, ...}) = 0
3986  1420550762.753259 futex(0x7f160b8d50c8, FUTEX_WAKE_PRIVATE, 2147483647 <unfinished ...>
3986  1420550762.753285 <... futex resumed> ) = 0
3986  1420550762.753764 pipe( <unfinished ...>
3986  1420550762.753808 <... pipe resumed> [6, 7]) = 0
3986  1420550762.753829 fcntl(6, F_GETFD) = 0
3986  1420550762.753867 fcntl(6, F_SETFD, FD_CLOEXEC) = 0
3986  1420550762.753885 fcntl(7, F_GETFD <unfinished ...>
3986  1420550762.753930 <... fcntl resumed> ) = 0
3986  1420550762.753945 fcntl(7, F_SETFD, FD_CLOEXEC) = 0
3986  1420550762.753978 fcntl(6, F_GETFL) = 0 (flags O_RDONLY)
3986  1420550762.754003 fcntl(6, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
3986  1420550762.754028 fcntl(7, F_GETFL) = 0x1 (flags O_WRONLY)
3986  1420550762.754038 fcntl(7, F_SETFL, O_WRONLY|O_NONBLOCK <unfinished ...>

        Which looks like a reasonably normal pipe setup - but - I wonder what
it's for =) I imagine to communicate with:

3986  1420550762.809356 clone(child_stack=0x7f15f2372eb0, 
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID,
 parent_tidptr=0x7f15f23739d0, tls=0x7f15f2373700, child_tidptr=0x7f15f23739d0) = 3989

        Whatever is 'execve'd from that fork - unfortunately I don't see the -f
strace output there - to be able to follow that. Something (prolly vcl)
spawns something - and we block for 5 seconds on the output of that.

        But of course it could be the 'headless' main-loop pipe.

        Anyhow - hopefully that gives some pointers that you can puzzle through
& try to trace / chase down what's going wrong for you.

        ATB,

                Michael.        

-- 
 michael.meeks@collabora.com  <><, Pseudo Engineer, itinerant idiot