search

Yubico / Yubico.NET.SDK

A YubiKey SDK for .NET developers
Apache License 2.0
96 stars 48 forks source link

High CPU/Memory cost with following call stack in c# .Net472 application on Windows. The Yubikey version is 1.5.1 #37

Closed zyyanfei closed 1 month ago

zyyanfei commented 1 year ago

Child-SP RetAddr Call Site

00 0000009bab6fdaf0 00007ff8dba4af2d KERNELBASE!RaiseException+0x69 [minkernel\kernelbase\xcpt.c @ 938] 01 0000009bab6fdbd0 00007ff8d28d16f8 msvcrt!_CxxThrowException+0xad [minkernel\crts\crtw32\eh\throw.cpp @ 175] 02 (Inline Function) ---------------- WinSCard!CHandleList::Get+0x42 [ds\security\scard\pcsc\inc\Handles.h @ 575] 03 (Inline Function) ---------------- WinSCard!CHandleList::operator[]+0x42 [ds\security\scard\pcsc\inc\Handles.h @ 243] 04 0000009bab6fdc40 00007ff867b9b202 WinSCard!SCardGetStatusChangeA+0xb8 [ds\security\scard\pcsc\server\client\winscarda.cpp @ 2049] 05 0000009bab6fdcf0 00007ff8675b8b15 Yubico_NativeShims!Native_SCardGetStatusChange+0xc2 06 0000009bab6fdd30 00007ff8675b99ab Microsoft_Office_Datacenter_Torus_Interop!DomainBoundILStubClass.IL_STUB_PInvoke(Yubico.PlatformInterop.SCardContext, Int32, Yubico.PlatformInterop.SCARD_READER_STATE[], Int32)+0x165 07 0000009bab6fde50 00007ff8675b71bf Yubico_Core_1af22b80000!Yubico.Core.Devices.SmartCard.DesktopSmartCardDeviceListener.CheckForUpdates+0xfb 08 0000009bab6fe120 00007ff8c4a4df12 Yubico_Core_1af22b80000!Yubico.Core.Devices.SmartCard.DesktopSmartCardDeviceListener.ListenForReaderChanges+0xef 09 0000009bab6fe1a0 00007ff8c4a4dd95 mscorlib_ni!System.Threading.ExecutionContext.RunInternal+0x172 [f:\dd\ndp\clr\src\BCL\system\threading\executioncontext.cs @ 980] 0a 0000009bab6fe270 00007ff8c4a4dd65 mscorlib_ni!System.Threading.ExecutionContext.Run+0x15 [f:\dd\ndp\clr\src\BCL\system\threading\executioncontext.cs @ 928] 0b 0000009bab6fe2a0 00007ff8c4af3e85 mscorlib_ni!System.Threading.ExecutionContext.Run+0x55 [f:\dd\ndp\clr\src\BCL\system\threading\executioncontext.cs @ 917] 0c 0000009bab6fe2f0 00007ff8c65a6893 mscorlib_ni!System.Threading.ThreadHelper.ThreadStart+0x55 [f:\dd\ndp\clr\src\BCL\system\threading\thread.cs @ 111] 0d 0000009bab6fe330 00007ff8c65a67b0 clr!CallDescrWorkerInternal+0x83 [f:\dd\ndp\clr\src\vm\amd64\CallDescrWorkerAMD64.asm @ 97] 0e 0000009bab6fe370 00007ff8c65a7050 clr!CallDescrWorkerWithHandler+0x4e [f:\dd\ndp\clr\src\vm\callhelpers.cpp @ 89] 0f 0000009bab6fe3b0 00007ff8c6763e4f clr!MethodDescCallSite::CallTargetWorker+0xfa [f:\dd\ndp\clr\src\vm\callhelpers.cpp @ 655] 10 (Inline Function) ---------------- clr!MethodDescCallSite::Call+0xffffffffffffeee3 [f:\dd\ndp\clr\src\vm\callhelpers.h @ 423] 11 0000009bab6fe4b0 00007ff8c65a7c38 clr!ThreadNative::KickOffThread_Worker+0xfffffffffffff02f [f:\dd\ndp\clr\src\vm\comsynchronizable.cpp @ 301] 12 0000009bab6fe710 00007ff8c65a7ba3 clr!ManagedThreadBase_DispatchInner+0x40 [f:\dd\ndp\clr\src\vm\threads.cpp @ 10296] 13 0000009bab6fe750 00007ff8c65a7ae2 clr!ManagedThreadBase_DispatchMiddle+0x6c [f:\dd\ndp\clr\src\vm\threads.cpp @ 10345] 14 0000009bab6fe850 00007ff8c65a7cd3 clr!ManagedThreadBase_DispatchOuter+0x4c [f:\dd\ndp\clr\src\vm\threads.cpp @ 10600] 15 0000009bab6fe8c0 00007ff8c6763d39 clr!ManagedThreadBase_FullTransitionWithAD+0x2f [f:\dd\ndp\clr\src\vm\threads.cpp @ 10664] 16 (Inline Function) ---------------- clr!ManagedThreadBase::KickOff+0x20 [f:\dd\ndp\clr\src\vm\threads.cpp @ 10698] 17 0000009bab6fe920 00007ff8c65abd15 clr!ThreadNative::KickOffThread+0xe6 [f:\dd\ndp\clr\src\vm\comsynchronizable.cpp @ 421] 18 0000009bab6fea00 00007ff8db997614 clr!Thread::intermediateThreadProc+0x8b [f:\dd\ndp\clr\src\vm\threads.cpp @ 2882] 19 0000009bab6ff8c0 00007ff8dc0626a1 KERNEL32!BaseThreadInitThunk+0x14 [clientcore\base\win32\client\thread.c @ 64] 1a 0000009bab6ff8f0 0000000000000000 ntdll!RtlUserThreadStart+0x21 [minkernel\ntdll\rtlstrt.c @ 1153]

zyyanfei commented 1 year ago

another report is as below. Looks like it is a random issue on some machines. Appreciate if anyone can share insights here/ Thanks.

<html xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40">

Cannot resolve some symbols, but looks like repeated calls to SCardGetStatusChangeA throwing exception repeatedly (similar stack in torusclienthelperservice)

 

Line # | Process | Stack | Count | Weight (in view) (ms) | TimeStamp (s) | % Weight -- | -- | -- | -- | -- | -- | -- 2 | powershell.exe (41456) |   | 35763 | 35,625.225500 |   | 6.14 3 |   | [Root] | 32490 | 32,359.816800 |   | 5.58 4 |   | \|- ntdll.dll!RtlUserThreadStart | 32385 | 32,256.779000 |   | 5.56 5 |   | \|    kernel32.dll!BaseThreadInitThunk | 32385 | 32,256.779000 |   | 5.56 6 |   | \|    \|- clr.dll!Thread::intermediateThreadProc | 32333 | 32,204.713300 |   | 5.55 7 |   | \|    \|    \|- clr.dll!ThreadNative::KickOffThread | 32330 | 32,201.711000 |   | 5.55 8 |   | \|    \|    \|    clr.dll!ManagedThreadBase_FullTransitionWithAD | 32330 | 32,201.711000 |   | 5.55 9 |   | \|    \|    \|    clr.dll!ManagedThreadBase_DispatchOuter | 32330 | 32,201.711000 |   | 5.55 10 |   | \|    \|    \|    clr.dll!ManagedThreadBase_DispatchMiddle | 32330 | 32,201.711000 |   | 5.55 11 |   | \|    \|    \|    clr.dll!ManagedThreadBase_DispatchInner | 32330 | 32,201.711000 |   | 5.55 12 |   | \|    \|    \|    clr.dll!ThreadNative::KickOffThread_Worker | 32330 | 32,201.711000 |   | 5.55 13 |   | \|    \|    \|    clr.dll!MethodDescCallSite::CallTargetWorker | 32330 | 32,201.711000 |   | 5.55 14 |   | \|    \|    \|    clr.dll!CallDescrWorkerWithHandler | 32330 | 32,201.711000 |   | 5.55 15 |   | \|    \|    \|    clr.dll!CallDescrWorkerInternal | 32330 | 32,201.711000 |   | 5.55 16 |   | \|    \|    \|    mscorlib.ni.dll! | 32330 | 32,201.711000 |   | 5.55 17 |   | \|    \|    \|    mscorlib.ni.dll! | 32330 | 32,201.711000 |   | 5.55 18 |   | \|    \|    \|    mscorlib.ni.dll! | 32330 | 32,201.711000 |   | 5.55 19 |   | \|    \|    \|    mscorlib.ni.dll! | 32330 | 32,201.711000 |   | 5.55 20 |   | \|    \|    \|    \|- ?!? | 32291 | 32,162.696800 |   | 5.54 21 |   | \|    \|    \|    \|    \|- ?!? | 32230 | 32,101.846900 |   | 5.53 22 |   | \|    \|    \|    \|    \|    \|- ?!? | 30777 | 30,653.640000 |   | 5.28 23 |   | \|    \|    \|    \|    \|    \|    \|- ?!? | 23680 | 23,589.013700 |   | 4.06 24 |   | \|    \|    \|    \|    \|    \|    \|    \|- WinSCard.dll!SCardGetStatusChangeA | 20147 | 20,069.342800 |   | 3.46 25 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|- msvcrt.dll!_CxxThrowException | 17780 | 17,713.477200 |   | 3.05 26 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- KernelBase.dll!RaiseException | 17519 | 17,454.468900 |   | 3.01

GregDomzalski commented 1 year ago

Hi @zyyanfei -

There's an indication of a native exception occurring within the call to WinSCard.dll!SCardGetStatusChangeA. Do you have any insight as to what that exception is or if it is being translated to an error code?

It's likely that we're getting some indication of error that the event loop was not prepared for. It would help to understand what that error might be.

Thanks.

zyyanfei commented 1 year ago

Hi @zyyanfei -

There's an indication of a native exception occurring within the call to WinSCard.dll!SCardGetStatusChangeA. Do you have any insight as to what that exception is or if it is being translated to an error code?

It's likely that we're getting some indication of error that the event loop was not prepared for. It would help to understand what that error might be.

Thanks.

Hi Greg, I already repro this case consistently when I rdp a remote Windows machine on which an application is invoking Yubico SDK. Once I disconnect and re-RDP again, then the application's CPU cost will increase signaficantly.

Look into Yubico SDK implementation, I think there is a bug here :

In [Yubico.YubiKey.YubiKeyDevice]::FindByTransport, YubiKeyDeviceListener.Instance isn't disposed explicitly so that the background listener thread won't be end after the call FindByTransport. Each call for FindByTransport will create a new background thread. But I can't prove if it is related with the bug we hit above. Could you help double confirm if it is a bug ?

zyyanfei commented 1 year ago

Hi @GregDomzalski did you get a chance to look into this issue ?

GregDomzalski commented 1 year ago

No, not yet. I will try to get to it this week.

It would be extremely helpful if you were able to determine the error code of the native exception noted in your above reply.

zyyanfei commented 1 year ago

The callstack above is what I get from my powershell client. How could I get "the error code of the native exception"

DennisDyallo commented 2 months ago

Hey @zyyanfei ! We've since published updates to the SDK. Question is, are you still experiencing this? If so, that'd afford us taking another look at it. Thanks.

DennisDyallo commented 1 month ago

Closing old issues. Feel free to reopen if this is still important to you.