GNU bug report logs - #74311
Long startup time on windows (with simple fix)

Previous Next

Full log

View this message in rfc822 format

From: help-debbugs <at> gnu.org (GNU bug Tracking System)
To: Vladimir Šironja <vladimir.sironja <at> gmail.com>
Subject: bug#74311: closed (Re: bug#74311: Long startup time on windows
 (with simple fix))
Date: Thu, 02 Jan 2025 06:15:05 +0000

[Message part 1 (text/plain, inline)]

Your bug report

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

which was filed against the emacs package, has been closed.

The explanation is attached below, along with your original report.
If you require more details, please reply to 74311 <at> debbugs.gnu.org.

-- 
74311: https://debbugs.gnu.org/cgi/bugreport.cgi?bug=74311
GNU Bug Tracking System
Contact help-debbugs <at> gnu.org with problems

[Message part 2 (message/rfc822, inline)]

From: Eli Zaretskii <eliz <at> gnu.org>
To: Stefan Kangas <stefankangas <at> gmail.com>
Cc: vladimir.sironja <at> gmail.com, 74311-done <at> debbugs.gnu.org
Subject: Re: bug#74311: Long startup time on windows (with simple fix)
Date: Thu, 02 Jan 2025 08:14:11 +0200

> From: Stefan Kangas <stefankangas <at> gmail.com>
> Date: Wed, 1 Jan 2025 20:03:04 -0600
> Cc: Vladimir Šironja <vladimir.sironja <at> gmail.com>, 
> 	74311 <at> debbugs.gnu.org
> 
> Eli Zaretskii <eliz <at> gnu.org> writes:
> 
> >> From: Vladimir Šironja <vladimir.sironja <at> gmail.com>
> >> Date: Mon, 11 Nov 2024 15:12:39 +0100
> >> Cc: 74311 <at> debbugs.gnu.org
> >>
> >> sorry, didn't quite understand which bugs should be separated, please
> >> advice again,
> >
> > Sorry, my misunderstanding, please ignore that part.
> >
> >> 1) regarding netlogon, I do not really have an option disconnecting from DC
> >
> > Canj you at least try it once, to see if that is the root cause?
> >
> >> 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.
> >
> > This tells me:
> >
> >   . the first 2 calls are from init_user_info, where we obtain and
> >     record the user SID and the Group SID of your user
> >   . the next 2 calls are from file-attributes, where Emacs for some
> >     reason needed to obtain the owner and owner's group of the
> >     directory "c:/Development/emacs-emacs-29.4/src"
> >
> > These are different calls for different purposes: they obtain both the
> > user and group SID (which are different SID values), and there's no
> > guarantee that the directory "c:/Development/emacs-emacs-29.4/src" is
> > necessarily owned by your user.
> >
> > So I don't see how caching could help here, and still produce the
> > correct results.
> >
> > You could avoid the second pair of calls (and many similar calls in
> > other cases where Emacs calls file-attributes) if you set the variable
> > w32-get-true-file-attributes to the nil value.  Maybe this makes
> > startup faster in your case.
> 
> Does that mean that we should close this as wontfix?

Yes, done.

[Message part 3 (message/rfc822, inline)]

From: Vladimir Šironja <vladimir.sironja <at> gmail.com>
To: bug-gnu-emacs <at> gnu.org
Subject: Long startup time on windows (with simple fix)
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


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.
However, when lucky, the function is invoked only once and it just
works as always.

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.

from w32.c:

struct lookup_account_sid_cache {
    BOOL ret;
    LPTSTR Name;
    LPSTR DomainName;
    SID_NAME_USE peUse;
  };

static BOOL WINAPI
lookup_account_sid (LPCTSTR lpSystemName,
        PSID Sid,
        LPTSTR Name,
        LPDWORD cbName,
        LPTSTR DomainName,
        LPDWORD cbDomainName,
        PSID_NAME_USE peUse)
{
  static struct lookup_account_sid_cache cache = { 0, NULL, NULL, 0 };

  static LookupAccountSid_Proc s_pfn_Lookup_Account_Sid = NULL;
  HMODULE hm_advapi32 = NULL;
  if (is_windows_9x () == TRUE)
    {
      return FALSE;
    }
  if (g_b_init_lookup_account_sid == 0)
    {
      g_b_init_lookup_account_sid = 1;
      hm_advapi32 = LoadLibrary ("Advapi32.dll");
      s_pfn_Lookup_Account_Sid = (LookupAccountSid_Proc)
        get_proc_addr (hm_advapi32, LookupAccountSid_Name);
    }
  if (s_pfn_Lookup_Account_Sid == NULL)
    {
      return FALSE;
    }

  BOOL ret;

  if(!cache.ret) {
   ret = s_pfn_Lookup_Account_Sid (
          lpSystemName,
          Sid,
          Name,
          cbName,
          DomainName,
          cbDomainName,
          peUse);

    if(ret) {
      cache.ret = ret;
      cache.Name = Name && *Name ? strdup(Name) : NULL;
      cache.DomainName = DomainName && *DomainName ? strdup(DomainName) : NULL;
      cache.peUse = peUse ? *peUse : 0;
    }
  }
  else {
    ret = cache.ret;
    if(cache.Name) {
      strncpy(Name, cache.Name, *cbName);
      *cbName = strlen(cache.Name);
    }
    if(cache.DomainName && cbDomainName && *cbDomainName > 0) {
      if(DomainName) strncpy(DomainName, cache.DomainName, *cbDomainName);
      *cbDomainName = strlen(cache.DomainName);
     }
    if(peUse) *peUse = cache.peUse;
  }
  return ret;
}

Tried about 30 times since the fix: works like a charm.
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.

Cheers to fellow emacsers!
And thx for all the good work form the team

Bye
Vlado

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.