bug#74311: Long startup time on windows (with simple fix)

["Vladimir Šironja" <vladimir.sironja@gmail.com>]

Hello Eli,

sorry, didn't quite understand which bugs should be separated, please
advice again,

1) regarding netlogon, I do not really have an option disconnecting from DC

2) I have added a counter in line 695 like this:

 685   static BOOL WINAPI
  686   lookup_account_sid (LPCTSTR lpSystemName,
  687                       PSID Sid,
  688                       LPTSTR Name,
  689                       LPDWORD cbName,
  690                       LPTSTR DomainName,
  691                       LPDWORD cbDomainName,
  692                       PSID_NAME_USE peUse)
  693   {
  694     static struct lookup_account_sid_cache cache = { 0, NULL, NULL, 0 };
  695     static unsigned been_here_count = 0;
  696
  697     ++been_here_count;
  698
  699     static LookupAccountSid_Proc s_pfn_Lookup_Account_Sid = NULL;
  700     HMODULE hm_advapi32 = NULL;
  701     if (is_windows_9x () == TRUE)

Here the debugger session:

(gdb) b w32.c:701
Breakpoint 1 at 0x40031a8e0: file w32.c, line 701.
(gdb) run
Starting program: C:\Development\emacs-emacs-29.4\src\emacs.exe
[New Thread 20812.0x73b4]
[New Thread 20812.0x7bbc]
[New Thread 20812.0x60fc]

Thread 1 hit Breakpoint 1, lookup_account_sid (lpSystemName=0x0,
Sid=0x3e714b0, Name=0xbfe850 "└o\021", cbName=0xbfe32c,
DomainName=0xbfe330 "b", cbDomainName=0xbfe328, peUse=0xbfe314) at
w32.c:701
701       HMODULE hm_advapi32 = NULL;
(gdb) bt
#0  lookup_account_sid (lpSystemName=0x0, Sid=0x3e714b0, Name=0xbfe850
"└o\021", cbName=0xbfe32c, DomainName=0xbfe330 "b",
cbDomainName=0xbfe328, peUse=0xbfe314) at w32.c:701
#1  0x00007ff79378d364 in init_user_info () at w32.c:2314
#2  0x00007ff79378f2fe in init_environment (argv=0x26015b0) at w32.c:3233
#3  0x00007ff7935a93de in main (argc=1, argv=0x26015b0) at emacs.c:2120
(gdb) continue
Continuing.

Thread 1 hit Breakpoint 1, lookup_account_sid (lpSystemName=0x0,
Sid=0x3e714a8, Name=0xbfe740 "XDړ\001", cbName=0xbfe320,
DomainName=0x0, cbDomainName=0xbfe328, peUse=0xbfe314) at w32.c:701
701       HMODULE hm_advapi32 = NULL;
(gdb) bt
#0  lookup_account_sid (lpSystemName=0x0, Sid=0x3e714a8, Name=0xbfe740
"XDړ\001", cbName=0xbfe320, DomainName=0x0, cbDomainName=0xbfe328,
peUse=0xbfe314) at w32.c:701
#1  0x00007ff79378d50c in init_user_info () at w32.c:2354
#2  0x00007ff79378f2fe in init_environment (argv=0x26015b0) at w32.c:3233
#3  0x00007ff7935a93de in main (argc=1, argv=0x26015b0) at emacs.c:2120
(gdb) info locals
cache = {ret = 1, Name = 0x2606560 "Vladimir.Sironja", DomainName =
0x26065b0 "EDGE", peUse = SidTypeUser}
been_here_count = 2
s_pfn_Lookup_Account_Sid = 0x7ff9e0d9bc20 <LookupAccountSidA>
hm_advapi32 = 0x7ff9e0d50000
ret = 5
(gdb) continue
Continuing.
[New Thread 20812.0x4594]

Thread 1 hit Breakpoint 1, lookup_account_sid (lpSystemName=0x0,
Sid=0x1242d4, Name=0xbfdb30 "\220\\q̨\177", cbName=0xbfdb2c,
DomainName=0xbfd720 "P3\022", cbDomainName=0xbfd71c, peUse=0xbfdc38)
    at w32.c:701
701       HMODULE hm_advapi32 = NULL;
(gdb) bt
#0  lookup_account_sid (lpSystemName=0x0, Sid=0x1242d4, Name=0xbfdb30
"\220\\q̨\177", cbName=0xbfdb2c, DomainName=0xbfd720 "P3\022",
cbDomainName=0xbfd71c, peUse=0xbfdc38) at w32.c:701
#1  0x00007ff793792fa6 in get_name_and_id (psd=0x1242c0, id=0xbfeac0,
nm=0xbfeaf0 "ñ9Þ\003", what=1) at w32.c:5230
#2  0x00007ff79379308b in get_file_owner_and_group (psd=0x1242c0,
st=0xbfeab0) at w32.c:5256
#3  0x00007ff79379379f in stat_worker (path=0x7ff793da0043
<shortname+3> "Development\\emacs-emacs-29.4\\src\\", buf=0xbfeab0,
follow_symlinks=0) at w32.c:5504
#4  0x00007ff793794217 in fstatat (fd=-3041965, name=0x3e7d408
"c:/Development/emacs-emacs-29.4/src/", st=0xbfeab0, flags=4096) at
w32.c:5751
#5  0x00007ff7935d7b79 in emacs_fstatat (dirfd=-3041965,
filename=0x3e7d408 "c:/Development/emacs-emacs-29.4/src/",
st=0xbfeab0, flags=4096) at sysdep.c:2338
#6  0x00007ff793612ab9 in file_attributes (fd=-3041965, name=0x3e7d408
"c:/Development/emacs-emacs-29.4/src/", dirname=0x0,
filename=0x3e839a4, id_format=0x0) at dired.c:1016
#7  0x00007ff793612a1e in Ffile_attributes (filename=0x3e839a4,
id_format=0x0) at dired.c:962
#8  0x00007ff7936810f6 in funcall_subr (subr=0x7ff793c824a0
<Sfile_attributes>, numargs=1, args=0x4cbd070) at eval.c:3040
#9  0x00007ff7936d99a3 in exec_byte_code (fun=0x44e227d,
args_template=513, nargs=2, args=0x4cbd200) at bytecode.c:809
#10 0x00007ff7936814f2 in fetch_and_exec_byte_code (fun=0x43ee9e5,
args_template=0, nargs=0, args=0xbff420) at eval.c:3085
#11 0x00007ff793681899 in funcall_lambda (fun=0x43ee9e5, nargs=0,
arg_vector=0xbff420) at eval.c:3157
#12 0x00007ff793681676 in apply_lambda (fun=0x43ee9e5, args=0x0,
count=...) at eval.c:3107
#13 0x00007ff79367fb3f in eval_sub (form=0x48a614b) at eval.c:2549
#14 0x00007ff79367f0af in Feval (form=0x48a614b, lexical=0x0) at eval.c:2365
#15 0x00007ff7935ae82a in top_level_2 () at keyboard.c:1142
#16 0x00007ff79367ce04 in internal_condition_case (bfun=0x7ff7935ae803
<top_level_2>, handlers=0x90, hfun=0x7ff7935adfad <cmd_error>) at
eval.c:1474
#17 0x00007ff7935ae87c in top_level_1 (ignore=0x0) at keyboard.c:1150
#18 0x00007ff79367c4ac in internal_catch (tag=0x103b0,
func=0x7ff7935ae82f <top_level_1>, arg=0x0) at eval.c:1197
#19 0x00007ff7935ae6d2 in command_loop () at keyboard.c:1110
#20 0x0000000000000000 in ?? ()
(gdb) info locals
cache = {ret = 1, Name = 0x2606560 "Vladimir.Sironja", DomainName =
0x26065b0 "EDGE", peUse = SidTypeUser}
been_here_count = 3
s_pfn_Lookup_Account_Sid = 0x7ff9e0d9bc20 <LookupAccountSidA>
hm_advapi32 = 0x0
ret = 0
(gdb) continue
Continuing.

Thread 1 hit Breakpoint 1, lookup_account_sid (lpSystemName=0x0,
Sid=0x1242f0, Name=0xbfdb30 "Vladimir.Sironja", cbName=0xbfdb2c,
DomainName=0xbfd720 "EDGE", cbDomainName=0xbfd71c, peUse=0xbfdc38)
    at w32.c:701
701       HMODULE hm_advapi32 = NULL;
(gdb) bt
#0  lookup_account_sid (lpSystemName=0x0, Sid=0x1242f0, Name=0xbfdb30
"Vladimir.Sironja", cbName=0xbfdb2c, DomainName=0xbfd720 "EDGE",
cbDomainName=0xbfd71c, peUse=0xbfdc38) at w32.c:701
#1  0x00007ff793792fa6 in get_name_and_id (psd=0x1242c0, id=0xbfeac4,
nm=0xbfebf4 "", what=2) at w32.c:5230
#2  0x00007ff7937930c2 in get_file_owner_and_group (psd=0x1242c0,
st=0xbfeab0) at w32.c:5258
#3  0x00007ff79379379f in stat_worker (path=0x7ff793da0043
<shortname+3> "Development\\emacs-emacs-29.4\\src\\", buf=0xbfeab0,
follow_symlinks=0) at w32.c:5504
#4  0x00007ff793794217 in fstatat (fd=-3041965, name=0x3e7d408
"c:/Development/emacs-emacs-29.4/src/", st=0xbfeab0, flags=4096) at
w32.c:5751
#5  0x00007ff7935d7b79 in emacs_fstatat (dirfd=-3041965,
filename=0x3e7d408 "c:/Development/emacs-emacs-29.4/src/",
st=0xbfeab0, flags=4096) at sysdep.c:2338
#6  0x00007ff793612ab9 in file_attributes (fd=-3041965, name=0x3e7d408
"c:/Development/emacs-emacs-29.4/src/", dirname=0x0,
filename=0x3e839a4, id_format=0x0) at dired.c:1016
#7  0x00007ff793612a1e in Ffile_attributes (filename=0x3e839a4,
id_format=0x0) at dired.c:962
#8  0x00007ff7936810f6 in funcall_subr (subr=0x7ff793c824a0
<Sfile_attributes>, numargs=1, args=0x4cbd070) at eval.c:3040
#9  0x00007ff7936d99a3 in exec_byte_code (fun=0x44e227d,
args_template=513, nargs=2, args=0x4cbd200) at bytecode.c:809
#10 0x00007ff7936814f2 in fetch_and_exec_byte_code (fun=0x43ee9e5,
args_template=0, nargs=0, args=0xbff420) at eval.c:3085
#11 0x00007ff793681899 in funcall_lambda (fun=0x43ee9e5, nargs=0,
arg_vector=0xbff420) at eval.c:3157
#12 0x00007ff793681676 in apply_lambda (fun=0x43ee9e5, args=0x0,
count=...) at eval.c:3107
#13 0x00007ff79367fb3f in eval_sub (form=0x48a614b) at eval.c:2549
#14 0x00007ff79367f0af in Feval (form=0x48a614b, lexical=0x0) at eval.c:2365
#15 0x00007ff7935ae82a in top_level_2 () at keyboard.c:1142
#16 0x00007ff79367ce04 in internal_condition_case (bfun=0x7ff7935ae803
<top_level_2>, handlers=0x90, hfun=0x7ff7935adfad <cmd_error>) at
eval.c:1474
#17 0x00007ff7935ae87c in top_level_1 (ignore=0x0) at keyboard.c:1150
#18 0x00007ff79367c4ac in internal_catch (tag=0x103b0,
func=0x7ff7935ae82f <top_level_1>, arg=0x0) at eval.c:1197
#19 0x00007ff7935ae6d2 in command_loop () at keyboard.c:1110
#20 0x0000000000000000 in ?? ()
(gdb) info locals
cache = {ret = 1, Name = 0x2606560 "Vladimir.Sironja", DomainName =
0x26065b0 "EDGE", peUse = SidTypeUser}
been_here_count = 4
s_pfn_Lookup_Account_Sid = 0x7ff9e0d9bc20 <LookupAccountSidA>
hm_advapi32 = 0x0
ret = 0
(gdb) continue
Continuing.
[New Thread 20812.0x4f7c]
[New Thread 20812.0x6d38]
[New Thread 20812.0x4a54]

here emacs comes  up.

So for some reason been_here_count = 4.

ps. I understand that my simple fix does't work if first invocation
incomplete with DomainName==NULL

On Mon, Nov 11, 2024 at 2:14 PM Eli Zaretskii <eliz@gnu.org> wrote:
>
> > From: Vladimir Šironja <vladimir.sironja@gmail.com>
> > Date: Mon, 11 Nov 2024 12:30:54 +0100
> >
> > Hello,
> > I have (*had!) a very annoying occurrence of long startup times on
> > windows 10 & 11.
> > Ended up with emacs 29.4 but tried several 28 and 26 versions with no
> > difference.
> > It takes sometimes around 30 secs for emacs to come up.
> > But not always, let's say a third of strarts were normal within a second.
> > Tried excluding relevant directories from virus check; no difference.
> > Also tried starting without init files (-Q); no difference.
> > So compiled with debug symbols gcc version 14.2.0 on msys2.
> > (Had to set manually add "#define HAVE_SYS_WAIT_H 1" into src/config.h
> > - but that's another issue, already handled several times in this
> > group.)
> >
> > In gdb-debugger caught the hanging operation:
> >
> > Thread 1 (Thread 19568.0x24c0):
> > #0  0x00007ff9e2331244 in ntdll!ZwAlpcSendWaitReceivePort () from
> > C:\WINDOWS\SYSTEM32\ntdll.dll
> > #1  0x00007ff9e0a4b032 in RpcBindingFromStringBindingW () from
> > C:\WINDOWS\System32\rpcrt4.dll
> > #2  0x00007ff9e0a47efb in RpcBindingFromStringBindingW () from
> > C:\WINDOWS\System32\rpcrt4.dll
> > #3  0x00007ff9e0a66c19 in RPCRT4!I_RpcSendReceive () from
> > C:\WINDOWS\System32\rpcrt4.dll
> > #4  0x00007ff9e0a66b5f in RPCRT4!NdrSendReceive () from
> > C:\WINDOWS\System32\rpcrt4.dll
> > #5  0x00007ff9e0af07da in RPCRT4!NdrClientCall3 () from
> > C:\WINDOWS\System32\rpcrt4.dll
> > #6  0x00007ff9e0aef69b in RPCRT4!NdrClientCall3 () from
> > C:\WINDOWS\System32\rpcrt4.dll
> > #7  0x00007ff9e11c6046 in SECHOST!LookupAccountSidLocalW () from
> > C:\WINDOWS\System32\sechost.dll
> > #8  0x00007ff9e11c5d4f in SECHOST!LookupAccountSidLocalW () from
> > C:\WINDOWS\System32\sechost.dll
> > #9  0x00007ff9e11dead3 in SECHOST!LookupAccountSidLocalA () from
> > C:\WINDOWS\System32\sechost.dll
> > #10 0x00007ff9e0d9bce0 in LookupAccountSidA () from
> > C:\WINDOWS\System32\advapi32.dll
> > #11 0x00007ff63569a990 in lookup_account_sid (lpSystemName=0x0,
> > Sid=0x4b414a8, Name=0xbfe740 "\030D╦5\001", cbName=0xbfe320,
> > DomainName=0x0, cbDomainName=0xbfe328, peUse=0xbfe314) at w32.c:706
> > #12 0x00007ff63569d35f in init_user_info () at w32.c:2319
> > #13 0x00007ff63569f151 in init_environment (argv=0xd315b0) at w32.c:3198
> > #14 0x00007ff6354b93de in main (argc=1, argv=0xd315b0) at emacs.c:2120
>
> So this is a completely different issue, and should have been
> submitted as a separate bug report.
>
> > Ok, so noticed that it if s_pfn_Lookup_Account_Sid (LookupAccountSid)
> > invoked for the *second* time, it blocks for around half a minute
> > causing the delay.
>
> The questions is: why does it happen on your system.  It doesn't
> happen here on my Windows 11 system, and never happened on my previous
> and other Windows systems where I use Emacs with this code.
>
> Are you working on a system under a domain controller, where Net Logon
> service is enabled?  We have a known problem described in
> etc/PROBLEMS, with a possible solution; search for "Net Logon".
>
> If that solution helps, then maybe your Domain Controller is set up
> sub-optimally, and need to be looked into.
>
> > I didn't analyse the cause for multiple invocations, but added a
> > simple naive workaround to test the theory - which simply caches the
> > results of LookupAccountSid.
>
> Caching the results of LookupAccountSid is problematic: the results
> might change behind Emacs's back, and we have no good way of knowing
> when that happens (to invalidate the cache).
>
> > Please change the code - to invoke the offending winapi function only
> > once, since it obviously punishes the second caller. Or perhaps a
> > caching mechanism as above.
>
> Can you show the backtraces for the two calls to LookupAccountSid?
> The two calls inside lookup_account_sid are not identical: the first
> gets information about the user, the second about its group.  So if
> you are talking about using just one of these two, then the results
> will not be correct for the user's group.
>
> But if you see two calls to LookupAccountSid with the same arguments,
> then please show the backtraces from these duplicate calls.
>
> P.S. If you want to keep discussing this bug further, please submit a
> separate new bug report using "M-x report-emacs-bug".