Mouse momentarily locks up on repeatedly hitting macro key

[xfacter]

XMBC Version: 2.18.3
Windows Version: Win10 Pro 1809
Mouse Information (brand/model): Razer Deathadder Chroma RZ01-0121 / also tested with Logitech G9
Computer Information: i7 8700k / R9 290 / 16GB DDR4 / Gigabyte Aorus Gaming 5
Did the problem occur after an upgrade of XMBC?: Maybe. I upgrade as program checks and prompts me about updates.
Did the problem occur after a Windows update/upgrade?: Maybe. I manually upgraded from 1803 to 1809 recently (for some reason 1809 was never made available to me via automatic updates).
How long have you used XMBC?: Off and on for years.
What language and keyboard layout do you use in Windows?: en/qwerty

Clear description of the problem:

I have been using XMBC for simple mouse macros in games for a while. Recently it started doing something strange, locking up my mouse (edit: and keyboard) for maybe a full second after repeatedly hitting the macro key. I am not sure the precise conditions to reproduce but just hitting the macro button repeatedly seems to induce it pretty consistently.

I have confirmed that the problem is NOT:
- The mouse -- I have tested with another mouse
- The game -- I have tested in multiple games, and outside of games with the Default profile
- NOT XMBC -- I have tested same macro with another macro program (AHK) and NOT able to reproduce

This is happening with a common macro I use with similar definitions in a few games. Both are defined similarly with just differing input {KEY} and Auto Repeat Delay, like this
Mouse Button 4 (MWDN) -- Simulated Keys: (repeat) [{KEY}] -- {KEY} = e.g. {SPACE}, {MWDN}, etc
How to send: 6 Repeatedly while the button is down
Auto repeat delay: 20-25 ms

Typically I have all three boxes checked (only send if process is active, block original input, randomise auto repeat), but I have tested with and without them checked and can reproduce either way. The macro/activation button does not matter, I can reproduce with same macro on other buttons. I cannot say whether this occurs with other types of macros or send methods, since this is the only combination I found that achieves what I am going for.

I never had any issues with this type of macro until recently. I did not change my XMBC configuration at all. The problem does seem to have started after updating XMBC and Windows 10, but I also took a break from the games where I use these macro for a while so cannot say if the issue is really related to either form of update.

Please let me know if you have any ideas. Thanks for reading.

[phil]

Thanks for all the detail. It does sound like an XMBC problem...
If you could check the log file for me and see if there are any strange error messages - I doubt there will be anything in the normal log.... So next can you enable debug logging, and first see if the problem still occurs, and if it does, send me a copy of the logfile (and please make a note of the <rough> time that the problem occurred to help me narrow it down in the log).

In the meantime, I'll try it here - you say it happens in many games - got any examples? Does it happen just on the desktop or notepad (that will make things easier to try and reproduce here)

Regards,
Phil

[phil]

Also do you know roughly what version you came from when the problem occurred (ie. from 2.17 (released Dec 2017) to 2.18.x (Dec 2018/Jan 2019) or earlier?

Initial try on notepad here shows noting obvious but maybe I didn't try for long enough.

[xfacter]

I am able to quickly reproduce in desktop apps like Notepad, so yes it's not just games. I was using XMBC with these macros regularly in November and early December and would have kept it up to date, so must have come from 2.17.

I am seeing some odd messages repeated often in the log. Small sample included here.

Full disclosure, I soft-upgraded from Windows 8.1 and upgraded my CPU/mobo but never installed a fresh OS. Have had my fair share of bizarre unrelated issues that may be at least partly due to my Frankenstein OS.

Code: Select all

25-02-2019 19:09:42.893> ***************************************************************************
25-02-2019 19:09:42.893> WARNING: Mouse hook has taken too long (1000 ms). Hook may be disabled.
25-02-2019 19:09:42.893> MouseHookData: Msg=0x020c (WM_XBUTTONUP), X=1714, Y=478, Data=0x00010000, Flags=0x00000000, Time=95399812, Info=0x0, Ptr=0x934A0E33, Layer=0
25-02-2019 19:09:42.893> ***************************************************************************
25-02-2019 19:34:26.582> SendInputThreaded: Ignoring input as the send thread has been blocked.
25-02-2019 19:34:26.582> SendInputThreaded: Ignoring input as the send thread has been blocked.
25-02-2019 19:34:27.580> ***************************************************************************
25-02-2019 19:34:27.580> WARNING: Mouse hook has taken too long (1000 ms). Hook may be disabled.
25-02-2019 19:34:27.580> MouseHookData: Msg=0x020c (WM_XBUTTONUP), X=1741, Y=846, Data=0x00010000, Flags=0x00000000, Time=96884515, Info=0x0, Ptr=0x86460F8F, Layer=0
25-02-2019 19:34:27.580> ***************************************************************************
25-02-2019 21:29:22.785> SendInputThreaded: Ignoring input as the send thread has been blocked.
25-02-2019 21:29:22.904> SendInputThreaded: Ignoring input as the send thread has been blocked.
25-02-2019 21:29:23.784> ***************************************************************************
25-02-2019 21:29:23.811> WARNING: Mouse hook has taken too long (1000 ms). Hook may be disabled.
25-02-2019 21:29:23.811> MouseHookData: Msg=0x020c (WM_XBUTTONUP), X=1675, Y=1072, Data=0x00010000, Flags=0x00000000, Time=103780718, Info=0x0, Ptr=0x86470F8F, Layer=0
25-02-2019 21:29:23.811> ***************************************************************************
25-02-2019 21:33:45.956> ***************************************************************************
25-02-2019 21:33:45.956> WARNING: Mouse hook has taken too long (1000 ms). Hook may be disabled.
25-02-2019 21:33:45.956> MouseHookData: Msg=0x020c (WM_XBUTTONUP), X=1702, Y=1031, Data=0x00010000, Flags=0x00000000, Time=104042890, Info=0x0, Ptr=0x40D30AB5, Layer=0
25-02-2019 21:33:45.956> ***************************************************************************

[phil]

OK I think I know what the problem is...
those "hook timeout" messages are the key. And upgrading windows probably did impact this, in that it reset the hook timeout to default.

The hook timeout defaults to 200ms and when that happens, XMBC gets "removed" meaning it wont respond. It will try and re-install the hook but this could explain the delays/lag.

Try increasing the hook timeout to 1000 - 5000ms in the advanced settings tab of XMBC - then reboot and see if the problem still occurs. If it does then it not that - but I hope it might make all the difference. Of course, it could be something completely different. If it still happens, please turn on debug logging and repeat the log procedure and send me the debug log (it will be much larger).

Regards,
Phil

[xfacter]

Okay. I tried changing the setting you mentioned to 1000ms, rebooted, and the problem still occurs but seems less frequent. I tried again at 2000ms with a similar result. I also tried resetting the value to 200ms, uninstalling, rebooting, and installing again. The value was automatically set to 1000ms when I checked and the problem still occurs.

I have reproduced the issue with debug logging and pasted it here. I believe I induced it once or twice while debug logging was on here.

http://pastebin.com/p4NhTizr (it won't let me post links)

[xfacter]

Any ideas? Thanks for your help.

If you haven't tried this already, perhaps to reproduce more easily you can try dropping your hook timeout to 200ms.

[phil]

Sorry, haven't looked at this one yet.
The hook timeout may well be a red herring, because if the hook gets removed, XMBC will fail to work at all from that point on - and from your description, it seems that it does continue to work, but after a delay of a second or so? This actually suggests that something is locking a thread and leaving it locked for a while and eventually resolving (unlocking) after a delay.

Unfortunately these timing things are really difficult to diagnose, as the issue may only happen on one configuration. A different speed CPU may not get into this deadlock scenario at all. On top of that simply enabling debug logging can change the timing enough to make it either not happen or happen all the time. Also the amount of log when debug is turned on can make it difficult to see the wood through the trees so to speak. I don't suppose when you made the log, you noted the time the issue occurred (as I asked) so I can narrow down the search at all?

[xfacter]

I'll make another log with a clock open so I can note the exact time.

[phil]

Thanks...

I have my suspisions - there is an entry in that log where it gets stuck on the locked thread for 1 second... That for sure could be the problem

Code: Select all

26-02-2019 12:09:30.257> CSendInput::ProcessQueue: Sleeping for 1ms
26-02-2019 12:09:30.258> CSendInput::ProcessQueue: Finished sending 2 queue entries... (Flushed = 0)
26-02-2019 12:09:30.282> MouseHookLLProc: MouseHookData: Msg=0x020c (WM_XBUTTONUP), X=883, Y=551, Data=0x00010000, Flags=0x00000000, Time=498937, Info=0x0, Ptr=0x2007A7, Layer=0
26-02-2019 12:09:30.283> Unable to enter critical section in RealWindowFromPoint hook as it is locked by 'MouseHookLLProc 1'
26-02-2019 12:09:30.283> Unable to enter critical section for lock 'RepeatTimerProc NOWINDOW' (TID: 00001DC4) because it is already locked by 'MouseHookLLProc 1' - Waiting...
26-02-2019 12:09:30.283> Translating XLeft Button Up Key state 0x0: Action 28 [Simulated Keys '{SPACE}' (repeat)]
26-02-2019 12:09:30.283> SendInput::FlushQueue requested
26-02-2019 12:09:31.279> MouseHookLLProc: Removing message 0x020C (883,551) from mouse hook queue as we have overridden it.
26-02-2019 12:09:31.279> Obtained lock for 'RepeatTimerProc NOWINDOW' after 1000ms.
26-02-2019 12:09:31.279> Unable to enter critical section in WM_MOUSEMOVE hook as it is locked by 'RepeatTimerProc NOWINDOW'
26-02-2019 12:09:31.279> RepeatTimerProc: Unable to get the window under the cursor. Resetting timer.
26-02-2019 12:09:31.279> ProxySetTimer [TID: 0x00001DC4]: Starting timer 4113
26-02-2019 12:09:31.279> TimerThread(00001DC4): Killing timer 4113 (ID: 0x00007B7A)

But its not clear why its getting stuck - other than one thread has obtained a lock and seemingly not released it - some sort of temporary deadlock - enough to notice in the mouse movement.

Another log would be good extra evidence, esp. if the times of the log entries like we see above correlate with the lockup!
In the mean time, I'll study the code and try and work out how it can lock up in this way!

Regards,
Phil

[phil]

OK Found it... Don't worry about making any more logs - I will release another update with this fixed.

[xfacter]

Fantastic -- thank you very much!

Was the fix in yesterday's patch or will it be in a later patch?

[phil]

Yes, urm, should be fixed in yesterdays release...
I think I missed it out of the change log though (but its definitely in there!)

[xfacter]

Great, I tested earlier with latest build and could not manage to reproduce. Thanks again for the fix.

[jeffbs]

Yes, urm, should be fixed in yesterdays release...
I think I missed it out of the change log though (but its definitely in there!)

I'm getting the same problem as the post author, already checked the log file and the same "SendInputThreaded: Ignoring input as the send thread has been blocked." message appears.

29-10-2021 10:09:21.685> X-Mouse Button Control v2.19.2 (x64) Startup. Commandline ''
29-10-2021 10:09:21.688> Running in high integrity mode (0x00003000)
29-10-2021 10:09:21.690> Loaded 3 application specific profiles (3 normal and 0 custom window).
29-10-2021 10:09:21.690> Running on Microsoft Windows 10 Professional Edition (build 19043), 64-bit, Hook Timeout: 5000 ms
29-10-2021 10:09:21.690> Startup folder: 'C:\Program Files\Highresolution Enterprises\X-Mouse Button Control\'
29-10-2021 10:09:21.690> Settings (and log) folder: 'C:\Users\Jeff\AppData\Roaming\Highresolution Enterprises\XMouseButtonControl\'
29-10-2021 10:09:21.802> HookThreadProc[0x4B50]: Using keyboard language 0x04090409
29-10-2021 10:09:22.277> TimerThread: Error in timer thread message queue. (Error code 1400: O identificador da janela é inválido. )
29-10-2021 10:09:23.803> CMyMessageWnd::OnSetup - Opening setup dialog.
29-10-2021 10:09:23.842> Loaded 3 application specific profiles (3 normal and 0 custom window).
29-10-2021 10:09:48.129> SendInputThreaded: Ignoring input as the send thread has been blocked.
29-10-2021 10:09:48.129> SendInputThreaded: Ignoring input as the send thread has been blocked.

Already tried 200ms, 1000ms, 2000ms and 5000ms for Hook Timeout and nothing.