> I wrote
>> I'm working with a company that's trying to use NetBSD for a turnkey
>> product. It works with 9.1; they're trying to move to 10.x [...]
>> Problem is, starting X takes foreeeeever [under 10.1]
> I've now actually tried this for myself.
I have a little more information.
Talking with the people in question, I have managed to reproduce
something like the issue myself.
I booted my test system with a 10.1 kernel and a 9.1 userland. Log in
on the console as root. Then, with scripts
x
#! /bin/sh
exec /usr/X11R7/bin/xinit /usr/X11R7/bin/xterm -fg white -bg black
-geometry 160x50+0+0 -- -retro -cc 3
badx
#! /bin/sh
exec /usr/X11R7/bin/xinit /usr/X11R7/bin/xterm -fg white -bg black
-geometry 160x50+0+0 -- -retro -tst -depth 8 -cc 3
I find
# ./x
X comes up and xterm starts, so fast I have trouble seeing any
delay. There's enough flicker there's probably at least one
video frame of delay, but I'd be surprised if the delay reaches
200ms.
# ./badx
Server starts fast, but it takes approximately 3 seconds from
then until xterm's window shows up.
I tried the same scripts under a 9.1 kernel; then, each script started
fast, fast enough I coudn't perceive any time delay. I speculate that
the reason I saw only 3 seconds of delay whereas they saw tens of
seconds is that I don't quite have the same hardware they do, but that
*is* speculation; I'm far from certain.
I ran each script under ktrace -i. Looking at the X server portions of
the traces, with the PIDs stripped off and diffing the results, I see
numerous small differences due to the stack being shifted by the extra
command-line args, things like
-X CALL open(0x7f7fffffe138,0,0)
+X CALL open(0x7f7fffffe158,0,0)
By changing the size of the environment (a junk environment variable
with a carefully-chosen length), I was able to make these go away.
(Oh, and, I had to set security.pax.aslr.enabled to 0 or I got a whole
lot more address diffs, of course.)
But the diffs are not very helpful. There are a lot of _lwp_self
calls, which of course return different values. And then there's a big
diff hunk (@@ -21889,1642 +21865,2866 @@) which begins with
@@ -21889,1642 +21865,2866 @@
X CALL read(5,0x7f7ff7b2f8c0,0x4000)
X GIO fd 5 read 0 bytes
X RET read 0
-X CALL
mmap(0,0x51000,PROT_READ|PROT_WRITE,0x1002<PRIVATE,ANONYMOUS,ALIGN=NONE>,0xffffffff,0,0)
-X RET mmap 140187589292032/0x7f7ff7763000
-X CALL ioctl(0xe,DRM_IOCTL_I915_GEM_CREATE,0x7f7fffffe600)
+X CALL _lwp_self
+X RET _lwp_self 651/0x28b
+X CALL __sigprocmask14(1,0x7f7fffffe120,0x7f7fffffe170)
+X RET __sigprocmask14 0
+X CALL open(0x7f7fffffe200,0,6)
+X NAMI "/usr/X11R7/lib/modules/dri/i965_dri.so"
+X RET open 16/0x10
+X CALL __fstat50(0x10,0x7f7fffffde28)
+X RET __fstat50 0
[158 more + lines]
+X CALL open(0x7f7fffffd1a0,0x400000,0x3a)
+X NAMI "/usr/share/nls/C/libc.cat"
+X RET open 16/0x10
+X CALL __fstat50(0x10,0x7f7fffffcce0)
+X RET __fstat50 0
+X CALL mmap(0,0x10be,PROT_READ,0x1<SHARED,FILE,ALIGN=NONE>,0x10,0,0)
+X RET mmap 140187589328896/0x7f7ff776c000
+X CALL close(0x10)
+X RET close 0
+X CALL munmap(0x7f7ff776c000,0x10be)
+X RET munmap 0
+X CALL issetugid
+X RET issetugid 0
+X CALL ioctl(0xe,DRM_IOCTL_I915_GETPARAM,0x7f7fffffdb20)
X GIO fd 14 wrote 16 bytes
X GIO fd 14 read 16 bytes
X RET ioctl 0
-X CALL ioctl(0xe,DRM_IOCTL_I915_GEM_SET_TILING,0x7f7fffffe500)
+X CALL ioctl(0xe,DRM_IOCTL_I915_GEM_CONTEXT_GETPARAM,0x7f7fffffdae0)
+X GIO fd 14 wrote 24 bytes
+X GIO fd 14 read 24 bytes
+X RET ioctl 0
+X CALL ioctl(0xe,DRM_IOCTL_I915_GETPARAM,0x7f7fffffdae0)
X GIO fd 14 wrote 16 bytes
X GIO fd 14 read 16 bytes
X RET ioctl 0
-X CALL
mmap(0,0x21000,PROT_READ|PROT_WRITE,0x1002<PRIVATE,ANONYMOUS,ALIGN=NONE>,0xffffffff,0,0)
-X RET mmap 140187589156864/0x7f7ff7742000
-X CALL ioctl(0xe,DRM_IOCTL_I915_GEM_CREATE,0x7f7fffffe600)
+X CALL ioctl(0xe,DRM_IOCTL_I915_GETPARAM,0x7f7fffffdae0)
X GIO fd 14 wrote 16 bytes
[lots more lines]
None of the syscalls in the `bad' run took very long. Using kdump -R
and sorting by elapsed time, the longest 16 times are
544 549 X 0.296895070 RET poll 1
544 544 X 0.243910223 RET ioctl 0
544 549 X 0.109929501 RET poll 1
544 549 X 0.039969679 RET poll 1
544 544 X 0.039901056 CALL
mmap(0,0xb000,PROT_READ|PROT_WRITE,0x1002<PRIVATE,ANONYMOUS,ALIGN=NONE>,0xffffffff,0,0)
544 549 X 0.036890455 RET poll 1
544 549 X 0.036889406 RET poll 1
544 544 X 0.029997974 RET poll 0
544 544 X 0.029997673 RET poll 0
544 544 X 0.029996880 RET poll 0
544 544 X 0.029996210 RET poll 0
544 549 X 0.026892913 RET poll 1
544 544 X 0.019547689 RET poll 0
544 544 X 0.016640645 GIO fd 14 read 32 bytes
544 544 X 0.016640250 GIO fd 14 read 32 bytes
544 544 X 0.016640244 GIO fd 14 read 32 bytes
which doesn't look very helpful to me. Adding up all 16 of those gives
barely over one second...and, without some idea what they're poll()ing
for, which ktrace doesn't seem to record, I'm not sure where to go from
here. The slow ioctl (the second line quoted above) is KDSETMODE, in
case that says anything to anyone.
Interestingly, none of the syscalls took very long - even though after
X started I still had to type "exit", which I would expect would
involve some relatively long delays.
Running the commands manually with different args, I find that -retro
-tst -depth 8 -cc 3 is slow but -retro -tst -cc 3 is fast. I'd
speculate that switching the hardware from one depth to another is slow
under 10.1 for some reason, except that the root weave and cursor come
up fast, and I'd expect that to happen only after the hardware has been
configured.
/~\ The ASCII Mouse
\ / Ribbon Campaign
X Against HTML [email protected]
/ \ Email! 7D C8 61 52 5D E7 2D 39 4E F1 31 3E E8 B3 27 4B
