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

[akash07k]

Steps to reproduce:

1. Open Visual studio code.
2. Open a file or directory containing any text files in it such as a javascript/python project.
3. Go to the editor.
4. try navigating the text/code via arrow keys.
5. Now try typing some code in the editor quickly.
6. It will be observed that in both 4th and 5th point, NVDA laggs a lot while navigating and typing the code in the editor.
7. Now repeat the same thing with Notepad plus plus or another text editor.
8. 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]

@feerrenrut
Bro, your views/comments on this?

[feerrenrut]

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]

Unsub

On 8/31/20, Akash Kakkar [e-mail] 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]

cc @isidorn

[akash07k]

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]

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]

@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]

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]

@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]

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]

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

[akash07k]

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]

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]

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

[Neurrone]

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]

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]

@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]

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

[akash07k]

Ok. :-)

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

[feerrenrut]

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]

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]

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]

@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]

@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]

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]

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]

@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]

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]

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]

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]

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]

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]

@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]

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]

@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]

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

[leonardder]

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

[akash07k]

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]

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]

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]

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]

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]

@feerrenrut
Any updates on this?

[feerrenrut]

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]

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

[akash07k]

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]

@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]

@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]

@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]

@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.

[XLTechie]

Could choice of synth be contributing to this?

I have not read the logs in depth because I don't use VS Code and can't
replicate anything, but the thought occurred.

[leonardder]

Could you also have a try with this try build as a portable copy? This is the build associated with pr #11437. You should enable the Only process MSAA/IA2 &events for specific objects (focus, etc.) option in NVDA"s advanced settings.

[akash07k]

@leonardder
I've tested this try build and It may be my illusion, but I feel some difference in laggyness.
Laggyness is somewhat reduced with this try build by checking that checkbox.
I've only done quick testing, may be it is my illusion and the situation is still the same.
@MarcoZehe
@Neurrone
Can you guys also please verify?

Could you also have a try with this try build as a portable copy? This is the build associated with pr #11437. You should enable the Only process MSAA/IA2 &events for specific objects (focus, etc.) option in NVDA"s advanced settings.

[leonardder]

@akash07k Are you saying that, even though lag might be reduced somewhat, it is still significant?

[akash07k]

@leonardder
No, as of now, I'm not feeling very significant lag.
May be I should test it somewhat more.
Can you please rebase this try build on the latest master branch?
May be I can feel more difference due to latest fixes included related to logging and all stuff?

@akash07k Are you saying that, even though lag might be reduced somewhat, it is still significant?

[akash07k]

No, it is not TTS specific.
I've tried with many TTS engines but the same issue.

Could choice of synth be contributing to this? I have not read the logs in depth because I don't use VS Code and can't replicate anything, but the thought occurred.

[beqabeqa473]

i tested vscode stable and insider builds and yes, i can confirm micro lags but they are not significant.
i tried to type continuously for a half minute and navigate through plain text.

[akash07k]

I'm testing it more, untill now felt that code typing is little bit fine, but sometimes significant lag is there while navigating the code.
But not always as previous.
Will test more, I hope it can permanently fix the issue

i tested vscode stable and insider builds and yes, i can confirm micro lags but they are not significant.
i tried to type continuously for a half minute and navigate through plain text.

[feerrenrut]

Looking at the log in https://github.com/nvaccess/nvda/issues/11533#issuecomment-688421777 again, note that there is 100ms between when NVDA detects the input and when Hook received winEvent: IA2_EVENT_TEXT_CARET_MOVED (the entry point for this win event into NVDA`. This accounts for the majority of 130ms of recorded delay. Unfortunately, this is outside of NVDA's control, and likely is due to how vsCode treats the keyboard input event. If these events are received faster in a standard HTML edit field in Chrome, that might help to rule out the chromium part.

This raises the question of why the performance is different in JAWS. This is hard to say, since we can't inspect the approach it takes. It's not really helpful to speculate on this. It might be helpful to look back at older versions of NVDA and see if the performance with the latest vsCode was better, and also try older versions of vsCode with the current version of NVDA (and update the issue description with the results since this issue is getting very long and hard to follow). This can help to identify if somethings has been introduced that causes a performance problem

Please note: The recorded time does not take into account the time it takes for NVDA to receive the keyboard input in the first place (which could be delayed due to system load for instance). It also does not take into account how long it takes a synthesizer to produce the audio, and get it played by nvWave, each of these steps could add to the perceived delay. That said, 100ms of delay alone is significant enough to be annoying. While it's not important for the observation I have made here, it may be useful to be aware of.

[akash07k]

@isidorn
Can you please reply below comment?
Also, @feerrenrut
Finding the older versions of VS Code is not easily possible as I tried a lot but couldn't find any.
Also, I'm following all the releases of VS code as well as releases of NVDA since feb/march 2020, and the issue is still the same since then.
What should we do in this case?
If we talk about JAWS part, then I don't feel that they may have done something special to handle this.
:(

Looking at the log in #11533 (comment) again, note that there is 100ms between when NVDA detects the input and when Hook received winEvent: IA2_EVENT_TEXT_CARET_MOVED (the entry point for this win event into NVDA`. This accounts for the majority of 130ms of recorded delay. Unfortunately, this is outside of NVDA's control, and likely is due to how vsCode treats the keyboard input event. If these events are received faster in a standard HTML edit field in Chrome, that might help to rule out the chromium part.

This raises the question of why the performance is different in JAWS. This is hard to say, since we can't inspect the approach it takes. It's not really helpful to speculate on this. It might be helpful to look back at older versions of NVDA and see if the performance with the latest vsCode was better, and also try older versions of vsCode with the current version of NVDA (and update the issue description with the results since this issue is getting very long and hard to follow). This can help to identify if somethings has been introduced that causes a performance problem

Please note: The recorded time does not take into account the time it takes for NVDA to receive the keyboard input in the first place (which could be delayed due to system load for instance). It also does not take into account how long it takes a synthesizer to produce the audio, and get it played by nvWave, each of these steps could add to the perceived delay. That said, 100ms of delay alone is significant enough to be annoying. While it's not important for the observation I have made here, it may be useful to be aware of.

[leonardder]

One thing I experience myself is that when indentation tones are enabled, the tones are very late with playing. On a line with only the word test, for example, the indentation beep plays after the speech said the word test. This is espeak, rate 35, rate boost on.

[leonardder]

This case actually reminds me of a case @feerrenrut and I met somewhere where the power plan of the system was set to power saving. When I do that on my system, indeed, VS Code gets far from usable, but I have to say that this applies to many other applications on my system, even normal usage of Windows Explorer.
It would be helpful if you could explore the impact of changing your power plan, setting it to high performance, for example.

[MarcoZehe]

I have set my laptop to high performance mode when connected to a power outlet, and still see the lag. So at least for me, it's not that. :-(

[akash07k]

No bro, I too use my laptop to high power plan as I'm always connected to the power outlet.
I never use it on power save mode.

This case actually reminds me of a case @feerrenrut and I met somewhere where the power plan of the system was set to power saving. When I do that on my system, indeed, VS Code gets far from usable, but I have to say that this applies to many other applications on my system, even normal usage of Windows Explorer.
It would be helpful if you could explore the impact of changing your power plan, setting it to high performance, for example.

[akash07k]

@MarcoZehe
Bro, can you please report your findings with the try build which @leonardder provided some hours ago in previous comments?

I have set my laptop to high performance mode when connected to a power outlet, and still see the lag. So at least for me, it's not that. :-(

[akash07k]

Hmm, there's certainly something wrong going on at NVDA side while handling VS code.

One thing I experience myself is that when indentation tones are enabled, the tones are very late with playing. On a line with only the word test, for example, the indentation beep plays after the speech said the word test. This is espeak, rate 35, rate boost on.

[brunoprietog]

One thing I experience myself is that when indentation tones are enabled, the tones are very late with playing. On a line with only the word test, for example, the indentation beep plays after the speech said the word test. This is espeak, rate 35, rate boost on.

I feel very identified with this, it's very annoying

[MarcoZehe]

OK, here are my findings:

1. With a regular current NVDA alpha snapshot, and an updated Code Insiders build, including extensions, I no longer experience the lag that I experienced a few days ago. So for me, this has been reduced to an intermittent problem.
2. however, using that try build, and turning on the MSAA event ignoring functionality, turned navigation responsiveness up a notch, meaning for me, now navigating by character, word or line, is super snappy, not just normal, but really snappy.

Hope this helps.

[leonardder]

I just stumbled upon the VS Code online play ground, which was exactly the thing I was looking for.

@akash07k Would you be able to test this play ground in the browser, preferably both Firefox and Chrome?

[beqabeqa473]

@leonardder i've tested in browsers and observed the following behaviour.

nvda latest alpha

in chrome - i can observe microlags when navigating up/down arrows on long lines.
typing fast also have microlags.

in firefox: microlags still exist when navigating with up and down arros, but typing fast makes no lags.

[akash07k]

@leonardder
My experience is also same as Beqa, however, I get microlaggs in typing in firefox too.

I just stumbled upon the VS Code online play ground, which was exactly the thing I was looking for.

@akash07k Would you be able to test this play ground in the browser, preferably both Firefox and Chrome?

[akash07k]

@leonardder
Also, same as before, with JAWS, no lags at all. This is really sad. 👍

@leonardder
My experience is also same as Beqa, however, I get microlaggs in typing in firefox too.

I just stumbled upon the VS Code online play ground, which was exactly the thing I was looking for.
@akash07k Would you be able to test this play ground in the browser, preferably both Firefox and Chrome?

[MarcoZehe]

The lags are certainly not as present in the browser as they are in the Electron app, when present at all for me. However, I still notice a slight improvement, in Chrome and Firefox, with this MSAA PR. So it is worth pursuing I think.

[akash07k]

Ya, I haven't checcked with MSAA PR as of now in browser, gonna do that as well. BTW, this MSAA thing looks promising.

The lags are certainly not as present in the browser as they are in the Electron app, when present at all for me. However, I still notice a slight improvement, in Chrome and Firefox, with this MSAA PR. So it is worth pursuing I think.

[MarcoZehe]

Can you please give me your any of the contact detail via private message? may be we can talk more about this issue.

No. I don't think that's necessary. Besides, I am low on time.

[akash07k]

@leonardder
@feerrenrut
Any updates on this?

[camlorn]

From the duplicate issue, it's important to flag that 2020.1 doesn't reproduce this problem. This is a long comment thread so I may have missed that already being stated, but at least on my machine this acts like a regression on the NVDA side.

[akash07k]

@camlorn
No, I even tried with NVDA 2019.3, but I faced same issue.
However, I truely feel that this is NVDA's problem since it doesn't reproduce with JAWS, but it is sure that this problem is aftter NVDA 2020.1 release.
At least this editor laggyness.
Gonna try with 2019.2 also and will report right here within couple of minutes

From the duplicate issue, it's important to flag that 2020.1 doesn't reproduce this problem. This is a long comment thread so I may have missed that already being stated, but at least on my machine this acts like a regression on the NVDA side.

[akash07k]

So, I tested with 2019.2 also, but the same lag persists. sadly.

[akash07k]

Seems that this issue is quite complex to fix as well as track down.
Losing the hope for the fix anytime soon 😢😢😭😭

[akash07k]

@leonardder
I experimented with try build little bit more, and I feel that it may give promising results.
The lag is reduced.
May be the work can be continued in #11437 in order to fix it.

Could you also have a try with this try build as a portable copy? This is the build associated with pr #11437. You should enable the Only process MSAA/IA2 &events for specific objects (focus, etc.) option in NVDA"s advanced settings.

[camlorn]

I just got the 1.49 VSCode update and still can't duplicate this against 2020.1. @akash07k , where do you fall on the spectrum from netbook to workstation, and have you tried disabling all extensions in VSCode yet?

Someone more qualified than me will probably have better questions, but in terms of a bug functioning like the most typical regression scenario ever, this one does: happens perfectly reliably in 2020.2, happens never in 2020.1.

[leonardder]

@leonardder
@feerrenrut
Any updates on this?

It is under investigation. Could you please refrain from asking for updates? We'll provide them when appropriate.

[akash07k]

@camlorn
Not at all, may be your issue was different and mine is different.
I can reproduce my issue with 2019.2 even.
I don't think that your issue was regarding the laggyness of editor. I.E: typing and navigating the code.
I'm on laptop.
Tried with 8 GB I7, and 16 GB I7 10th gen processor.
I've tried everything, done every troubleshooting disabled everything and done whatever I could do.
Please go through whole thread for the complete understanding of this issue.
Only then you'll be able to understand that what I've done or what not.
I've tried the clean installation of everything.
Not only this, I've tried with multiple laptops and same issue persists, even with or without SSD.

I just got the 1.49 VSCode update and still can't duplicate this against 2020.1. @akash07k , where do you fall on the spectrum from netbook to workstation, and have you tried disabling all extensions in VSCode yet?

Someone more qualified than me will probably have better questions, but in terms of a bug functioning like the most typical regression scenario ever, this one does: happens perfectly reliably in 2020.2, happens never in 2020.1.

[akash07k]

Ok, let's see.

@leonardder
@feerrenrut
Any updates on this?

It is under investigation. Could you please refrain from asking for updates? We'll provide them when appropriate.

@leonardder
@feerrenrut
Any updates on this?

It is under investigation. Could you please refrain from asking for updates? We'll provide them when appropriate.

[camlorn]

I'll see if I can find the time to set up to run from source and bisect this weekend. I suspect there's two causes of lag. I'm not the only person I know for whom 2020.1 works fine.

I have read the thread. @akash07k, your comments are hard to follow because you have been splitting up what you've tried across multiple comments back to back so it is possible I missed the answers to my questions. Sorry.

[akash07k]

@camlorn
You are right, I've splitted my comments, but, actually it happens sometime. 😂😂 I can understand that you may have missed some of them. Actually sometimes when we write something and submit, afterwards, something more comes in our mind to add and instead of editing the previous comment, we add the fresh comment. 😂😂
Regarding lag, I've tried the editor thing with many machines and used even 2019.2 (As I sad earlier) but same issue reproduces. I dont know what can be the cause of it.
Which causes you are suspecting on lag?
If you work on something, then I'll be happy to try your build.
Have you tried that build which @leonardder provided some comments before?

I'll see if I can find the time to set up to run from source and bisect this weekend. I suspect there's two causes of lag. I'm not the only person I know for whom 2020.1 works fine.

I have read the thread. @akash07k, your comments are hard to follow because you have been splitting up what you've tried across multiple comments back to back so it is possible I missed the answers to my questions. Sorry.

[akash07k]

Finally,
Losing the hope that this bug will be fixed soon. As per other issues/bugs, it may take years to get fixed. and It's very unproductive to wait for years.
It is also possible that this bug gets ignored for several years and it doesn't get the attension to get it fixed on priority basis.
I think I should move back to JAWS. only it will be better for me if I want to code with Visual Studio Code.

[camlorn]

I bisected and this gets weird. The lag is introduced for me and the other person I know who is experiencing this by the rollback of the app module in commit e095f81183f3d904b56060c619a0e0966c8b5c9c. And, per the directions in that commit, unchecking enable browse mode on page load gets rid of it for me and massively improves it for him.

Notably, entering and leaving browse mode after VSCode loads doesn't reintroduce the lag, either. It's specifically that setting.

The NVDA snapshot with the selective event subscription setting doesn't matter for me because there's too little lag left, but for my friend it didn't help.

So I think the next thing for this issue is anyone else trying that. Note that configuration profiles are a thing for anyone who doesn't know that already. You can work around it (if this workaround works) by using a configuration profile to selectively toggle the setting rather than gain a responsive VSCode at the cost of a terrible browsing experience.

[akash07k]

@camlorn
Thanks a lot for your work around bro.
I'll just try it and will let you know whether it improves the performance for me or not.
If it improves, then I'll be extremely happy because it's very painful for me.
Will create the configuration profile for VS Code itself. that's a better and productive idea.

I bisected and this gets weird. The lag is introduced for me and the other person I know who is experiencing this by the rollback of the app module in commit e095f81. And, per the directions in that commit, unchecking enable browse mode on page load gets rid of it for me and massively improves it for him.

Notably, entering and leaving browse mode after VSCode loads doesn't reintroduce the lag, either. It's specifically that setting.

The NVDA snapshot with the selective event subscription setting doesn't matter for me because there's too little lag left, but for my friend it didn't help.

So I think the next thing for this issue is anyone else trying that. Note that configuration profiles are a thing for anyone who doesn't know that already. You can work around it (if this workaround works) by using a configuration profile to selectively toggle the setting rather than gain a responsive VSCode at the cost of a terrible browsing experience.

[lpintes]

Hello all,

I tested the workaround and it works for me.

Currently I am working on one Go project and was not able to use VSCode. I already had a configuration profile to have spoken indentation, it is helping me a lot while reading the code.

Now I switched the mentioned setting and the lag disappeared.

[leonardder]

Wow, this workaround also imposes a huge performance increase on my system. This is really one of the ways to go.

This issue is currently scattered with lots of comments, making it very hard to follow the line of the issue. Therefore, I'm thinking about opening a new issue that describes the problem more technically.

[MarcoZehe]

Wow, this workaround also imposes a huge performance increase on my system. This is really one of the ways to go.

Confirmed, and I am really surprised by this.

This issue is currently scattered with lots of comments, making it very hard to follow the line of the issue. Therefore, I'm thinking about opening a new issue that describes the problem more technically.

Please do. As someone who advocated to remove the original app module that forced application mode in VS Code, so the transitions between actual interactions and pieces that were appropriate for reading mode, I am interested in why NVDA suffers so badly if reading mode is involved.

[akash07k]

Seriously, it's amazing! It works flawlessly and drastically improves the performance of VS code as well completely eliminates the lag on my 16 GB memory stick and I7 10th gen system.
@camlorn
Thanks a lot buddy, you really solved one of my biggest problem.
Although with my 8GB laptop, the lag is still, however it is minor.

[akash07k]

Really, same here.
Please create the issue it will be great.

Wow, this workaround also imposes a huge performance increase on my system. This is really one of the ways to go.

This issue is currently scattered with lots of comments, making it very hard to follow the line of the issue. Therefore, I'm thinking about opening a new issue that describes the problem more technically.

[leonardder]

Here is a new try build that should allow enabling the browse mode on page load setting again.
@akash07k, @MarcoZehe, @lpintes and @camlorn , could you have a test please?

[MarcoZehe]

Yes, this seems to be both loading browse mode on documents, such as release notes or similar, as well as have better performance when editing files. But let's wait for confirmation from @akash07k since he can more reliably reproduce the sluggishness than I can.

[akash07k]

@leonardder
Yes, Agreed with @MarcoZehe
Try build works well even though the "enable browse mode upon page load" check box is checked and there's no lag.
However, I'll test more in order to verify the performance aspect accurately.

[lpintes]

@leonardder,
I Tested the try build and can confirm that the lag disappeared.

[camlorn]

I'll test this weekend if there aren't enough other confirms from people. Bit limited on time this week.

[brunoprietog]

This is great! It solves VS Code's slowness, although it introduced a bug in Microsoft Edge Chromium. The controls announce them twice and sometimes three times. Does the same thing happen to anyone else?