Cygwin 'cp' command is still slow after Cygserver is installed

Cygwin 'cp' command is still slow after Cygserver is installed

[Derek Pagel]

[-- Attachment #1: Type: text/plain, Size: 8851 bytes --]

I've been seeing an issue where Cygwin commands sometimes take a while to complete, or they will not complete at all and will have to be manually killed through task manager. I installed Cygserver and that helped to lessen the number of times that the issue happens but it didn't get rid of it. I'm wondering if anyone has run into the same behavior. I've also shared the .dmp files of a 'cp' command that was taking a while to complete in case that helps:


cp.dmp

Microsoft (R) Windows Debugger Version 10.0.22621.755 AMD64

Copyright (c) Microsoft Corporation. All rights reserved.



Loading Dump File [C:\sandbox\Logs\cp.dmp]

User Mini Dump File with Full Memory: Only application data is available

Symbol search path is: srv*

Executable search path is:

Windows 10 Version 17763 MP (8 procs) Free x64

Product: Server, suite: TerminalServer SingleUserTS

Edition build lab: 17763.1.amd64fre.rs5_release.180914-1434

Machine Name:

Debug session time: Tue Apr  4 11:13:23.000 2023 (UTC - 5:00)

System Uptime: 38 days 11:52:56.830

Process Uptime: 0 days 0:21:50.000

.......

For analysis of this file, run !analyze -v

ntdll!NtWaitForSingleObject+0x14:

00007ffd`f967f7e4 c3              ret

0:000> !analyze -v

*******************************************************************************

*                                                                             *

*                        Exception Analysis                                   *

*                                                                             *

*******************************************************************************



KEY_VALUES_STRING: 1

    Key  : Analysis.CPU.mSec

    Value: 327

    Key  : Analysis.DebugAnalysisManager

    Value: Create

    Key  : Analysis.Elapsed.mSec

    Value: 1001

    Key  : Analysis.Init.CPU.mSec

    Value: 624

    Key  : Analysis.Init.Elapsed.mSec

    Value: 13453

    Key  : Analysis.Memory.CommitPeak.Mb

    Value: 80

    Key  : Timeline.OS.Boot.DeltaSec

    Value: 3325976

    Key  : Timeline.Process.Start.DeltaSec

    Value: 1310

    Key  : WER.OS.Branch

    Value: rs5_release

    Key  : WER.OS.Timestamp

    Value: 2018-09-14T14:34:00Z

    Key  : WER.OS.Version

    Value: 10.0.17763.1



FILE_IN_CAB:  cp.dmp

NTGLOBALFLAG:  0

APPLICATION_VERIFIER_FLAGS:  0

EXCEPTION_RECORD:  (.exr -1)

ExceptionAddress: 0000000000000000

   ExceptionCode: 80000003 (Break instruction exception)

  ExceptionFlags: 00000000

NumberParameters: 0



FAULTING_THREAD:  000019f0

PROCESS_NAME:  cp.exe

ERROR_CODE: (NTSTATUS) 0x80000003 - {EXCEPTION}  Breakpoint  A breakpoint has been reached.

EXCEPTION_CODE_STR:  80000003



STACK_TEXT:

00000000`004fe608 00007ffd`f61783d3     : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`004fe720 : ntdll!NtWaitForSingleObject+0x14

00000000`004fe610 00000000`677ea815     : 00000000`00000001 00000000`00000000 00000000`00000000 00000000`000000c8 : KERNELBASE!WaitForSingleObjectEx+0x93

00000000`004fe6b0 00000000`677eb688     : 00000000`00000000 00000000`00ae6bd0 00000000`00000000 00000000`00000000 : msvcr90!_dospawn+0x261

00000000`004fe7d0 00000000`677eb831     : ffffffff`ffffffff 00000000`00ae4cb0 00000000`00000000 00007931`45513238 : msvcr90!comexecmd+0x78

00000000`004fe820 00000000`677ebd0a     : 00000000`00000000 00000000`00ae4c20 00000000`00000000 00000000`00000000 : msvcr90!_spawnve+0x17d

00000000`004fe890 00007ff7`afc11261     : 00000000`00ae6bd0 00000000`00000003 00000000`004fed20 00000000`004fe920 : msvcr90!system+0xaa

00000000`004fe8f0 00007ff7`afc11442     : 00000000`00000000 00001e3c`d7e4c5c9 00000000`00000000 00000000`00000000 : cp+0x1261

00000000`004ffd40 00007ffd`f9227974     : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : cp+0x1442

00000000`004ffd70 00007ffd`f964a271     : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0x14

00000000`004ffda0 00000000`00000000     : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x21



STACK_COMMAND:  ~0s; .ecxr ; kb

FAULTING_SOURCE_LINE:  f:\dd\vctools\crt_bld\self_64_amd64\crt\src\dospawn.c

FAULTING_SOURCE_FILE:  f:\dd\vctools\crt_bld\self_64_amd64\crt\src\dospawn.c

FAULTING_SOURCE_LINE_NUMBER:  215

SYMBOL_NAME:  msvcr90!_dospawn+261

MODULE_NAME: msvcr90

IMAGE_NAME:  msvcr90.dll

FAILURE_BUCKET_ID:  BREAKPOINT_80000003_msvcr90.dll!_dospawn

OS_VERSION:  10.0.17763.1

BUILDLAB_STR:  rs5_release

OSPLATFORM_TYPE:  x64

OSNAME:  Windows 10

IMAGE_VERSION:  9.0.30729.9518

FAILURE_ID_HASH:  {ae098e47-a4ce-0039-c30c-1cea11724b06}



Followup:     MachineOwner

---------



cp2.dmp:

Microsoft (R) Windows Debugger Version 10.0.22621.755 AMD64

Copyright (c) Microsoft Corporation. All rights reserved.



Loading Dump File [C:\sandbox\116929941_cp\cp2.dmp]

User Mini Dump File with Full Memory: Only application data is available

Symbol search path is: srv*

Executable search path is:

Windows 10 Version 17763 MP (8 procs) Free x64

Product: Server, suite: TerminalServer SingleUserTS

Edition build lab: 17763.1.amd64fre.rs5_release.180914-1434

Machine Name:

Debug session time: Tue Apr  4 11:13:35.000 2023 (UTC - 5:00)

System Uptime: 38 days 11:53:08.253

Process Uptime: 0 days 0:22:02.000

....................

For analysis of this file, run !analyze -v

*** WARNING: Unable to verify timestamp for cygwin1.dll

ntdll!NtQueryObject+0x14:

00007ffd`f967f964 c3              ret

0:000> !analyze -v

*******************************************************************************

*                                                                             *

*                        Exception Analysis                                   *

*                                                                             *

*******************************************************************************



KEY_VALUES_STRING: 1

    Key  : Analysis.CPU.mSec

    Value: 421

    Key  : Analysis.DebugAnalysisManager

    Value: Create

    Key  : Analysis.Elapsed.mSec

    Value: 943

    Key  : Analysis.Init.CPU.mSec

    Value: 264

    Key  : Analysis.Init.Elapsed.mSec

    Value: 127055

    Key  : Analysis.Memory.CommitPeak.Mb

    Value: 70

    Key  : Timeline.OS.Boot.DeltaSec

    Value: 3325988

    Key  : Timeline.Process.Start.DeltaSec

    Value: 1322

    Key  : WER.OS.Branch

    Value: rs5_release

    Key  : WER.OS.Timestamp

    Value: 2018-09-14T14:34:00Z

    Key  : WER.OS.Version

    Value: 10.0.17763.1



FILE_IN_CAB:  cp2.dmp

NTGLOBALFLAG:  0

PROCESS_BAM_CURRENT_THROTTLED: 0

PROCESS_BAM_PREVIOUS_THROTTLED: 0

APPLICATION_VERIFIER_FLAGS:  0

EXCEPTION_RECORD:  (.exr -1)

ExceptionAddress: 0000000000000000

   ExceptionCode: 80000003 (Break instruction exception)

  ExceptionFlags: 00000000

NumberParameters: 0



FAULTING_THREAD:  00005dd4

PROCESS_NAME:  cp.exe

ERROR_CODE: (NTSTATUS) 0x80000003 - {EXCEPTION}  Breakpoint  A breakpoint has been reached.

EXCEPTION_CODE_STR:  80000003



STACK_TEXT:

00000000`fffdc9b8 00000001`80059050     : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!NtQueryObject+0x14

00000000`fffdc9c0 00000001`8005b483     : 00020000`00000011 00000008`00000010 00000001`8034d860 00000001`8034de70 : cygwin1!dlfork+0xa0

00000000`ffffca50 00000001`8005ba3d     : 00000000`00000001 00000001`800d87de 00000000`00000000 00000000`00000000 : cygwin1!dlfork+0x24d3

00000000`ffffcb50 00000001`80048c3f     : 00000000`ffffcc10 00000024`00048a70 00000000`00000000 ffffffff`ffffff85 : cygwin1!dlfork+0x2a8d

00000000`ffffcbd0 00000001`80047746     : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : cygwin1!cygwin_dll_init+0x38f

00000000`ffffcd80 00000001`800477f4     : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : cygwin1!_assert+0x41f6

00000000`ffffcdd0 00000000`00000000     : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : cygwin1!_assert+0x42a4



STACK_COMMAND:  ~0s; .ecxr ; kb

SYMBOL_NAME:  cygwin1+a0

MODULE_NAME: cygwin1

IMAGE_NAME:  cygwin1.dll

FAILURE_BUCKET_ID:  BREAKPOINT_80000003_cygwin1.dll!Unknown

OS_VERSION:  10.0.17763.1

BUILDLAB_STR:  rs5_release

OSPLATFORM_TYPE:  x64

OSNAME:  Windows 10

IMAGE_VERSION:  3003.3.0.0

FAILURE_ID_HASH:  {6e59254d-04c5-5897-9d5c-9c053de3947f}



Followup:     MachineOwner

---------

Re: Cygwin 'cp' command is still slow after Cygserver is installed

[marco atzeri]

On Tue, Apr 11, 2023 at 10:08 PM Derek Pagel via Cygwin  wrote:
>
> I've been seeing an issue where Cygwin commands sometimes take a while to complete, or they will not complete at all and will have to be manually killed through task manager. I installed Cygserver and that helped to lessen the number of times that the issue happens but it didn't get rid of it. I'm wondering if anyone has run into the same behavior. I've also shared the .dmp files of a 'cp' command that was taking a while to complete in case that helps:
>

how big are these files and from where to where are you copying them ?
AV interference ?

RE: Cygwin 'cp' command is still slow after Cygserver is installed

[Derek Pagel]

how big are these files and from where to where are you copying them ?
AV interference ?


The files being copied are not very big at all and they're just being copied from one directory to another on the same server.

Re: Cygwin 'cp' command is still slow after Cygserver is installed

[Brian Inglis]

On 2023-04-12 06:44, Derek Pagel via Cygwin wrote:
>> how big are these files and from where to where are you copying them ?
>> AV interference ?
> The files being copied are not very big at all and they're just being copied
> from one directory to another on the same server.

Could be long ACL lists with many unique ACEs that need looked up on AD, and/or 
slow ADCs, and/or slow AV, and/or slow net:

for each file show the outputs of

	$ ls -dl $f
	$ getfacl $f
	$ icacls "`cygpath -m $f`"

and also attach as text, the output from strace on the cp command, as it will 
show the timing and delays e.g.

	$ strace -o cp-strace.log cp ...

-- 
Take care. Thanks, Brian Inglis              Calgary, Alberta, Canada

La perfection est atteinte                   Perfection is achieved
non pas lorsqu'il n'y a plus rien à ajouter  not when there is no more to add
mais lorsqu'il n'y a plus rien à retirer     but when there is no more to cut
                                 -- Antoine de Saint-Exupéry

RE: Cygwin 'cp' command is still slow after Cygserver is installed

[Derek Pagel]

Could be long ACL lists with many unique ACEs that need looked up on AD, and/or slow ADCs, and/or slow AV, and/or slow net:

for each file show the outputs of

	$ ls -dl $f
	$ getfacl $f
	$ icacls "`cygpath -m $f`"

and also attach as text, the output from strace on the cp command, as it will show the timing and delays e.g.

	$ strace -o cp-strace.log cp ...



I couldn't run strace on the Cygwin command because the issue is really intermittent. I did have another Cygwin cmd, 'mv', that was hung so I ran the commands below on the file it was trying to move:

D:\lsenv\law\lsapps\edi\work>ls -dl valid_ediout.20230413113258.tmp
-rwxrwxrwa   1 Administrators   INFORBC\Domain Users        749 Apr 13 valid_ediout.20230413113258.tmp

D:\lsenv\law\lsapps\edi\work>getfacl valid_ediout.20230413113258.tmp
getfacl: valid_ediout.20230413113258.tmp: No such file or directory

D:\lsenv\law\lsapps\edi\work>icacls "`cygpath -m valid_ediout.20230413113258.tmp"
'cygpath -m valid_ediout.20230413113258.tmp; The system cannot find the file specified.
Successfully processed 0 files; Failed processing 1 files

Re: Cygwin 'cp' command is still slow after Cygserver is installed

[Brian Inglis]

On 2023-04-14 08:10, Derek Pagel via Cygwin wrote:
> Could be long ACL lists with many unique ACEs that need looked up on AD, 
> and/or slow ADCs, and/or slow AV, and/or slow net:
> for each file show the outputs of
> 	$ ls -dl $f
> 	$ getfacl $f
> 	$ icacls "`cygpath -m $f`"
> and also attach as text, the output from strace on the cp command, as it will
> show the timing and delays e.g.
> 	$ strace -o cp-strace.log cp ...

> I couldn't run strace on the Cygwin command because the issue is really
> intermittent. I did have another Cygwin cmd, 'mv', that was hung so I ran the
> commands below on the file it was trying to move:
> D:\lsenv\law\lsapps\edi\work>ls -dl valid_ediout.20230413113258.tmp
> -rwxrwxrwa   1 Administrators   INFORBC\Domain Users        749 Apr 13 valid_ediout.20230413113258.tmp
> D:\lsenv\law\lsapps\edi\work>getfacl valid_ediout.20230413113258.tmp
> getfacl: valid_ediout.20230413113258.tmp: No such file or directory
> D:\lsenv\law\lsapps\edi\work>icacls "`cygpath -m valid_ediout.20230413113258.tmp"
> 'cygpath -m valid_ediout.20230413113258.tmp; The system cannot find the file specified.
> Successfully processed 0 files; Failed processing 1 files

Looks like the ACL has not been written, so the incoming ACEs are still being 
looked up (and/or maybe inherited)?
Where was that file moved from and what were the files' permissions and ACLs 
before and after?

Anyone know what execute permission *a* means? -rwxrwxrwa [above]

-- 
Take care. Thanks, Brian Inglis              Calgary, Alberta, Canada

La perfection est atteinte                   Perfection is achieved
non pas lorsqu'il n'y a plus rien à ajouter  not when there is no more to add
mais lorsqu'il n'y a plus rien à retirer     but when there is no more to cut
                                 -- Antoine de Saint-Exupéry

RE: Cygwin 'cp' command is still slow after Cygserver is installed

[Derek Pagel]

Looks like the ACL has not been written, so the incoming ACEs are still being looked up (and/or maybe inherited)?
Where was that file moved from and what were the files' permissions and ACLs before and after?

Anyone know what execute permission *a* means? -rwxrwxrwa [above]

------------------------------------------------------------------------------------------------------------

I was able to get the files' permissions and ACLs before and after. It's interesting to note that the source and destination for the file is the same directory.


D:\lsenv\law\lsapps\edi\work>ls -l interchange.20230418*
-rwxrwxrwa   1 Administrators   INFORBC\Domain Users       1586 Apr 18 interchange.20230418091901 
-rwxrwxrwa   1 Administrators   INFORBC\Domain Users       1586 Apr 18 interchange.20230418091901.tmp


Getfacl works on the source but not the destination file:

D:\lsenv\law\lsapps\edi\work>getfacl interchange.20230418091901
# file: interchange.20230418091901
# owner: Administrators
# group: Domain Users
user::rwx
user:lawson:rwx
group::---
group:Authenticated Users:rwx
group:SYSTEM:rwx
group:Users:r-x
group:AD_LAWUSERS:rwx
mask::rwx
other::---

D:\lsenv\law\lsapps\edi\work>getfacl interchange.20230418091901.tmp
getfacl: interchange.20230418091901.tmp: No such file or directory


The icalcs command doesn’t work on either and I haven’t been able to get it to work elsewhere either.

D:\lsenv\law\lsapps\edi\work>icacls "`cygpath -m interchange.20230418091901"
`cygpath -m interchange.20230418091901: The system cannot find the file specified.
Successfully processed 0 files; Failed processing 1 files

D:\lsenv\law\lsapps\edi\work>icacls "`cygpath -m interchange.20230418091901.tmp"
`cygpath -m interchange.20230418091901.tmp: The system cannot find the file specified.
Successfully processed 0 files; Failed processing 1 files

Re: Cygwin 'cp' command is still slow after Cygserver is installed

[Andrey Repin]

Greetings, Derek Pagel!


> The icalcs command doesn’t work on either and I haven’t been able to get it to work elsewhere either.

> D:\lsenv\law\lsapps\edi\work>icacls "`cygpath -m interchange.20230418091901"
> `cygpath -m interchange.20230418091901: The system cannot find the file specified.
> Successfully processed 0 files; Failed processing 1 files

Stop using ` already. Or at the very least use it properly.
Either

icacls `cygpath -m interchange.20230418091901`

or

icacls "$(cygpath -m interchange.20230418091901)"

> D:\lsenv\law\lsapps\edi\work>icacls "`cygpath -m interchange.20230418091901.tmp"
> `cygpath -m interchange.20230418091901.tmp: The system cannot find the file specified.
> Successfully processed 0 files; Failed processing 1 files

Not to mention, you don't need to cygpath the file in current directory.
Just

icacls "interchange.20230418091901.tmp"

should suffice.


-- 
With best regards,
Andrey Repin
Thursday, April 20, 2023 10:31:55

Sorry for my terrible english...

RE: Cygwin 'cp' command is still slow after Cygserver is installed

[Derek Pagel]

Stop using ` already. Or at the very least use it properly.
Either

icacls `cygpath -m interchange.20230418091901`
or
icacls "$(cygpath -m interchange.20230418091901)"

Not to mention, you don't need to cygpath the file in current directory.
Just

icacls "interchange.20230418091901.tmp"
should suffice.

----------------------------------------------------------------------------------------------------------------

I've re-ran the commands and was able to get output for all of them:

The command that hung:
D:\cygwin64\bin\mv.exe D:/lsenv/law/lsapps/edi/work/valid_ediout.20230425113255.tmp D:/lsenv/law/lsapps/edi/work/valid_ediout.20230425113255

Note: The 'valid_ediout.20230425113255.tmp' file did not exist when running the commands:

D:\lsenv\law\lsapps\edi\work>ls -l valid_ediout.20230425113255.tmp
ls: File or directory is not found


D:\lsenv\law\lsapps\edi\work>ls -l valid_ediout.20230425113255
-rwxrwxrwa   1 Administrators   INFORBC\Domain Users        574 Apr 25 valid_ediout.20230425113255


D:\lsenv\law\lsapps\edi\work>getfacl valid_ediout.20230425113255
# file: valid_ediout.20230425113255
# owner: Administrators
# group: Domain Users
user::rwx
user:lawson:rwx
group::---
group:Authenticated Users:rwx
group:SYSTEM:rwx
group:Users:r-x
group:AD_LAWUSERS:rwx
mask::rwx
other::---


D:\lsenv\law\lsapps\edi\work>icacls valid_ediout.20230425113255
valid_ediout.20230425113255 INFORBC\lawson:(I)(F)
                            INFORBC\AD_LAWUSERS:(I)(F)
                            BUILTIN\Administrators:(I)(F)
                            NT AUTHORITY\SYSTEM:(I)(F)
                            NT AUTHORITY\Authenticated Users:(I)(M)
                            BUILTIN\Users:(I)(RX)

Successfully processed 1 files; Failed processing 0 files

Re: mode -rwxrwxrwa what is execute permission a?

[Brian Inglis]

On 2023-04-26 08:37, Derek Pagel via Cygwin wrote:
> D:\lsenv\law\lsapps\edi\work>ls -l valid_ediout.20230425113255
> -rwxrwxrwa   1 Administrators   INFORBC\Domain Users        574 Apr 25 valid_ediout.20230425113255
> D:\lsenv\law\lsapps\edi\work>getfacl valid_ediout.20230425113255
> # file: valid_ediout.20230425113255
> # owner: Administrators
> # group: Domain Users
> user::rwx
> user:lawson:rwx
> group::---
> group:Authenticated Users:rwx
> group:SYSTEM:rwx
> group:Users:r-x
> group:AD_LAWUSERS:rwx
> mask::rwx
> other::---
> D:\lsenv\law\lsapps\edi\work>icacls valid_ediout.20230425113255
> valid_ediout.20230425113255 INFORBC\lawson:(I)(F)
>                              INFORBC\AD_LAWUSERS:(I)(F)
>                              BUILTIN\Administrators:(I)(F)
>                              NT AUTHORITY\SYSTEM:(I)(F)
>                              NT AUTHORITY\Authenticated Users:(I)(M)
>                              BUILTIN\Users:(I)(RX)
> 
> Successfully processed 1 files; Failed processing 0 files

-- 
Take care. Thanks, Brian Inglis              Calgary, Alberta, Canada

La perfection est atteinte                   Perfection is achieved
non pas lorsqu'il n'y a plus rien à ajouter  not when there is no more to add
mais lorsqu'il n'y a plus rien à retirer     but when there is no more to cut
                                 -- Antoine de Saint-Exupéry