im-select-mspy 执行后到最终退出间隔很长时间

JMwill commented 1 year ago

2023-06-21-19-53-31-min

现象描述：使用 im-select-mspy.exe 实现语言切换功能时，执行后程序退出需要等待很长时间导致问题：当使用 neovim 等执行切换命令时，光标恢复功能需要等 im-select-mspy.exe 执行结束，这导致每次按 ESC 之后都要等相应时间 neovim命令：autocmd InsertLeave * :silent !im-select-mspy.exe 英语模式 想请问下是什么原因会导致需要等待这么长时间才能退出，有没有什么解决办法？或者排查的办法？

JMwill commented 1 year ago

修改 return 为 exit 可以解决这个问题： #67

daipeihust commented 1 year ago

mspy是什么

JMwill commented 1 year ago

你这个不是专门针对微软自带的拼音输入法实现了对应版本的 im-select 么？就是 win-mspy 文件夹内的程序呀

elsejj commented 1 year ago

@JMwill 很奇怪的问题，方便的话，可以加个日志看看

class LogExit {
public:
  LogExit() {
    SYSTEMTIME now;
    GetLocalTime(&now);
    wcout << now.wHour << L":" << now.wMinute << L":" << now.wSecond << L"." << now.wMilliseconds << L" Start " << endl;
  }
  ~LogExit() {
    SYSTEMTIME now;
    GetLocalTime(&now);
    wcout << now.wHour << L":" << now.wMinute << L":" << now.wSecond << L"." << now.wMilliseconds << L" Exited " << endl;
  }
};
int wmain(int argc, wchar_t * argv[])
{
  auto log_exit = LogExit();

  std::ios::sync_with_stdio(false);
  std::locale::global( std::locale("") );

在我这里，是这样的，看起来时间还好。

JMwill commented 1 year ago

@JMwill 很奇怪的问题，方便的话，可以加个日志看看

class LogExit {
public:
  LogExit() {
    SYSTEMTIME now;
    GetLocalTime(&now);
    wcout << now.wHour << L":" << now.wMinute << L":" << now.wSecond << L"." << now.wMilliseconds << L" Start " << endl;
  }
  ~LogExit() {
    SYSTEMTIME now;
    GetLocalTime(&now);
    wcout << now.wHour << L":" << now.wMinute << L":" << now.wSecond << L"." << now.wMilliseconds << L" Exited " << endl;
  }
};
int wmain(int argc, wchar_t * argv[])
{
  auto log_exit = LogExit();

  std::ios::sync_with_stdio(false);
  std::locale::global( std::locale("") );

在我这里，是这样的，看起来时间还好。

添加了你的代码，但是执行后退出时并没有执行析构函数，很奇怪，是我电脑环境有什么问题吗？比如说安装了Anaconda 的 Miniconda im-select-mspy-vscode-code

https://github.com/daipeihust/im-select/assets/11496449/6f38e7b5-1b27-47d9-9c69-4baf4cf4396b

elsejj commented 1 year ago

@JMwill 可以看看机器上是不是有这个设置么 https://learn.microsoft.com/zh-cn/windows/win32/wer/collecting-user-mode-dumps?redirectedfrom=MSDN

没有执行析构的话，有可能是之前有异常退出了，然后系统在做异常退出的处理，或是有什么防护软件在干什么。

JMwill commented 1 year ago

@JMwill 可以看看机器上是不是有这个设置么 https://learn.microsoft.com/zh-cn/windows/win32/wer/collecting-user-mode-dumps?redirectedfrom=MSDN

没有执行析构的话，有可能是之前有异常退出了，然后系统在做异常退出的处理，或是有什么防护软件在干什么。

好的，查找系统看到有crash dump的记录，源文件是： im-select-mspy.exe.30344.dmp.zip 已经用WinDbg解析出结果，还请麻烦帮忙分析下原因，我自己看内容像是访问了没有权限访问的地址00007ffa5f5cf01c，但是不理解那是什么，具体分析内容如下：

*******************************************************************************
*                                                                             *
*                        Exception Analysis                                   *
*                                                                             *
*******************************************************************************

Unable to load image uiautomationcore.dll, Win32 error 0n2
*** WARNING: Unable to verify timestamp for uiautomationcore.dll

KEY_VALUES_STRING: 1

    Key  : AV.Fault
    Value: Execute

    Key  : Analysis.CPU.mSec
    Value: 2265

    Key  : Analysis.DebugAnalysisManager
    Value: Create

    Key  : Analysis.Elapsed.mSec
    Value: 4774

    Key  : Analysis.Init.CPU.mSec
    Value: 1202

    Key  : Analysis.Init.Elapsed.mSec
    Value: 18421

    Key  : Analysis.Memory.CommitPeak.Mb
    Value: 135

    Key  : Timeline.Process.Start.DeltaSec
    Value: 6

    Key  : WER.OS.Branch
    Value: vb_release

    Key  : WER.OS.Timestamp
    Value: 2019-12-06T14:06:00Z

    Key  : WER.OS.Version
    Value: 10.0.19041.1

FILE_IN_CAB:  im-select-mspy.exe.30344.dmp

NTGLOBALFLAG:  0

PROCESS_BAM_CURRENT_THROTTLED: 0

PROCESS_BAM_PREVIOUS_THROTTLED: 0

APPLICATION_VERIFIER_FLAGS:  0

CONTEXT:  (.ecxr)
rax=0000000000000001 rbx=00000000000007d0 rcx=00000209aa820000
rdx=00000209aa820000 rsi=00000209aa8ab9b0 rdi=0000000000070000
rip=00007ffa5f5cf01c rsp=0000009bdb6fe540 rbp=0000000000000001
 r8=00000209aa790fc0  r9=0000000000000001 r10=0000000000008000
r11=0000009bdb6fe440 r12=0000000000000000 r13=0000000000000000
r14=00007ffa5f815ff8 r15=0000000000000000
iopl=0         nv up ei pl nz na po nc
cs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00010204
uiautomationcore+0x3f01c:
00007ffa`5f5cf01c ??              ???
Resetting default scope

EXCEPTION_RECORD:  (.exr -1)
ExceptionAddress: 00007ffa5f5cf01c (uiautomationcore+0x000000000003f01c)
   ExceptionCode: c0000005 (Access violation)
  ExceptionFlags: 00000000
NumberParameters: 2
   Parameter[0]: 0000000000000008
   Parameter[1]: 00007ffa5f5cf01c
Attempt to execute non-executable address 00007ffa5f5cf01c

PROCESS_NAME:  im-select-mspy.exe

EXECUTE_ADDRESS: 7ffa5f5cf01c

FAILED_INSTRUCTION_ADDRESS: 
uiautomationcore.dll!Unloaded+3f01c
00007ffa`5f5cf01c ??              ???

ERROR_CODE: (NTSTATUS) 0xc0000005 - 0x%p            0x%p                    %s

EXCEPTION_CODE_STR:  c0000005

EXCEPTION_PARAMETER1:  0000000000000008

EXCEPTION_PARAMETER2:  00007ffa5f5cf01c

STACK_TEXT:  
0000009b`db6fe540 00000000`000007d0     : 00000209`aa8ab9b0 0000009b`00000001 00000209`00000000 0000009b`000007d0 : uiautomationcore+0x3f01c
0000009b`db6fe548 00000209`aa8ab9b0     : 0000009b`00000001 00000209`00000000 0000009b`000007d0 00000209`aa8ab900 : 0x7d0
0000009b`db6fe550 0000009b`00000001     : 00000209`00000000 0000009b`000007d0 00000209`aa8ab900 0000009b`db6fe580 : 0x00000209`aa8ab9b0
0000009b`db6fe558 00000209`00000000     : 0000009b`000007d0 00000209`aa8ab900 0000009b`db6fe580 0000009b`db6fe5b8 : 0x0000009b`00000001
0000009b`db6fe560 0000009b`000007d0     : 00000209`aa8ab900 0000009b`db6fe580 0000009b`db6fe5b8 00000000`00000000 : 0x00000209`00000000
0000009b`db6fe568 00000209`aa8ab900     : 0000009b`db6fe580 0000009b`db6fe5b8 00000000`00000000 00007ffa`5f5ac724 : 0x0000009b`000007d0
0000009b`db6fe570 0000009b`db6fe580     : 0000009b`db6fe5b8 00000000`00000000 00007ffa`5f5ac724 00000209`aa8ab9b0 : 0x00000209`aa8ab900
0000009b`db6fe578 0000009b`db6fe5b8     : 00000000`00000000 00007ffa`5f5ac724 00000209`aa8ab9b0 00000209`aa8ab9b8 : 0x0000009b`db6fe580
0000009b`db6fe580 00000000`00000000     : 00007ffa`5f5ac724 00000209`aa8ab9b0 00000209`aa8ab9b8 00000000`00000001 : 0x0000009b`db6fe5b8

STACK_COMMAND:  ~0s; .ecxr ; kb

SYMBOL_NAME:  uiautomationcore.dll!Unloaded+3f01c

MODULE_NAME: uiautomationcore

IMAGE_NAME:  uiautomationcore.dll

FAILURE_BUCKET_ID:  BAD_INSTRUCTION_PTR_c0000005_uiautomationcore.dll!Unloaded

OS_VERSION:  10.0.19041.1

BUILDLAB_STR:  vb_release

OSPLATFORM_TYPE:  x64

OSNAME:  Windows 10

FAILURE_ID_HASH:  {94e356cc-1541-43e7-1177-a5efc3211ee1}

Followup:     MachineOwner
---------

elsejj commented 1 year ago

看意思是在 uiautomationcore.dll 卸载时有一个访问异常，这个一般是有空指针，或是有二次释放造成的，因为我这里无法复现，从代码上看的话， https://github.com/daipeihust/im-select/blob/9cd5278b185a9d6daa12ba35471ec2cc1a2e3012/win-mspy/main.cc#L143 这个返回会有可能会有问题，方便的话，可以改成

  return { match.str(1), pButton};

试试，这将显式的复制出一个 wstring

JMwill commented 1 year ago

@elsejj 已经添加并执行，没有执行析构函数而且依然需要等待很长时间才退出，通过添加打印发现执行CoUninitialize后就卡住了，截图如下：

JMwill commented 1 year ago

很抱歉耽误大家时间了，真正的问题找到了，导致im-select-mspy.exe退出慢的原因是防护软件对它进行了拦截，因为我用的是公司电脑，强制安装了防护软件，然后防护软件又对任何陌生程式的执行进行了拦截，这就导致软件从执行到退出需要耗费特别长的时间。这里描述一下如何找到问题的，希望对后来者有参考作用：

打开 git-bash 软件
打开任务管理器
观察系统资源消耗情况，直到基本平稳
在 git-bash 中执行如下代码 for((i=0;i<30;i++)); do im-select-mspy; done
观察资源消耗情况

在第五步的观察过程中，我发现防护软件的CPU使用量异常升高，在多次重复后确定是防护软件的问题

解决办法：在发现是防护软件的问题后，由于软件不允许卸载，因此在防护软件的信任列表中把im-select-mspy.exe加进去后就解决问题了，软件执行速度在可接受范围内。

elsejj commented 1 year ago

@JMwill 辛苦测试了，windows 环境比较复杂。

daipeihust / im-select

im-select-mspy 执行后到最终退出间隔很长时间 #65