Re: Severe performance degradation on Linux

Hey,

On Wed, Jan 7, 2015 at 10:27 AM, Michael Meeks <michael.meeks@collabora.com>
wrote:

> 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,


Ah. I fear that this is a regression introduced through my code. This
sounds a bit like the glxtest codewhich might not work optimally in a
headless setup. I suppose you are using 4-4 or master.

Regards,
Markus