Ensure that all in-process log calls never block an app's threads#11431
Conversation
LeonarddeR
left a comment
There was a problem hiding this comment.
If i'm correct, we no longer limit inproc log messages to a level higher than debug, right? Is this intentional?
|
@LeonarddeR Ah yes, I should have mentioned I removed the limitation around not logging debug level to NVDA. This limitation was originally there as there are so many debug calls and they would majorly slow down an app's main thread (say when debuggind displayModel) as each call would contact NvDA from that thread. Now as it is in a separate thread it shouldn't be so bad. However, note that by default (and therefore in all official builds of NVDA) the nvdaHelperLogLevel is lower than debug, and therefore the LOG_DEBUG macro is a no-op anyway. In other words, even now, to get messages at level debug, you still need to compile NvDA with nvdaHelperLogLevel at debug or higher. |
|
@LeonarddeR I have fixed the indentation now. |
|
@feerrenrut thanks for the useful review. I think the main reason why I had maxCount as an argument in the first place came from the fact I was trying to avoid an extra function and using log_flushQueue also as the apc function.
|
|
Yes, these changes look good.
I need to look into how APC works to really make assertions around this, but if these two functions can run concurrently then I'm concerned that there should be concurrency control on on this deque. Check the thread safety header on the following page also: https://en.cppreference.com/w/cpp/container I'll come back to this. |
|
We can be sure that two APC functions of ours will never run at the same
time, as they are all queued to the same thread.
But, certainly two threads could push to the queue at the same time, or
a thread could push, and and the manager thread could pop at the same time.
I always assumed that c++ containers (at least Windows implementations
of them) had a lock where necessary, so that (in the case of deque)
push_back and pop_front could never run concurrently, but I could be wrong.
|
I think we will have to protect this deque from this. See the detailed rules under the "thread safety" header on the following page also: https://en.cppreference.com/w/cpp/container The gist of it is that reading from the container (eg const member functions) are fine, modifying the container not so. |
|
There seems to be two thread safety problems:
To prevent this we need to introduce locks. Preventing multiple threads from modifying the queue. The main concern is to watch for deadlocks, though data races should be kept in mind. By ensuring we only hold a lock while making changes to the queue, we can prevent deadlocks. The trick to this is localizing the code that needs a lock. So, I see two options:
Assumptions:
|
|
@feerrenrut in log_flushQueue I now lock and swap. And in logMessage I now also lock. |
feerrenrut
left a comment
There was a problem hiding this comment.
I think this generally looks good. Just a couple of small questions, minor suggestions.
…ally, just let them all get destroied when the queue is destroied. Co-authored-by: Reef Turner <feerrenrut@users.noreply.github.com>
…r thread, queue the call back to the manager thread with apc. Co-authored-by: Reef Turner <feerrenrut@users.noreply.github.com>
* Only try to queue a call to log_flushQueue via APC if the manager thread actually exists yet. * Declare log_flushQueue_apcFunc early so it actualy compiles :) * Remove a redundant blank line.
|
@feerrenrut I committed your suggestions but made a couple of small changes: We can only queue via APC if the manager thread actually exists yet. And log_flushQueue_apcFunc needed to be declared first. Does this all look okay now? |
feerrenrut
left a comment
There was a problem hiding this comment.
Thanks @michaelDCurran
8de91b2
Link to issue number:
Re #11369 , #11398
Summary of the issue:
While NVDA is running code within other processes (such as for visutlaBuffers, displayModels and other helper functions), it occasionally logs messages back to NvDA for debugging purposes. Log messages are sent to NvDA via rpc. But currently these rpc calls block while the log message is being sent to NVDA, which may mean that an app's main thread could block for a time or in the worst case deadlock with NvDA, if the Python garbage collector in NVDA happens to run within the incoming rpc call and happens to release a COM object for the thread the log call originated from.
Description of how this pull request fixes the issue:
logMessage (in NVDAHelperRemote) will now do the following:
Just before the inproc manager thread finally exits, we also process any queued log messages to catch any queued after the manager thread main loop completed.
Testing performed:
Ran NVDA, interacting with Microsoft Word, Notepad and the Run dialog.
Added some temporary log calls in various places in the in-process code, such as dllMain, and when handing typed characters in the app's main thread, to ensure that message ordering is correct, and that log calls were always happening from the manager thread.
Known issues with pull request:
None.
Change log entry:
Bug fixes: