Could you provide an strace -tt of the login. I think the problem is
probably caused by pango initialising its font cache.

i have found a second bonobo-activation-server (but the correct one
was running); removing it seems to have shortened login times on
remote machines to about 60 seconds. (F*cking FreeBSD port system, i
already have written two perl scripts to overcome it's shortages)
I'd like to do a "strace", i have already tried - but "strace"
disappeared while running... seems like it's b0rked on FreeBSD 4.3
right now... i should ask the main administrator to upgrade to FreeBSD 5.x
I don't think it's pangos fault; pango shouldn't be involved when
pressing the logout button.
BTW: the logout button worked instantly today on a remote X11 login,
but took over a minute on the local display.

The startup time is _very_ display-dependant.
This machine has up to five displays, one local, four remote.
While the login on a remote display running XF 4.2.something with the
vesa driver was just around 15 seconds (with AA enabled), the login on
the machine itself (running 4.2.0) still takes up to 2 minutes.
The remote machine has only the "fixed" font local, all other fonts
are loaded from the main machine via x font service.
Should i try to use the font server for the local display as well?

Please don't just put this bug on "needinfo" and ignore it, but help
me finding out what is causing the delay.

Erich: this isn't a support line, so I'm leaving it as NEEDINFO,
because there is not enough information here so that someone could
actually fix the bug, if there is a bug ..

Does this machine use Xft/fontconfig. If it does fontconfig may be
trying to initialise its fonr information cache. I really can't tell
without an strace of what gnome-session is doing as it starts up ...

Can't you just tell me what it is supposed to be doing after
displaying the splash screen and before drawing the first icon (or
printing any other verbose message to the console?)
So i could find it myself.

FreeBSD seems to have no fontconfig support.
Neither with nor without Xft makes any difference.
How would i initialize the fontconfig font cache?

Okay Erich. I really cannot determine if there is a bug here without
some cold hard facts ....

Basically, I need to know *what* is the bottleneck here. I can't just
guess that. There are numerous potential bottlenecks with GNOME's
startup ... I'm suspecting it may be related to Pango/Xft because
that's one area of major change in GNOME lately ...

You haven't even told me what version of gnome-session and the various
GNOME libraries you are using ...

But again, I need some cold hard data on what is happening during
those 120 seconds.

Created attachment 11268 [details]
Strace -tt of login

Seems like my last posting here got lost... :-(  
Here again the list of installed versions:  
  
gnomecanvas-0.18.0  
gnomecontrolcenter2-2.0.1.1  
gnomedb-0.2.96_1  
gnomedesktop-2.0.8  
gnomemimedata-2.0.1_1  
gnomepanel-2.0.9  
gnomesession-2.0.7  
gnometerminal-2.0.1  
gnomeutils2-2.0.5,1  
gnomevfs2-2.0.4  
libgnome-2.0.5  
libgnomecanvas-2.0.4  
libgnomeprint-1.116.1  
libgnomeprintui-1.116.0  
libgnomeui-2.0.5  
pango-1.0.4  
gtk-2.0.6  
  
attached a "strace -tt gnome-session" showing the delay  
11:02:26.730110 poll([{fd=3, events=POLLRDNORM}, {fd=6,  
events=POLLIN}, {fd=10, events=POLLIN|POLLPRI}, {fd=11,  
events=POLLIN|POLLPRI}, {fd=12,  
 events=POLLIN|POLLPRI}, {fd=14, events=POLLIN|POLLPRI,  
revents=POLLIN}, {fd=15, events=POLLIN|POLLPRI}, {fd=16,  
events=POLLIN|POLLPRI}, {fd=17  
, events=POLLIN|POLLPRI}], 9, INFTIM) = 1  
11:03:43.331804 gettimeofday({1033031023, 331912}, NULL) = 0  
  

Same kind of delay also occurs on pressing the logout button; i can 
re-upload the strace if you want to see that, too. (75 sec this 
time) 
 
[nothing due to my inactivity writing the previous report on a 
different screen] 
11:09:57.955693 gettimeofday({1033031397, 955801}, NULL) = 0 
11:09:57.958683 ioctl(5, FIONREAD, [32]) = 0 
11:09:57.959247 read(5, 
"n\2\262\1B2x\205\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 32) = 
32 
11:09:57.959828 ioctl(5, FIONREAD, [0]) = 0 
11:09:57.960359 poll([{fd=5, events=POLLIN}, {fd=8, events=POLLIN}, 
{fd=10, events=POLLIN|POLLPRI}, {fd=11, events=POLLIN|POLLPRI}, 
{fd=12, eve 
nts=POLLIN|POLLPRI}, {fd=14, events=POLLIN|POLLPRI}, {fd=15, 
events=POLLIN|POLLPRI}, {fd=18, events=POLLIN|POLLPRI}, {fd=19, 
events=POLLIN|POLL 
PRI}, {fd=16, events=POLLIN|POLLPRI}, {fd=17, 
events=POLLIN|POLLPRI}, {fd=20, events=POLLIN|POLLPRI}, {fd=21, 
events=POLLIN|POLLPRI}, {fd=22, e 
vents=POLLIN|POLLPRI}, {fd=13, events=POLLIN}], 15, 0) = 0 
11:09:57.961047 poll([{fd=5, events=POLLIN}, {fd=8, events=POLLIN}, 
{fd=10, events=POLLIN|POLLPRI}, {fd=11, events=POLLIN|POLLPRI}, 
{fd=12, eve 
nts=POLLIN|POLLPRI}, {fd=14, events=POLLIN|POLLPRI}, {fd=15, 
events=POLLIN|POLLPRI}, {fd=18, events=POLLIN|POLLPRI}, {fd=19, 
events=POLLIN|POLL 
PRI}, {fd=16, events=POLLIN|POLLPRI}, {fd=17, 
events=POLLIN|POLLPRI}, {fd=20, events=POLLIN|POLLPRI}, {fd=21, 
events=POLLIN|POLLPRI}, {fd=22, e 
vents=POLLIN|POLLPRI}, {fd=13, events=POLLIN}], 15, 0) = 0 
11:09:57.961710 poll([{fd=3, events=POLLRDNORM}, {fd=5, 
events=POLLIN}, {fd=8, events=POLLIN}, {fd=10, 
events=POLLIN|POLLPRI}, {fd=11, events=P 
OLLIN|POLLPRI}, {fd=12, events=POLLIN|POLLPRI}, {fd=14, 
events=POLLIN|POLLPRI}, {fd=15, events=POLLIN|POLLPRI}, {fd=18, 
events=POLLIN|POLLPRI}, 
 {fd=19, events=POLLIN|POLLPRI}, {fd=16, events=POLLIN|POLLPRI}, 
{fd=17, events=POLLIN|POLLPRI}, {fd=20, events=POLLIN|POLLPRI, 
revents=POLLIN} 
, {fd=21, events=POLLIN|POLLPRI}, {fd=22, events=POLLIN|POLLPRI}, 
{fd=13, events=POLLIN}], 16, INFTIM) = 1 
11:11:12.951483 gettimeofday({1033031472, 951595}, NULL) = 0 
11:11:12.963264 read(20, "\1\4\1\0\1\0\0\0", 8) = 8 
11:11:12.964142 read(20, "\0\1\2\0\1\320\320\320", 8) = 8 
11:11:12.964642 write(18, "\1\3\0\1\1\0\0\0\0\1\2\0001181", 16) = 16 
11:11:12.965403 write(16, "\1\3\0\1\1\0\0\0\0\1\2\0001181", 16) = 16 
[...] 
 

Thanks for the straces. We can start to figure out where the
bottleneck is ... The one that really concerns me is:

11:02:26.544581 writev(14, [{"GIOP\1\2\1\0\354\0\0\0", 12},
{"t\357\277\277\1\0\0\0\0\0\0\0\34\0\0\0\0\0\0\0\357\244"..., 236}],
2) = 248
11:02:26.728829 poll([{fd=6, events=POLLIN}, {fd=10,
events=POLLIN|POLLPRI}, {fd=11, events=POLLIN|POLLPRI}, {fd=12,
events=POLLIN|POLLPRI}, {fd=14, events=POLLIN|POLLPRI}, {fd=15,
events=POLLIN|POLLPRI}, {fd=16, events=POLLIN|POLLPRI}, {fd=17,
events=POLLIN|POLLPRI}], 8, 0) = 0
11:02:26.729453 poll([{fd=6, events=POLLIN}, {fd=10,
events=POLLIN|POLLPRI}, {fd=11, events=POLLIN|POLLPRI}, {fd=12,
events=POLLIN|POLLPRI}, {fd=14, events=POLLIN|POLLPRI}, {fd=15,
events=POLLIN|POLLPRI}, {fd=16, events=POLLIN|POLLPRI}, {fd=17,
events=POLLIN|POLLPRI}], 8, 0) = 0
11:02:26.730110 poll([{fd=3, events=POLLRDNORM}, {fd=6,
events=POLLIN}, {fd=10, events=POLLIN|POLLPRI}, {fd=11,
events=POLLIN|POLLPRI}, {fd=12, events=POLLIN|POLLPRI}, {fd=14,
events=POLLIN|POLLPRI, revents=POLLIN}, {fd=15,
events=POLLIN|POLLPRI}, {fd=16, events=POLLIN|POLLPRI}, {fd=17,
events=POLLIN|POLLPRI}], 9, INFTIM) = 111:03:43.331804
gettimeofday({1033031023, 331912}, NULL) = 0
11:03:43.332430 read(14, "GIOP\1\2\1\1\234\1\0\0", 12) = 12
11:03:43.332936 read(14,
"t\357\277\277\0\0\0\0\1\0\0\0\1\0\0\0\f\0\0\0\1\1\1\1\1"..., 412) = 412



This is come CORBA comms going on. See it writes a GIOP message on fd
14, polls and over a minute later reads the response. So we need to
identify with what gnome-session is communicating here.

If you comile ORBit2 with --enable-debug and set 
 ORBIT2_DEBUG=traces:timings, you will get a trace of all the CORBA
methods being called ....

the relvant part on login: 
 
p14742 1033486855.457768 : 
([0x8098740])->report_activation_succeeded ({ 'OAFAID 
:[OAFIID:Bonobo_Moniker_std_Factory,erich,byron,session]', { d=1 
v=seq[3]={ 'OAF 
IID:Bonobo_Moniker_Oaf', 'OAFIID:Bonobo_Moniker_std_Factory', 
'/usr/local/lib/bo 
nobo/monikers/libmoniker_std_2.so' } } })p14742 1033486855.464538 : 
([0x80b2c00] 
)->setName ('OAFIID:GNOME_SettingsDaemon') 1033486855.464838 
 1033486855.465129 
p14742 1033486855.557784 : ([0x80b2e00])->setName 
('OAFIID:GNOME_SettingsDaemon' 
, ) 1033486855.558987 
 1033486855.559851 
p14742 1033486855.560420 : ([0x817e0c0])->resolve ({ 0xbfbff49c, 
0x8097040 }, 'I 
DL:Bonobo/Unknown:1.0') 1033486855.561265 
p14742 1033486855.562151 : ([0x80b2e00])->resolve ({ 0xbfbff49c, 
0x8097040 }, 'I 
DL:Bonobo/Unknown:1.0', )p14742 1033486855.564242 : 
([0x8098540])->activate_from 
_id ('OAFIID:GNOME_SettingsDaemon', 0x0) context { ( username: 
'erich' ), ( host 
name: 'byron' ), ( domain: 'user' ), ( display: ':0.0' ) } =>: { 
'OAFAID:[OAFIID 
:GNOME_SettingsDaemon,erich,byron,session]', { d=0 v=[0x817e200] } } 
1033486933. 
115649 
p14742 1033486933.116275 : ([0x817e200])->queryInterface 
('IDL:Bonobo/Unknown:1. 
0') =>: [0x817e200] 1033486933.144318 
p14742 1033486933.145000 : ([0x817e200])->unref () 1033486933.152096 
 =>; [0x817e200] 1033486933.153188 
 =>: [0x817e240] 1033486933.169951 
 
 
 
the delay on logout: 
 
p14803 1033486950.627434 : ([0x80d9d00])->set 
('/apps/panel/profiles/default/ ... 1120245235k3217026448/panel_id', 
{ d=2 v='929394689' }) 1033486950.629016 
p14803 1033486950.629166 : ([0x80d9d00])->sync () 1033486950.631254 
p14803 1033486950.631531 : ([0x80d9d00])->sync () 1033486950.854909 
p14803 1033487025.923267 : ([0x80d9d00])->lookup_with_schema_name 
('/apps/panel/profiles/default/general/panel_id_list', 'C', 1, ) =>: 
{ d=6 v={ seq[2]={ { d=2 v='929394689' }, { d=2 v='850747393' } }, 2 
} } out: ('/schemas/apps/panel/default_p ... 
s/medium/general/panel_id_list', 0, 1 ) 1033487025.929324 
p14803 1033487025.929795 : ([0x80d9d00])->set 
('/apps/panel/profiles/default/panels/929394689/panel_type', { d=2 
v='aligned-panel' }) 1033487025.934599 
 

Created attachment 11338 [details]
orbit debug output with timings

Okay, so from this:

1033486855.564242 : ([0x8098540])->activate_from_id
('OAFIID:GNOME_SettingsDaemon', 0x0) .... =>: { 
'OAFAID:[OAFIID:GNOME_SettingsDaemon,erich,byron,session ...} 
1033486933.115649 

We can see that gnome-settings-daemon startup is taking nearly 80
seconds. Moving to gnome-control-center ....


Erich could you login to a failsafe session and just do a strace -tt
gnome-settings-daemon and attach it here ? Thanks.

Created attachment 11345 [details]
Strace -tt of gnome-settings-daemon

Erich: that attachment is corrupt :/

the previous log has been done on a Xnest server started over ssh...

here's the relevant snippet again:

23:42:53.443312 access("/tmp/.esd/socket", R_OK|W_OK) = -1 ENOENT (No
such file or directory)
23:42:53.443970 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 15
23:42:53.444361 fcntl(15, F_GETFL)      = 0x2 (flags O_RDWR)
23:42:53.444708 fcntl(15, F_SETFL, O_RDWR|O_NONBLOCK) = 0
23:42:53.445228 fcntl(15, F_SETFD, FD_CLOEXEC) = 0
23:42:53.445707 setsockopt(15, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
23:42:53.446272 connect(15, {sin_family=AF_INET,
sin_port=htons(16001), sin_addr=inet_addr("127.0.0.1")}}, 16) = -1
EINPROGRESS (Operation now in progress)
23:42:53.446879 poll([{fd=15, events=POLLOUT}], 1, 0) = 0
23:42:53.447371 poll([{fd=3, events=POLLRDNORM}, {fd=15,
events=POLLOUT, revents=POLLOUT}], 2, INFTIM) = 1
23:44:08.441000 gettimeofday({1033508648, 441149}, NULL) = 0
23:44:08.441639 getpeername(15, 0xbfbff408, [16]) = -1 ENOTCONN
(Socket is not connected)
23:44:08.442040 getsockopt(15, SOL_SOCKET, SO_ERROR, [60], [4]) = 0
23:44:08.442638 fstat(15, {st_mode=S_IFSOCK, st_size=0, ...}) = 0
23:44:08.443071 close(15)               = 0
23:44:08.443655 open("/usr/local/etc/esd.conf", O_RDONLY) = 15

well, i actually can't believe it's an esd problem to localhost...
i'll try enabling esd (although the machine has no sound hardware...)

The previous lines for fd=3 are:

23:42:52.459451 poll([{fd=3, events=POLLRDNORM}, {fd=15,
events=POLLRDNORM, revents=POLLRDNORM|POLLHUP}], 2, INFTIM) = 1
[...]
<some childs terminated>
23:42:52.680241 <... poll resumed> [{fd=3, events=POLLRDNORM}], 1,
INFTIM) = -1 EINTR (Interrupted system call)
23:42:52.680702 write(4, "\24", 1)      = 1
23:42:52.681276 sigreturn(0x8069e7c)    = -1 EINTR (Interrupted system
call)
23:42:52.681602 read(3, "\24", 128)     = 1
23:42:52.681987 read(3, 0x805fed8, 128) = -1 EAGAIN (Resource
temporarily unavailable)

fd 3 was created as a pipe with fd 4. (the first i found in the
strace) - i didn't find any other communication going on except this
"\24" exchange.

sorry, i gave the wrong mime type for the attachment...
i gzip'ed the strace... should i attach it again?

Okay what I'm seeing in this is lots of this:

23:44:09.830721 writev(5,
[{"\7\6\2\0\7\6\3\0\7\5\4\0\7\5\4\0\t\7\7\0\5\6\6\0\17!\""...,
57368}], 1) = -1 EAGAIN (Resource temporarily unavailable)
23:44:09.831277 poll([{fd=5, events=POLLIN|POLLOUT}], 1, 0) = 0
23:44:09.831778 poll([{fd=5, events=POLLIN|POLLOUT}], 1, 0) = 0
23:44:09.832252 poll([{fd=3, events=POLLRDNORM}, {fd=5,
events=POLLIN|POLLOUT, revents=POLLOUT}], 2, INFTIM) = 1
23:44:15.795562 gettimeofday({1033508655, 795668}, NULL) = 0
23:44:15.796055 writev(5,
[{"\7\6\2\0\7\6\3\0\7\5\4\0\7\5\4\0\t\7\7\0\5\6\6\0\17!\""...,
57368}], 1) = 8192


Where fd=5 is your Xserver. Basically gnome-settings-daemon is pumping
data to your Xserver, the socket buffer is filling up and g-s-d then
blocks until the buffer has cleared again.

I notice this just before it:

23:44:09.759523 writev(5,
[{"7\0\5\0\3\0@\0\1\0`\0\0\0\1\0\0\0\0\0bA\4\0\6\0US", 28}, {"RENDER",
6}, {"\0\0", 2}], 3) = 36

I assume this is a qeuery to see if the the Xserver has the RENDER
extension. Does it ?

Again, I'm beggining to suspect font initialisation here. But I'm not
fully sure what Pango does when Xft isn't available or what Xft does
when RENDER isn't available.

cc-ing Owen - he may be able to shed some light.

No, the Xnest server hasn't got the render extension.
At some point it loads my background image, a fullscreen jpeg - that
could be the data it is pushing to the xserver. I'll try to remove the
background tomorrow and see if the log get's easier to understand.

The lines you quoted were already _past_ the delay, which was from
23:42:53 - 23:44:08
should i try strace with fork monitoring?

There's some other weird stuff going on:
$ gconftool --get "/desktop/gnome/sound/enable_esd"
false

why is gnome-settings-daemon then trying to access esd?

First thing to check is DNS configuration ... that's the
typical reason for slow logins. If it is trying to look
up the machines hostname, and the first DNS server times
out, then you'll see glacial performance. (It may sound
obvious, but as I said, this is the most common reason
for login speed problems.)

Then try "export GDK_USE_XFT=1" before logging in. You
almost certainly have Xft on FreeBSD, so trying the session
both with and without XFT will show you whether it has
anything to do with fonts or not, since they involve
completely different code paths.

My guess is it is more likely to be a bonobo-activation
problem of some sort. (Fonts definitely won't affect
log*out* speed)

owen: you've lost me.  What does any of this have to do with 'log*out*'

Far above, there is a comment:

> BTW: the logout button worked instantly today on a remote X11 login,
> but took over a minute on the local display.

the delay on logout is also included in the first strace log. 
i even added a comment about it ;)  2002-09-26 05:18 

I tried with and without GDK_USE_XFT before, it didn't make a 
difference. 
I know about this typical DNS problem, but gnome1 worked just fine 
and i'm pretty sure that DNS is working (and i think there was some 
check added for this typical problem, at least in gnome 
1.4.something). In fact the machine itself is the master DNS server 
for this small subdomain at the university (including the remote 
displays where the delay at login and logout doesn't occur). 

One more thing on the logout issue: 
I think it was on the first click only; so if i press the logout 
button, wait these 90 seconds, then cancel logout, then click the 
button again the confirmation dialog will pop up immediately. 

Since todays upgrade of bonobo-activation (to 1.0.4) the login seems 
to take forever... Both local and remote... No process uses the CPUs 
much, but the splash screen still is empty. 
Running processes: gnome-smproxy, gnome-settings-daemon, 
bonobo-activation-server, gconfd-2, gnome-session 
 
I'll check if the strace still fails at the same time; but the 
"result" (i.e. the point where it "hangs") is the same... 

It looks like some ORBit Problem... 
  
[pid 91866] 18:02:14.982124 connect(18, {sin_family=AF_UNIX,  
path="/tmp/.ICE-unix/91841"}, 22) = 0  
[pid 91866] 18:02:14.983104 fcntl(18, F_SETFD, FD_CLOEXEC) = 0  
[pid 91866] 18:02:14.983817 write(18, "\0\1\0\320\0\0\0\0", 8) = 8  
[pid 91866] 18:02:14.984561 read(18, 0x808f800, 8) = -1 EAGAIN  
(Resource temporarily unavailable)  
[pid 91866] 18:02:14.985601 poll([{fd=18, events=POLLRDNORM}], 1, 0)  
= 0  
[pid 91866] 18:02:14.986222 poll( <unfinished ...>  
 
 
91841 is the PID of gnome-session. 
The last things gnome-session did: 
 
[pid 91841] 18:02:11.778517 writev(14, [{"GIOP\1\2\1\0\354\0\0\0", 
12}, {"\370\3 
56\277\277\1\0\0\0\0\0\0\0\34\0\0\0\0\0\0\0\362\236"..., 236}], 2 
<unfinished ...> 
[pid 91841] 18:02:11.781309 <... writev resumed> ) = 248 
[pid 91841] 18:02:11.783077 poll( <unfinished ...> 
 
the file descriptor 14 is 
[pid 91841] 18:02:07.223694 connect(14, {sin_family=AF_UNIX, 
path="/tmp/orbit-erich/linc-166cf-0-986f39926ae2"}, 44) = 0 
 
That is bonobo-activation-server sitting on the other end; 
waiting for the pipe opened to a forked child (which never did 
anything...) 
I'll attach an excerpt from that strace -ff -tt. 
 
I'm still waiting for the login - about 17 Minutes now... 

Created attachment 11917 [details]
Excerpt from the strace, forking and sleeping bonobo-activation-server

Presumably this bug applies to 2.1.x too? If so please add GNOME2.1.x
keyword.

Erich: this last bug is unrelated to the original report. Update
gnome-control-center and it will be fixed.

Any chance of an update here? Is the problem still there?

I'm not adminstrating/using the affected machine any more. I'm pretty
sure the problem still exists, but i don't think anything was updated
on the machine since... AFAIK there have been plans to reinstall it,
and i believe the (a little outdated) FreeBSD is to blame.
Feel free to close the bug (perhaps "NOTGNOME").

I'm going to close this because a) we don't know if it even still
happens, and b) without you administrating the machine there is no way
of getting more information on it.