> I ktraced some more.  Now Applix is running quite slow - every oldselect()
> call takes around 20...30 ms.  BUT, this time it's clear where that time
> is spent - here's a ktrace of the X server:

made with ktrace -R, right?


>    203 XF86_SVGA 0.000053 CALL  select(0x3f,0x271614,0,0,0xf7bfd908)
>    203 XF86_SVGA 0.000101 RET   select 2
>    203 XF86_SVGA 0.000068 CALL  read(0x15,0x7ec008,0x15d8)
>    203 XF86_SVGA 0.000134 GIO   fd 21 read 52 bytes
>        "J\0     \0\^Z\^A@\^D"\^A@\^D\^B\^B*\^A\^Q\0itsetestaustila, \0T\0\^D\0\
>         #\0\0\0\0\0\0\0\0\0@\^D"
>    203 XF86_SVGA 0.000047 RET   read 52/0x34
>    203 XF86_SVGA 0.000698 CALL  mmap(0,0x22000,0x3,0x1002,0xffffffff,0,0,0)
>    203 XF86_SVGA 0.000159 RET   mmap 286355456/0x11117000 
>    203 XF86_SVGA 0.007421 CALL  munmap(0x11139000,0x22000)
>    203 XF86_SVGA 0.000225 RET   munmap 0
>    203 XF86_SVGA 0.000061 CALL  mmap(0,0x22000,0x3,0x1002,0xffffffff,0,0,0)
>    203 XF86_SVGA 0.000133 RET   mmap 286494720/0x11139000 
>    203 XF86_SVGA 0.007442 CALL  munmap(0x11183000,0x22000)
>    203 XF86_SVGA 0.000230 RET   munmap 0
>    203 XF86_SVGA 0.000061 CALL  mmap(0,0x22000,0x3,0x1002,0xffffffff,0,0,0)
>    203 XF86_SVGA 0.000130 RET   mmap 286797824/0x11183000
>    203 XF86_SVGA 0.007411 CALL  munmap(0x111a5000,0x22000)
>    203 XF86_SVGA 0.000240 RET   munmap 0
>    203 XF86_SVGA 0.000075 CALL  writev(0x15,0xf7bfd930,0x1)
>    203 XF86_SVGA 0.000097 GIO   fd 21 wrote 32 bytes
>        "\^A\M-9\^A5\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\^U\0\0\0\M^Lw5\0"
>    203 XF86_SVGA 0.000354 RET   writev 32/0x20
> 
> The three munmap() calls take over 20 ms!  Why?  It seems that these calls
> are slowing down grtadually.  During the last ktrace of the X server, they
> were taking about 2 ms each.

how do you get this?

>    203 XF86_SVGA 0.000061 CALL  mmap(0,0x22000,0x3,0x1002,0xffffffff,0,0,0)
>    203 XF86_SVGA 0.000133 RET   mmap 286494720/0x11139000
>    203 XF86_SVGA 0.007442 CALL  munmap(0x11183000,0x22000)
>    203 XF86_SVGA 0.000230 RET   munmap 0

is interpreted as (assuming i remember how to do this properly 8-):

0.000061 seconds after the previous event was posted to ktrace, mmap
was called.

0.000133 seconds after mmap was called, it returned.

0.007442 seconds after mmap returned, munmap was called.

0.000230 seconds after munmap was called, it returned.


If the 7.4ms number was really 2ms earlier in the run, sounds like X
is having a hard time dealing with fragmentation (or something) in its
malloc pool, and that it's an X problem.



FWIW, i sanity checked myself with a "more" in which i started up
'more' waited a few seconds, and quit.  that looked like:

  2766 more     0.000036 RET   write 27/0x1b
  2766 more     0.000032 CALL  read(0x3,0xf7bfd6e3,0x1)
  2766 more     3.443546 GIO   fd 3 read 1 bytes
       "q"
  2766 more     0.000062 RET   read 1

which confirms my interpretation.  (3.4 seconds after the 'read' was
issued, data for the read showed up and was copied to user-space.)


chris