NVDA Laggs a lot in Visual Studio Code editor while typing and reading the code

akash07k commented 4 years ago

Steps to reproduce:

Open Visual studio code.
Open a file or directory containing any text files in it such as a javascript/python project.
Go to the editor.
try navigating the text/code via arrow keys.
Now try typing some code in the editor quickly.
It will be observed that in both 4th and 5th point, NVDA laggs a lot while navigating and typing the code in the editor.
Now repeat the same thing with Notepad plus plus or another text editor.
It will be observed that NVDA doesn't lag there at all and responds very snappily.

Actual behavior:

When we navigate/read and type the text/code in visual studio code editor, NVDA laggs a lot and responds very slowly. For example, If we navigate/read the code in notepad NVDA responds/reads every line quickly but in VS Code, it doesn't happen like this. Also, If we quickly type the code, most of the times, NVDA announces the typed characters after a delay which is very annoying and problematic. It doesn't happen with other applications.

Expected behavior:

NVDA should not lag in VS Code editor and should be responsive like it is with other editors.

System configuration

NVDA installed/portable/running from source:

Installed

NVDA version:

NVDA version alpha-20793,9a4074bc

Windows version:

Tried with multiple Windows builds: Windows 10 2004, 19041.450, and latest insider too.

Name and version of other software in use when reproducing the issue:

Visual Studio Code both insider and stable.

Other information about your system:

I7 processor, 8 GB ram, Samsung SSD and also tried with multiple other systems. Same issue persists.

Other questions

Does the issue still occur after restarting your computer?

Yes, always and even after reformatting the system too.

Have you tried any other versions of NVDA? If so, please report their behaviors.

Yes, NVDA stable versions, and the same issue is being observed since months.

If addons are disabled, is your problem still occuring?

Yes, always.

Did you try to run the COM registry fixing tool in NVDA menu / tools?

Yes, but no luck

akash07k commented 4 years ago

@feerrenrut Bro, your views/comments on this?

feerrenrut commented 4 years ago

Can you turn on "time since input" logging in the advanced settings panel, with add-ons disabled, do a short test with vsCode and post the debug level log please?

prajwalkeny22 commented 4 years ago

Unsub

On 8/31/20, Akash Kakkar notifications@github.com wrote:

@feerrenrut Bro, your views/comments on this?

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/nvaccess/nvda/issues/11533#issuecomment-683650824

-- Prajwal

LeonarddeR commented 4 years ago

cc @isidorn

akash07k commented 4 years ago

Can you turn on "time since input" logging in the advanced settings panel, with add-ons disabled, do a short test with vsCode and post the debug level log please?

Sure @feerrenrut I'll attach log soon after my office hours.

Neurrone commented 4 years ago

I can confirm that I've also been experiencing this on my work machine, though its a really old Dell XPS 13 from 2016.

Soome other things that might be related:

I'm working primarily with TypeScript and JavaScript, about 100,000 lines of code for the folders that I'm trying to open
Even while typing normally in a blank document or in a .md file and arrowing around on my more powerful personal machine feels laggier than on notepad

akash07k commented 4 years ago

@feerrenrut Please find the log attached with this comment. Please let me know if anything more is needed.

Can you turn on "time since input" logging in the advanced settings panel, with add-ons disabled, do a short test with vsCode and post the debug level log please?

NVDA_Log.txt

akash07k commented 4 years ago

Absolutely, same here as well. Notepad, notepad plus plus, android studio, all other editors etc are absolutely fine and feel very snappier. I've tried VS Code with JAWS yesterday and it was not lagging at all, hence it seems that this problem is NVDA specific. But, I don't want to leave NVDA at any cost now. Don't want to go back to JAWS at any cost.

I can confirm that I've also been experiencing this on my work machine, though its a really old Dell XPS 13 from 2016.

Soome other things that might be related:
* I'm working primarily with TypeScript and JavaScript, about 100,000 lines of code for the folders that I'm trying to open

* Even while typing normally in a blank document or in a .md file and arrowing around on my more powerful personal machine feels laggier than on notepad

akash07k commented 4 years ago

@feerrenrut Today I tried it with another system which was having 16 GB ram, and I7 10th generation processor, but same laggyness was observed there. It was my friends computer. This lag is really painful and completely prevents me for using VS Code

feerrenrut commented 4 years ago

Since it is a long log, I picked a random part to inspect where I was sure you were using vsCode:

Input: kb(laptop):upArrow
DEBUG - editableText.EditableText._hasCaretMoved (23:41:10.127) - MainThread (8528):
Caret move detected using bookmarks. Elapsed: 20 ms
IO - inputCore.logTimeSinceInput (23:41:10.130) - MainThread (8528):
0.109 sec since input
IO - speech.speak (23:41:10.130) - MainThread (8528):
Speaking ['let test2 = "test2";\n']
IO - inputCore.InputManager.executeGesture (23:41:10.428) - winInputHook (1656):
Input: kb(laptop):upArrow
DEBUG - editableText.EditableText._hasCaretMoved (23:41:10.552) - MainThread (8528):
Caret move detected using bookmarks. Elapsed: 20 ms
IO - inputCore.logTimeSinceInput (23:41:10.557) - MainThread (8528):
0.128 sec since input
IO - speech.speak (23:41:10.557) - MainThread (8528):
Speaking ['let test1 = "this is a test";\n']
IO - inputCore.InputManager.executeGesture (23:41:11.902) - winInputHook (1656):
Input: kb(laptop):upArrow
DEBUG - editableText.EditableText._hasCaretMoved (23:41:12.033) - MainThread (8528):
Caret move detected using bookmarks. Elapsed: 30 ms
IO - inputCore.logTimeSinceInput (23:41:12.039) - MainThread (8528):
0.136 sec since input
IO - speech.speak (23:41:12.039) - MainThread (8528):
Speaking ['blank']
IO - inputCore.InputManager.executeGesture (23:41:12.414) - winInputHook (1656):
Input: kb(laptop):upArrow
DEBUG - editableText.EditableText._hasCaretMoved (23:41:12.524) - MainThread (8528):
Caret move detected using bookmarks. Elapsed: 20 ms
IO - inputCore.logTimeSinceInput (23:41:12.529) - MainThread (8528):
0.114 sec since input
IO - speech.speak (23:41:12.529) - MainThread (8528):
Speaking ["//I'm testing the slowness with visual studio code.\n"]
IO - inputCore.InputManager.executeGesture (23:41:12.855) - winInputHook (1656):
Input: kb(laptop):upArrow
DEBUG - editableText.EditableText._hasCaretMoved (23:41:13.060) - MainThread (8528):
Caret didn't move before timeout. Elapsed: 100 ms
IO - inputCore.logTimeSinceInput (23:41:13.069) - MainThread (8528):
0.214 sec since input
IO - speech.speak (23:41:13.070) - MainThread (8528):
Speaking ["//I'm testing the slowness with visual studio code.\n"]

This indicates an average of 140 ms from input to speech. It would be interesting to compare these values to another application that does not have lag for you such as notepad, keeping all other configuration and test approach the same.

For future reference, Espeak was used for this test.

akash07k commented 4 years ago

So, Should I provide the logs while typing/interacting with notepad too?

akash07k commented 4 years ago

I can confirm that I've also been experiencing this on my work machine, though its a really old Dell XPS 13 from 2016.

Soome other things that might be related:
* I'm working primarily with TypeScript and JavaScript, about 100,000 lines of code for the folders that I'm trying to open

* Even while typing normally in a blank document or in a .md file and arrowing around on my more powerful personal machine feels laggier than on notepad

Bro, can you also provide your logs for the easier pin pointing of the problem

akash07k commented 4 years ago

Actually I used VS code many times only for generating the log, Can you please look at other parts too for the more better insights on this? Currently you've picked the logs where I've only navigated the code. Typing is much more pain.

akash07k commented 4 years ago

@feerrenrut I see that you've picked the part where I've only navigated the code. Typing the code is more laggier.

Neurrone commented 4 years ago

here're some logs of just using the arrow keys, but this on the machine where I'm not suffering from this.

Btw, do I need to choose the "restart with debug logging" option to have the timing logs show up? They wouldn't show up for me otherwise.

Input: kb(laptop):control+home
DEBUGWARNING - Python warning (21:36:15.569) - MainThread (26636):
C:\Program Files (x86)\NVDA\library.zip\keyboardHandler.py:549: DeprecationWarning: Yield() is deprecated
DEBUGWARNING - Python warning (21:36:15.569) - MainThread (26636):
C:\Program Files (x86)\NVDA\library.zip\api.py:287: DeprecationWarning: Yield() is deprecated
DEBUG - editableText.EditableText._hasCaretMoved (21:36:15.588) - MainThread (26636):
Caret move detected using bookmarks. Elapsed: 10 ms
IO - inputCore.logTimeSinceInput (21:36:15.591) - MainThread (26636):
0.056 sec since input
IO - speech.speak (21:36:15.591) - MainThread (26636):
Speaking ['# Espresso Extraction\n']
IO - inputCore.InputManager.executeGesture (21:36:16.445) - winInputHook (28992):
Input: kb(laptop):downArrow
DEBUG - editableText.EditableText._hasCaretMoved (21:36:16.510) - MainThread (26636):
Caret move detected using bookmarks. Elapsed: 10 ms
IO - inputCore.logTimeSinceInput (21:36:16.513) - MainThread (26636):
0.068 sec since input
IO - speech.speak (21:36:16.513) - MainThread (26636):
Speaking ['blank']
IO - inputCore.InputManager.executeGesture (21:36:16.823) - winInputHook (28992):
Input: kb(laptop):downArrow
DEBUG - editableText.EditableText._hasCaretMoved (21:36:16.879) - MainThread (26636):
Caret move detected using bookmarks. Elapsed: 10 ms
IO - inputCore.logTimeSinceInput (21:36:16.881) - MainThread (26636):
0.058 sec since input
IO - speech.speak (21:36:16.881) - MainThread (26636):
Speaking ['## Extraction\n']
IO - inputCore.InputManager.executeGesture (21:36:17.785) - winInputHook (28992):
Input: kb(laptop):rightArrow
DEBUG - editableText.EditableText._hasCaretMoved (21:36:17.813) - MainThread (26636):
Caret move detected using bookmarks. Elapsed: 0 ms
IO - inputCore.logTimeSinceInput (21:36:17.815) - MainThread (26636):
0.030 sec since input
IO - speech.speak (21:36:17.815) - MainThread (26636):
Speaking ['number', EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (21:36:18.126) - winInputHook (28992):
Input: kb(laptop):rightArrow
DEBUG - editableText.EditableText._hasCaretMoved (21:36:18.188) - MainThread (26636):
Caret move detected using bookmarks. Elapsed: 10 ms
IO - inputCore.logTimeSinceInput (21:36:18.190) - MainThread (26636):
0.064 sec since input
IO - speech.speak (21:36:18.190) - MainThread (26636):
Speaking ['space', EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (21:36:18.439) - winInputHook (28992):
Input: kb(laptop):rightArrow
DEBUG - editableText.EditableText._hasCaretMoved (21:36:18.492) - MainThread (26636):
Caret move detected using bookmarks. Elapsed: 10 ms
IO - inputCore.logTimeSinceInput (21:36:18.494) - MainThread (26636):
0.055 sec since input
IO - speech.speak (21:36:18.494) - MainThread (26636):
Speaking [PitchCommand(offset=30), CharacterModeCommand(True), 'E', PitchCommand(), EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (21:36:18.766) - winInputHook (28992):
Input: kb(laptop):rightArrow
DEBUG - editableText.EditableText._hasCaretMoved (21:36:18.799) - MainThread (26636):
Caret move detected using bookmarks. Elapsed: 0 ms
IO - inputCore.logTimeSinceInput (21:36:18.801) - MainThread (26636):
0.035 sec since input
IO - speech.speak (21:36:18.801) - MainThread (26636):
Speaking [CharacterModeCommand(True), 'x', EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (21:36:19.006) - winInputHook (28992):
Input: kb(laptop):rightArrow
DEBUG - editableText.EditableText._hasCaretMoved (21:36:19.067) - MainThread (26636):
Caret move detected using bookmarks. Elapsed: 10 ms
IO - inputCore.logTimeSinceInput (21:36:19.070) - MainThread (26636):
0.064 sec since input
IO - speech.speak (21:36:19.070) - MainThread (26636):
Speaking [CharacterModeCommand(True), 't', EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (21:36:19.269) - winInputHook (28992):
Input: kb(laptop):rightArrow
DEBUG - editableText.EditableText._hasCaretMoved (21:36:19.293) - MainThread (26636):
Caret move detected using bookmarks. Elapsed: 0 ms
IO - inputCore.logTimeSinceInput (21:36:19.296) - MainThread (26636):
0.027 sec since input
IO - speech.speak (21:36:19.296) - MainThread (26636):
Speaking [CharacterModeCommand(True), 'r', EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (21:36:19.524) - winInputHook (28992):
Input: kb(laptop):rightArrow
DEBUG - editableText.EditableText._hasCaretMoved (21:36:19.585) - MainThread (26636):
Caret move detected using bookmarks. Elapsed: 10 ms
IO - inputCore.logTimeSinceInput (21:36:19.588) - MainThread (26636):
0.064 sec since input
IO - speech.speak (21:36:19.588) - MainThread (26636):
Speaking [CharacterModeCommand(True), 'a', EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (21:36:19.794) - winInputHook (28992):
Input: kb(laptop):rightArrow
DEBUG - editableText.EditableText._hasCaretMoved (21:36:19.830) - MainThread (26636):
Caret move detected using bookmarks. Elapsed: 10 ms
IO - inputCore.logTimeSinceInput (21:36:19.832) - MainThread (26636):
0.038 sec since input
IO - speech.speak (21:36:19.832) - MainThread (26636):
Speaking [CharacterModeCommand(True), 'c', EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (21:36:20.044) - winInputHook (28992):
Input: kb(laptop):rightArrow
DEBUG - editableText.EditableText._hasCaretMoved (21:36:20.084) - MainThread (26636):
Caret move detected using bookmarks. Elapsed: 0 ms
IO - inputCore.logTimeSinceInput (21:36:20.086) - MainThread (26636):
0.042 sec since input
IO - speech.speak (21:36:20.087) - MainThread (26636):
Speaking [CharacterModeCommand(True), 't', EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (21:36:20.339) - winInputHook (28992):
Input: kb(laptop):rightArrow
DEBUG - editableText.EditableText._hasCaretMoved (21:36:20.382) - MainThread (26636):
Caret move detected using bookmarks. Elapsed: 10 ms
IO - inputCore.logTimeSinceInput (21:36:20.385) - MainThread (26636):
0.046 sec since input
IO - speech.speak (21:36:20.385) - MainThread (26636):
Speaking [CharacterModeCommand(True), 'i', EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (21:36:20.608) - winInputHook (28992):

akash07k commented 4 years ago

Hi bro, Just choose "Restart with addons disabled" in the NVDA exit dialogue box. Then, once NVDA restarts, go to NVDA settings>General Settings>Logging level combo box. Choose debug from there. After it, Go to NVDA Settings>Advanced>Check the checkbox for revealing the advanced settings, Now, tab to the debug "Debug logging" group and do right arrow there and find the option of "Time since input", check it nd hit ok. You'll be good to go

akash07k commented 4 years ago

@feerrenrut Please find the log attached where I've tested with notepad. It is not laggy at all and works wonderfully. NVDA_Logs_Notepad.txt

Neurrone commented 4 years ago

Thanks @akash07k, I'll try this on my machine which always has this issue tomorrow at work.

akash07k commented 4 years ago

Ok. :-)

Thanks @akash07k, I'll try this on my machine which always has this issue tomorrow at work.

feerrenrut commented 4 years ago

Thanks @akash07k, here is the section of the log I have compared:

Input: kb(laptop):downArrow
DEBUG - editableText.EditableText._hasCaretMoved (20:23:33.133) - MainThread (816):
Caret move detected using event. Elapsed: 0 ms
IO - inputCore.logTimeSinceInput (20:23:33.141) - MainThread (816):
0.060 sec since input
IO - speech.speak (20:23:33.142) - MainThread (816):
Speaking ["I'm testing with notepad\r\n"]
IO - inputCore.InputManager.executeGesture (20:23:34.176) - winInputHook (5208):
Input: kb(laptop):downArrow
DEBUG - editableText.EditableText._hasCaretMoved (20:23:34.213) - MainThread (816):
Caret move detected using event. Elapsed: 0 ms
IO - inputCore.logTimeSinceInput (20:23:34.222) - MainThread (816):
0.046 sec since input
IO - speech.speak (20:23:34.223) - MainThread (816):
Speaking ["It's not laagy at all\r\n"]
IO - inputCore.InputManager.executeGesture (20:23:35.198) - winInputHook (5208):
Input: kb(laptop):downArrow
DEBUG - editableText.EditableText._hasCaretMoved (20:23:35.247) - MainThread (816):
Caret move detected using event. Elapsed: 0 ms
IO - inputCore.logTimeSinceInput (20:23:35.256) - MainThread (816):
0.058 sec since input
IO - speech.speak (20:23:35.256) - MainThread (816):
Speaking ["It's not laggy at all.\r\n"]
IO - inputCore.InputManager.executeGesture (20:23:36.171) - winInputHook (5208):
Input: kb(laptop):downArrow
DEBUG - editableText.EditableText._hasCaretMoved (20:23:36.209) - MainThread (816):
Caret move detected using event. Elapsed: 0 ms
IO - inputCore.logTimeSinceInput (20:23:36.217) - MainThread (816):
0.046 sec since input
IO - speech.speak (20:23:36.218) - MainThread (816):
Speaking ['Wow\r\n']
IO - inputCore.InputManager.executeGesture (20:23:36.767) - winInputHook (5208):
Input: kb(laptop):downArrow
DEBUG - editableText.EditableText._hasCaretMoved (20:23:36.808) - MainThread (816):
Caret move detected using event. Elapsed: 0 ms
IO - inputCore.logTimeSinceInput (20:23:36.818) - MainThread (816):
0.051 sec since input
IO - speech.speak (20:23:36.818) - MainThread (816):
Speaking ['What a wonderful expereience!\r\n']

This seems to average about 50 ms between input and speaking.

akash07k commented 4 years ago

Hmm, Don't you find VS Code very laggy as compared to Notepad? Have you checked the section of the VS Code log section where I've typed the code? If you want, then I can generate a new log also I don't know what is causing this lag in VS Code in many machines. Are you also able to reproduce it?

Thanks @akash07k, here is the section of the log I have compared:

Input: kb(laptop):downArrow
DEBUG - editableText.EditableText._hasCaretMoved (20:23:33.133) - MainThread (816):
Caret move detected using event. Elapsed: 0 ms
IO - inputCore.logTimeSinceInput (20:23:33.141) - MainThread (816):
0.060 sec since input
IO - speech.speak (20:23:33.142) - MainThread (816):
Speaking ["I'm testing with notepad\r\n"]
IO - inputCore.InputManager.executeGesture (20:23:34.176) - winInputHook (5208):
Input: kb(laptop):downArrow
DEBUG - editableText.EditableText._hasCaretMoved (20:23:34.213) - MainThread (816):
Caret move detected using event. Elapsed: 0 ms
IO - inputCore.logTimeSinceInput (20:23:34.222) - MainThread (816):
0.046 sec since input
IO - speech.speak (20:23:34.223) - MainThread (816):
Speaking ["It's not laagy at all\r\n"]
IO - inputCore.InputManager.executeGesture (20:23:35.198) - winInputHook (5208):
Input: kb(laptop):downArrow
DEBUG - editableText.EditableText._hasCaretMoved (20:23:35.247) - MainThread (816):
Caret move detected using event. Elapsed: 0 ms
IO - inputCore.logTimeSinceInput (20:23:35.256) - MainThread (816):
0.058 sec since input
IO - speech.speak (20:23:35.256) - MainThread (816):
Speaking ["It's not laggy at all.\r\n"]
IO - inputCore.InputManager.executeGesture (20:23:36.171) - winInputHook (5208):
Input: kb(laptop):downArrow
DEBUG - editableText.EditableText._hasCaretMoved (20:23:36.209) - MainThread (816):
Caret move detected using event. Elapsed: 0 ms
IO - inputCore.logTimeSinceInput (20:23:36.217) - MainThread (816):
0.046 sec since input
IO - speech.speak (20:23:36.218) - MainThread (816):
Speaking ['Wow\r\n']
IO - inputCore.InputManager.executeGesture (20:23:36.767) - winInputHook (5208):
Input: kb(laptop):downArrow
DEBUG - editableText.EditableText._hasCaretMoved (20:23:36.808) - MainThread (816):
Caret move detected using event. Elapsed: 0 ms
IO - inputCore.logTimeSinceInput (20:23:36.818) - MainThread (816):
0.051 sec since input
IO - speech.speak (20:23:36.818) - MainThread (816):
Speaking ['What a wonderful expereience!\r\n']

This seems to average about 50 ms between input and speaking.

Neurrone commented 4 years ago

Found the section of @akash07k's log that demonstrates this horrendous lag, starting from line 220.

Input: kb(laptop):e
IO - inputCore.logTimeSinceInput (23:40:12.471) - MainThread (8528):
0.151 sec since input
IO - speech.speak (23:40:12.471) - MainThread (8528):
Speaking ['Suggest', 'list']
IO - inputCore.logTimeSinceInput (23:40:12.479) - MainThread (8528):
0.159 sec since input
IO - speech.speak (23:40:12.479) - MainThread (8528):
Speaking ['list item']
DEBUGWARNING - NVDAObjects.IAccessible.IAccessible._get_IA2States (23:40:12.533) - MainThread (8528):
could not get IAccessible2 states
Traceback (most recent call last):
  File "NVDAObjects\IAccessible\__init__.pyc", line 1626, in _get_IA2States
  File "comtypesMonkeyPatches.pyc", line 26, in __call__
_ctypes.COMError: (-2147467259, 'Unspecified error', (None, None, None, 0, None))
DEBUGWARNING - NVDAObjects.IAccessible.IAccessible._get_IA2Attributes (23:40:12.534) - MainThread (8528):
IAccessibleObject.attributes COMError (-2147467259, 'Unspecified error', (None, None, None, 0, None))
DEBUGWARNING - NVDAObjects.IAccessible.IAccessible._get_IAccessibleRole (23:40:12.535) - MainThread (8528):
accRole failed: (-2147467259, 'Unspecified error', (None, None, None, 0, None))
IO - inputCore.logTimeSinceInput (23:40:12.536) - MainThread (8528):
0.216 sec since input
IO - speech.speak (23:40:12.536) - MainThread (8528):
Speaking [CharacterModeCommand(True), 'e', EndUtteranceCommand()]
IO - inputCore.logTimeSinceInput (23:40:12.544) - MainThread (8528):
0.224 sec since input
IO - speech.speak (23:40:12.545) - MainThread (8528):
Speaking ['testing', '1 of 2']
DEBUG - speech.manager.SpeechManager._handleIndex (23:40:12.545) - MainThread (8528):
Unknown index 187, speech probably cancelled from main thread.
IO - inputCore.InputManager.executeGesture (23:40:12.772) - winInputHook (1656):
Input: kb(laptop):s
DEBUGWARNING - NVDAObjects.IAccessible.IAccessible._get_IA2States (23:40:12.947) - MainThread (8528):
could not get IAccessible2 states
Traceback (most recent call last):
  File "NVDAObjects\IAccessible\__init__.pyc", line 1626, in _get_IA2States
  File "comtypesMonkeyPatches.pyc", line 26, in __call__
_ctypes.COMError: (-2147467259, 'Unspecified error', (None, None, None, 0, None))
DEBUGWARNING - NVDAObjects.IAccessible.IAccessible._get_IA2Attributes (23:40:12.948) - MainThread (8528):
IAccessibleObject.attributes COMError (-2147467259, 'Unspecified error', (None, None, None, 0, None))
DEBUGWARNING - NVDAObjects.IAccessible.IAccessible._get_IAccessibleRole (23:40:12.950) - MainThread (8528):
accRole failed: (-2147467259, 'Unspecified error', (None, None, None, 0, None))
IO - inputCore.logTimeSinceInput (23:40:12.950) - MainThread (8528):
0.178 sec since input
IO - speech.speak (23:40:12.950) - MainThread (8528):
Speaking [CharacterModeCommand(True), 's', EndUtteranceCommand()]
DEBUG - speech.manager.SpeechManager._handleIndex (23:40:12.951) - MainThread (8528):
Unknown index 191, speech probably cancelled from main thread.
IO - inputCore.logTimeSinceInput (23:40:12.960) - MainThread (8528):
0.188 sec since input
IO - speech.speak (23:40:12.960) - MainThread (8528):
Speaking ['testing', '1 of 1']
IO - inputCore.InputManager.executeGesture (23:40:13.189) - winInputHook (1656):

LeonarddeR commented 4 years ago

@akash07k before going any further with this, are you able to reproduce this on the insider preview of VS Code? It switched from Electron 7 to ELectron 9, with a way newer version of chromium under the hood. Also, are you able to share a code snippet that causes this horrendous lag?

akash07k commented 4 years ago

@leonardder I'm able to reproduce this painful lag on both, the stable and the insider builds of VS Code. Also, there's no specific code snippet which causes the lag. In fact, every code with every programming language causes this. No matter it is typing the code or navigating. Although, typing is much more laggy. Currently, I've tried it on various machines with both, the stable and insider builds of VS code as well as Stable and Alpha builds of NVDA.

@akash07k before going any further with this, are you able to reproduce this on the insider preview of VS Code? It switched from Electron 7 to ELectron 9, with a way newer version of chromium under the hood. Also, are you able to share a code snippet that causes this horrendous lag?

Neurrone commented 4 years ago

Some logs on my machine which reproduce this.

Typing enter, then pressing the up arrow key to review the text:

Input: kb(laptop):enter
DEBUG - editableText.EditableText._hasCaretMoved (17:10:56.650) - MainThread (1724):
Caret move detected using bookmarks. Elapsed: 50 ms
IO - inputCore.InputManager.executeGesture (17:10:58.104) - winInputHook (10728):
Input: kb(laptop):upArrow
DEBUG - editableText.EditableText._hasCaretMoved (17:10:58.320) - MainThread (1724):
Caret move detected using bookmarks. Elapsed: 20 ms
IO - inputCore.logTimeSinceInput (17:10:58.326) - MainThread (1724):
0.222 sec since input
IO - speech.speak (17:10:58.326) - MainThread (1724):
Speaking [LangChangeCommand ('en_US'), '// must return empty object here\n']
IO - inputCore.InputManager.executeGesture (17:10:59.119) - winInputHook (10728):
Input: kb(laptop):downArrow
DEBUG - editableText.EditableText._hasCaretMoved (17:10:59.185) - MainThread (1724):
Caret move detected using bookmarks. Elapsed: 20 ms
IO - inputCore.logTimeSinceInput (17:10:59.192) - MainThread (1724):
0.073 sec since input
IO - speech.speak (17:10:59.192) - MainThread (1724):
Speaking [LangChangeCommand ('en_US'), 'blank']

Typing "// this is laggy" in Vs Code, notice some of the spikes which are over half a second!

IO - inputCore.InputManager.executeGesture (17:11:00.229) - winInputHook (10728):
Input: kb(laptop):/
IO - inputCore.logTimeSinceInput (17:11:00.257) - MainThread (1724):
0.029 sec since input
IO - speech.speak (17:11:00.257) - MainThread (1724):
Speaking [LangChangeCommand ('en_US'), 'slash', EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (17:11:02.326) - winInputHook (10728):
Input: kb(laptop):/
IO - inputCore.InputManager.executeGesture (17:11:03.262) - winInputHook (10728):
Input: kb(laptop):/
IO - inputCore.logTimeSinceInput (17:11:03.292) - MainThread (1724):
0.030 sec since input
IO - speech.speak (17:11:03.292) - MainThread (1724):
Speaking [LangChangeCommand ('en_US'), 'slash', EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (17:11:03.657) - winInputHook (10728):
Input: kb(laptop):space
IO - inputCore.logTimeSinceInput (17:11:03.673) - MainThread (1724):
0.016 sec since input
IO - speech.speak (17:11:03.674) - MainThread (1724):
Speaking [LangChangeCommand ('en_US'), 'slash', EndUtteranceCommand()]
DEBUG - speech.manager.SpeechManager._handleIndex (17:11:03.674) - MainThread (1724):
Unknown index 3163, speech probably cancelled from main thread.
IO - inputCore.logTimeSinceInput (17:11:03.984) - MainThread (1724):
0.327 sec since input
IO - speech.speak (17:11:03.984) - MainThread (1724):
Speaking [LangChangeCommand ('en_US'), 'space', EndUtteranceCommand()]
DEBUG - speech.manager.SpeechManager._handleIndex (17:11:03.985) - MainThread (1724):
Unknown index 3165, speech probably cancelled from main thread.
IO - inputCore.InputManager.executeGesture (17:11:04.768) - winInputHook (10728):
Input: kb(laptop):t
IO - inputCore.logTimeSinceInput (17:11:04.807) - MainThread (1724):
0.039 sec since input
IO - speech.speak (17:11:04.807) - MainThread (1724):
Speaking [CharacterModeCommand(True), LangChangeCommand ('en_US'), 't', EndUtteranceCommand()]
DEBUG - speech.manager.SpeechManager._handleIndex (17:11:04.808) - MainThread (1724):
Unknown index 3168, speech probably cancelled from main thread.
IO - inputCore.InputManager.executeGesture (17:11:05.431) - winInputHook (10728):
Input: kb(laptop):h
IO - inputCore.logTimeSinceInput (17:11:06.122) - MainThread (1724):
0.691 sec since input
IO - speech.speak (17:11:06.122) - MainThread (1724):
Speaking [CharacterModeCommand(True), LangChangeCommand ('en_US'), 'h', EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (17:11:06.793) - winInputHook (10728):
Input: kb(laptop):i
IO - inputCore.logTimeSinceInput (17:11:07.198) - MainThread (1724):
0.405 sec since input
IO - speech.speak (17:11:07.198) - MainThread (1724):
Speaking [CharacterModeCommand(True), LangChangeCommand ('en_US'), 'i', EndUtteranceCommand()]
DEBUG - speech.manager.SpeechManager._handleIndex (17:11:07.199) - MainThread (1724):
Unknown index 3172, speech probably cancelled from main thread.
IO - inputCore.InputManager.executeGesture (17:11:07.795) - winInputHook (10728):
Input: kb(laptop):s
IO - inputCore.logTimeSinceInput (17:11:07.818) - MainThread (1724):
0.023 sec since input
IO - speech.speak (17:11:07.818) - MainThread (1724):
Speaking [CharacterModeCommand(True), LangChangeCommand ('en_US'), 's', EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (17:11:08.361) - winInputHook (10728):
Input: kb(laptop):space
IO - speech.speakTypedCharacters (17:11:08.407) - MainThread (1724):
typed word: this
IO - inputCore.logTimeSinceInput (17:11:08.408) - MainThread (1724):
0.047 sec since input
IO - speech.speak (17:11:08.408) - MainThread (1724):
Speaking [LangChangeCommand ('en_US'), 'space', EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (17:11:08.722) - winInputHook (10728):
Input: kb(laptop):i
IO - inputCore.logTimeSinceInput (17:11:08.736) - MainThread (1724):
0.014 sec since input
IO - speech.speak (17:11:08.736) - MainThread (1724):
Speaking [CharacterModeCommand(True), LangChangeCommand ('en_US'), 'i', EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (17:11:09.492) - winInputHook (10728):
Input: kb(laptop):s
IO - inputCore.logTimeSinceInput (17:11:09.737) - MainThread (1724):
0.245 sec since input
IO - speech.speak (17:11:09.738) - MainThread (1724):
Speaking [CharacterModeCommand(True), LangChangeCommand ('en_US'), 's', EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (17:11:10.178) - winInputHook (10728):
Input: kb(laptop):space
IO - speech.speakTypedCharacters (17:11:10.869) - MainThread (1724):
typed word: is
IO - inputCore.logTimeSinceInput (17:11:10.869) - MainThread (1724):
0.691 sec since input
IO - speech.speak (17:11:10.869) - MainThread (1724):
Speaking [LangChangeCommand ('en_US'), 'space', EndUtteranceCommand()]
DEBUG - speech.manager.SpeechManager._handleIndex (17:11:10.870) - MainThread (1724):
Unknown index 3182, speech probably cancelled from main thread.
IO - inputCore.InputManager.executeGesture (17:11:11.265) - winInputHook (10728):
Input: kb(laptop):l
IO - inputCore.logTimeSinceInput (17:11:11.678) - MainThread (1724):
0.413 sec since input
IO - speech.speak (17:11:11.679) - MainThread (1724):
Speaking [CharacterModeCommand(True), LangChangeCommand ('en_US'), 'l', EndUtteranceCommand()]
DEBUG - speech.manager.SpeechManager._handleIndex (17:11:11.679) - MainThread (1724):
Unknown index 3184, speech probably cancelled from main thread.
IO - inputCore.InputManager.executeGesture (17:11:12.043) - winInputHook (10728):
Input: kb(laptop):a
IO - inputCore.logTimeSinceInput (17:11:12.787) - MainThread (1724):
0.744 sec since input
IO - speech.speak (17:11:12.787) - MainThread (1724):
Speaking [CharacterModeCommand(True), LangChangeCommand ('en_US'), 'a', EndUtteranceCommand()]
DEBUG - speech.manager.SpeechManager._handleIndex (17:11:12.788) - MainThread (1724):
Unknown index 3186, speech probably cancelled from main thread.
IO - inputCore.InputManager.executeGesture (17:11:13.117) - winInputHook (10728):
Input: kb(laptop):g
IO - inputCore.logTimeSinceInput (17:11:13.130) - MainThread (1724):
0.013 sec since input
IO - speech.speak (17:11:13.130) - MainThread (1724):
Speaking [CharacterModeCommand(True), LangChangeCommand ('en_US'), 'g', EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (17:11:13.464) - winInputHook (10728):
Input: kb(laptop):g
IO - inputCore.logTimeSinceInput (17:11:13.467) - MainThread (1724):
0.003 sec since input
IO - speech.speak (17:11:13.467) - MainThread (1724):
Speaking [CharacterModeCommand(True), LangChangeCommand ('en_US'), 'g', EndUtteranceCommand()]
IO - inputCore.InputManager.executeGesture (17:11:13.753) - winInputHook (10728):
Input: kb(laptop):y
IO - inputCore.logTimeSinceInput (17:11:13.812) - MainThread (1724):
0.059 sec since input
IO - speech.speak (17:11:13.812) - MainThread (1724):
Speaking [CharacterModeCommand(True), LangChangeCommand ('en_US'), 'y', EndUtteranceCommand()]

akash07k commented 4 years ago

Hmm, I noticed the maximum delay of 744 MS in your log at one place which is really really a lot and is very painful. I wish this issue could be fixed soon as it is preventing me from effectively coding my projects.

akash07k commented 4 years ago

@MarcoZehe Bro, sorry to ping you on this issue, but I think that you also use VS Code with NVDA? Do you also come across to this problem/Do you also face the same laggyness? Please give your views if possible.

MarcoZehe commented 4 years ago

Yes, I can definitely see the sluggishness, too. Especially when reading line by line or character by character, the current Code Insider build in combination with the current NVDA Alpha build behave very sluggish. When reading a line, and hitting up or down arrow while the synthesizer is still speaking, interruption doesn't happen immediately, but with a delay. The braille display then also only changes lines after a delay, and the new line is read. Single character navigation with left and right arrow also behaves slower than I would expect, and remember from the last time I used VS Code, which was a few weeks ago.

In addition, the laptop starts spinning up its fan to cool the CPU as if under very heavy load. This calms down as soon as I close VS Code again. But it appears that the editor is consuming huge amounts of CPU cycles.

akash07k commented 4 years ago

Ya, you're absolutely right. However, the sluggishness is not there while using JAWS with VS Code. @isidorn Your views on this? Sometimes I too feel that Editor is consuming very heavy CPU cycles. However, it happens very occasionally.

isidorn commented 4 years ago

My view is simple: let's see what the NVDA team says since this does not happen with JAWS and VS Code. As for the difference between 2, 3 weeks ago it is probably due to the Electron 9 update.

akash07k commented 4 years ago

Ok, But I'm having this issue since many versions of VS Code. I think since feb/march I've started using VS Code and since then itself I'm having this issue. So, I don't think that it is due to electron 9 update. However, can you please provide me the link to download previous versions of VS Code? I want to try it with VS code 1.4.0 or less. But let's see what NVDA team says on this

LeonarddeR commented 4 years ago

I opened #11545 as an issue to investigate a potential cause for this. The problem is that I can't reproduce this reliably, at least not on my fat Dell system with 16 gigs of ram. @akash07k I assume you also tested with a clean installation of VS Code, without any extensions active? Don't see how these could impact behavior. I'd also really appreciate a log with the most recent alpha snapshot, as that incorporates #11521 and could show us what the flow of events is. It might be likely that NVDA is flooded with win events when this is happening.

akash07k commented 4 years ago

@leonardder Yes,I've checked with the completely clean installation of VS code too. The issue is still there. Also,, I've provided the logs above, is more log required? Please let me know I've even checked the box for "selective event registration" but still no luck. same lag is there. 👎

I opened #11545 as an issue to investigate a potential cause for this. The problem is that I can't reproduce this reliably, at least not on my fat Dell system with 16 gigs of ram. @akash07k I assume you also tested with a clean installation of VS Code, without any extensions active? Don't see how these could impact behavior. I'd also really appreciate a log with the most recent alpha snapshot, as that incorporates #11521 and could show us what the flow of events is. It might be likely that NVDA is flooded with win events when this is happening.

michaelDCurran commented 4 years ago

When I use VSCode, I experience no more than 60 ms between pressing a key and speaking. Would you be comfortable sharing your nvda.ini config file here so we can see your exact NVDA configuration settings? Also, with the latest NVDA alpha: Can you set your log level to debug, then in NVDA's Advanced settings: check the MSAA checkbox in the debug logging list. Then navigate a bit in VSCode, and share the log again.

akash07k commented 4 years ago

@michaelDCurran Absolutely sure, Please find the log and nvda.ini attached with this comment. This time, I didn't typed and navigated a lot so that the log doesn't grow longer. However, it grew insanely since MSAA logging is also enabled. nvda_ini.txt

NVDA.log Also, I've tried the completely clean installation of NVDA too without modifying the nvda settings, but same lag is observed on all the machines.

When I use VSCode, I experience no more than 60 ms between pressing a key and speaking. Would you be comfortable sharing your nvda.ini config file here so we can see your exact NVDA configuration settings? Also, with the latest NVDA alpha: Can you set your log level to debug, then in NVDA's Advanced settings: check the MSAA checkbox in the debug logging list. Then navigate a bit in VSCode, and share the log again.

akash07k commented 4 years ago

@michaelDCurran @feerrenrut Did you got the time to check the logs?

LeonarddeR commented 4 years ago

Here is a try build. Quick testing on my end revealed that it doesn't seem to help much, though.

akash07k commented 4 years ago

Ya, I tested it, unfortunately, it doesn't help. :( The lag is still the same :( 😢😢😭😭😭😭😭😭

Here is a try build. Quick testing on my end revealed that it doesn't seem to help much, though.

LeonarddeR commented 4 years ago

And, what happens if you use the try build and execute the following into the python console after starting the build?

import editableText
editableText.EditableText._useEvents_maxTimeoutMs = 1000

The default is 10, which means that NVDA no longer relies on events after 10 milisconds as they might be unreliable. This change at runtime ensures that NVDA tries to listen for events for up to 1 second for the rest of the NVDA session.

akash07k commented 4 years ago

Hi @leonardder bro, I tried this now, but no luck. in fact, I feel that lag is increased more. I don't know why. Even I played around with many values after 1000 but no luck. :( 😭😭

And, what happens if you use the try build and execute the following into the python console after starting the build?
import editableText
editableText.EditableText._useEvents_maxTimeoutMs = 1000
The default is 10, which means that NVDA no longer relies on events after 10 milisconds as they might be unreliable. This change at runtime ensures that NVDA tries to listen for events for up to 1 second for the rest of the NVDA session.

LeonarddeR commented 4 years ago

Ah, I'm dropping this idea, than. Using events for caret movement detection won't improve anything here. Actually, when I search for the string Caret move detected using bookmarks, I get reasonable timings. There is also no indication of Caret didn't move before timeout in the log, which indiicates that caret movement detection works acceptable. This means that we've to search in another area.

akash07k commented 4 years ago

Oh. Quite sad then, at least, I got a hope that this issue could be fixed soon by extending the timeout for caret events movements. :(

Ah, I'm dropping this idea, than. Using events for caret movement detection won't improve anything here. Actually, when I search for the string Caret move detected using bookmarks, I get reasonable timings. There is also no indication of Caret didn't move before timeout in the log, which indiicates that caret movement detection works acceptable. This means that we've to search in another area.

akash07k commented 4 years ago

@feerrenrut Any updates on this?

feerrenrut commented 4 years ago

Here is a section from @akash07k's log with over 100ms and includes debug logging for events, starting at line 1922 from the log in this https://github.com/nvaccess/nvda/issues/11533#issuecomment-686437898:

IO - inputCore.InputManager.executeGesture (17:18:58.194) - winInputHook (2004):
Input: kb(laptop):downArrow
DEBUG - nvwave.WavePlayer._isPreferredDeviceOpen (17:18:58.224) - MainThread (14172):
preferred device: Microsoft Sound Mapper current device name: Microsoft Sound Mapper (id: -1)
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (17:18:58.241) - MainThread (14172):
Hook received winEvent: EVENT_OBJECT_LOCATIONCHANGE, window 1442668 (Chrome_WidgetWin_1), objectID OBJID_CARET, childID -4, process 464 (code - insiders), thread 8820
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (17:18:58.243) - MainThread (14172):
Adding winEvent to limiter: EVENT_OBJECT_LOCATIONCHANGE, window 1442668 (Chrome_WidgetWin_1), objectID OBJID_CARET, childID -4, process 464 (code - insiders), thread 8820
DEBUG - IAccessibleHandler.orderedWinEventLimiter.OrderedWinEventLimiter.flushEvents (17:18:58.244) - MainThread (14172):
Emitting winEvent EVENT_OBJECT_LOCATIONCHANGE, window 1442668 (Chrome_WidgetWin_1), objectID OBJID_CARET, childID -4, process 464 (code - insiders), thread 8820
DEBUG - IAccessibleHandler.processGenericWinEvent (17:18:58.245) - MainThread (14172):
Processing generic winEvent: EVENT_OBJECT_LOCATIONCHANGE, window 1442668 (Chrome_WidgetWin_1), objectID OBJID_CARET, childID -4, process 464 (code - insiders)
DEBUG - IAccessibleHandler.processGenericWinEvent (17:18:58.246) - MainThread (14172):
handling winEvent as caret event on focus
DEBUG - IAccessibleHandler.processGenericWinEvent (17:18:58.246) - MainThread (14172):
Directing winEvent to focus object <NVDAObjects.Dynamic_EditableTextWithAutoSelectDetectionEditorIa2WebIAccessible object at 0x032B8AF0>. WinEvent window 1442668 (Chrome_WidgetWin_1), objectID OBJID_CARET, childID -4, process 464 (code - insiders)
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (17:18:58.304) - MainThread (14172):
Hook received winEvent: IA2_EVENT_TEXT_CARET_MOVED, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -1487, process 464 (code - insiders), thread 8820
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (17:18:58.304) - MainThread (14172):
Adding winEvent to limiter: IA2_EVENT_TEXT_CARET_MOVED, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -1487, process 464 (code - insiders), thread 8820
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (17:18:58.304) - MainThread (14172):
Hook received winEvent: EVENT_OBJECT_NAMECHANGE, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -2044, process 464 (code - insiders), thread 8820
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (17:18:58.304) - MainThread (14172):
Adding winEvent to limiter: EVENT_OBJECT_NAMECHANGE, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -2044, process 464 (code - insiders), thread 8820
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (17:18:58.304) - MainThread (14172):
Hook received winEvent: EVENT_OBJECT_NAMECHANGE, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -2030, process 464 (code - insiders), thread 8820
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (17:18:58.304) - MainThread (14172):
Adding winEvent to limiter: EVENT_OBJECT_NAMECHANGE, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -2030, process 464 (code - insiders), thread 8820
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (17:18:58.304) - MainThread (14172):
Hook received winEvent: EVENT_OBJECT_LOCATIONCHANGE, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -2031, process 464 (code - insiders), thread 8820
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (17:18:58.304) - MainThread (14172):
locationChange for something other than the caret. Dropping winEvent EVENT_OBJECT_LOCATIONCHANGE, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -2031, process 464 (code - insiders), thread 8820
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (17:18:58.304) - MainThread (14172):
Hook received winEvent: EVENT_OBJECT_LOCATIONCHANGE, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -2047, process 464 (code - insiders), thread 8820
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (17:18:58.306) - MainThread (14172):
locationChange for something other than the caret. Dropping winEvent EVENT_OBJECT_LOCATIONCHANGE, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -2047, process 464 (code - insiders), thread 8820
DEBUG - IAccessibleHandler.orderedWinEventLimiter.OrderedWinEventLimiter.flushEvents (17:18:58.306) - MainThread (14172):
Emitting winEvent IA2_EVENT_TEXT_CARET_MOVED, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -1487, process 464 (code - insiders), thread 8820
DEBUG - IAccessibleHandler.orderedWinEventLimiter.OrderedWinEventLimiter.flushEvents (17:18:58.306) - MainThread (14172):
Emitting winEvent EVENT_OBJECT_NAMECHANGE, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -2044, process 464 (code - insiders), thread 8820
DEBUG - IAccessibleHandler.orderedWinEventLimiter.OrderedWinEventLimiter.flushEvents (17:18:58.306) - MainThread (14172):
Emitting winEvent EVENT_OBJECT_NAMECHANGE, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -2030, process 464 (code - insiders), thread 8820
DEBUG - IAccessibleHandler.processGenericWinEvent (17:18:58.306) - MainThread (14172):
Processing generic winEvent: IA2_EVENT_TEXT_CARET_MOVED, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -1487, process 464 (code - insiders)
DEBUG - IAccessibleHandler.winEventToNVDAEvent (17:18:58.307) - MainThread (14172):
Creating NVDA event from winEvent: IA2_EVENT_TEXT_CARET_MOVED, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -1487, process 464 (code - insiders), use cache True
DEBUG - IAccessibleHandler.winEventToNVDAEvent (17:18:58.307) - MainThread (14172):
winEvent mapped to NVDA event: caret
DEBUG - IAccessibleHandler.winEventToNVDAEvent (17:18:58.307) - MainThread (14172):
Fetched existing NVDAObject <NVDAObjects.Dynamic_EditableTextWithAutoSelectDetectionEditorIa2WebIAccessible object at 0x032B8AF0> from liveNVDAObjectTable for winEvent window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -1487, process 464 (code - insiders)
DEBUG - IAccessibleHandler.winEventToNVDAEvent (17:18:58.307) - MainThread (14172):
Successfully created NVDA event caret for <NVDAObjects.Dynamic_EditableTextWithAutoSelectDetectionEditorIa2WebIAccessible object at 0x032B8AF0> from winEvent IA2_EVENT_TEXT_CARET_MOVED, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -1487, process 464 (code - insiders)
DEBUG - IAccessibleHandler.processGenericWinEvent (17:18:58.307) - MainThread (14172):
Directing winEvent to focus object <NVDAObjects.Dynamic_EditableTextWithAutoSelectDetectionEditorIa2WebIAccessible object at 0x032B8AF0>. WinEvent window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -1487, process 464 (code - insiders)
DEBUG - IAccessibleHandler.processGenericWinEvent (17:18:58.307) - MainThread (14172):
Processing generic winEvent: EVENT_OBJECT_NAMECHANGE, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -2044, process 464 (code - insiders)
DEBUG - IAccessibleHandler.winEventToNVDAEvent (17:18:58.308) - MainThread (14172):
Creating NVDA event from winEvent: EVENT_OBJECT_NAMECHANGE, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -2044, process 464 (code - insiders), use cache True
DEBUG - IAccessibleHandler.winEventToNVDAEvent (17:18:58.308) - MainThread (14172):
winEvent mapped to NVDA event: nameChange
DEBUG - IAccessibleHandler.winEventToNVDAEvent (17:18:58.316) - MainThread (14172):
Successfully created NVDA event nameChange for <NVDAObjects.Dynamic_ButtonIa2WebIAccessible object at 0x07F2F850> from winEvent EVENT_OBJECT_NAMECHANGE, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -2044, process 464 (code - insiders)
DEBUG - IAccessibleHandler.processGenericWinEvent (17:18:58.317) - MainThread (14172):
Processing generic winEvent: EVENT_OBJECT_NAMECHANGE, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -2030, process 464 (code - insiders)
DEBUG - IAccessibleHandler.winEventToNVDAEvent (17:18:58.317) - MainThread (14172):
Creating NVDA event from winEvent: EVENT_OBJECT_NAMECHANGE, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -2030, process 464 (code - insiders), use cache True
DEBUG - IAccessibleHandler.winEventToNVDAEvent (17:18:58.317) - MainThread (14172):
winEvent mapped to NVDA event: nameChange
DEBUG - IAccessibleHandler.winEventToNVDAEvent (17:18:58.324) - MainThread (14172):
Successfully created NVDA event nameChange for <NVDAObjects.IAccessible.ia2Web.Ia2Web object at 0x07F2F530> from winEvent EVENT_OBJECT_NAMECHANGE, window 592742 (Chrome_RenderWidgetHostHWND), objectID OBJID_CLIENT, childID -2030, process 464 (code - insiders)
DEBUG - editableText.EditableText._hasCaretMoved (17:18:58.325) - MainThread (14172):
Caret move detected using bookmarks. Elapsed: 30 ms
IO - inputCore.logTimeSinceInput (17:18:58.329) - MainThread (14172):
0.135 sec since input
IO - speech.speak (17:18:58.329) - MainThread (14172):
Speaking ['    downloadStart: true\n']

akash07k commented 4 years ago

@feerrenrut Were you able to partially or fully pin point the underlying cause of this lag from the logs?

akash07k commented 4 years ago

I think this issue should be targeted for this upcoming NVDA release and the fix should be targeted for the beta as it is quite a critical issue for VS Code users. @feerrenrut @leonardder @michaelDCurran

LeonarddeR commented 4 years ago

@akash07k to While we really acknowledge your struggling with this issue, is it still very hard to do something with it only based on logging. We really need to have the steps to reproduce this. VS Code can be a bit sluggish on my system, but certainly not to the extend you're describing. I'm also seeing many messages about list items (e.g. intellisense) in your logging. How is performance when you use a plain text document in VS Code? Is it also sluggish then?

akash07k commented 4 years ago

@leonardder Bro, the steps to reproduce are already there. what else should I provide? I've already provided very detailed steps to reproduce in my initial issue description and I feel that it should suffice the purpose. And yes, it is sluggish with plain text too.

@akash07k to While we really acknowledge your struggling with this issue, is it still very hard to do something with it only based on logging. We really need to have the steps to reproduce this. VS Code can be a bit sluggish on my system, but certainly not to the extend you're describing. I'm also seeing many messages about list items (e.g. intellisense) in your logging. How is performance when you use a plain text document in VS Code? Is it also sluggish then?

LeonarddeR commented 4 years ago

@akash07k commented on Sep 9, 2020, 8:43 PM GMT+2:

Bro, the steps to reproduce are already there. what else should I provide?

You're correct, there are steps to reproduce, but they don't reproduce the actual issue on all systems, at least not on mine. You're talking about this being reproducible in plain text document as well, but here, VS Code is pretty fast in them. @isidorn: is there a way to run VS Code in the browser without setting up a full dev environment? I wonder how Code behaves in Chrome and may be other browsers as well on @akash07k's system.

akash07k commented 4 years ago

@leonardder Yes, but other people also confirmed that they are facing this same lag like @Neurrone @MarcoZehe So, it clearly shows that something is there at NVDA side since this problem is not being faced with JAWS. Also, may be it can be not reproducible on your system due to some hardware specifications. however, it shouldn't be the case as I've checked with multiple machines.

@akash07k commented on Sep 9, 2020, 8:43 PM GMT+2:

Bro, the steps to reproduce are already there. what else should I provide?

You're correct, there are steps to reproduce, but they don't reproduce the actual issue on all systems, at least not on mine. You're talking about this being reproducible in plain text document as well, but here, VS Code is pretty fast in them. @isidorn: is there a way to run VS Code in the browser without setting up a full dev environment? I wonder how Code behaves in Chrome and may be other browsers as well on @akash07k's system.

nvaccess / nvda