Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Speed ups to ms word object model #9217

Merged
merged 19 commits into from Feb 11, 2019
Merged

Speed ups to ms word object model #9217

merged 19 commits into from Feb 11, 2019

Conversation

@michaelDCurran
Copy link
Member

@michaelDCurran michaelDCurran commented Jan 31, 2019

Link to issue number:

None.

Summary of the issue:

We introduced in-process support for Microsoft Word back in 2011 which drastically improved performance from the old out-of-process code. However, over the years as we have added even more features for MS Word, our in-process code has been getting slower and slower, and many users are starting to say that it is becoming impractical to use.

Description of how this pull request fixes the issue:

This pr provides between a 2x and 3x speed up in response time when navigating documents in Microsoft Word, when using the standard object model code. The UI Automation support is not touched by this pr.
This pr has been able to achieve the speed ups in the following ways:

  • When detecting text columns, if there is only one column in the current section, then there is no need to try and work out which column we are in. Thus for documents that don't use multiple columns, this proves a useful optimization.
  • There was some debugging code that was run after text column information was fetched. this code validated we got nothing wrong and sent a nice error to the log if we did. Although this is useful for debugging, the majority of users would never read the error if it was shown, plus the debugging code was causing a significant delay in response times. this code is now commented out.
  • The way we fetch editor revision information has been rewritten similarly to how we fetch comments and spelling errors. I.e. We fetch all revisions for the given range, sotring them in a vector, including their start and end. then as we move through the range by word, we include the revision that overlaps our current position. This stops us from having to both duplicate the range, and call range.revisions for every word in the original range.

Testing performed:

Note that the experimental UI Automation support for MS Word must be turned off to test this. PR 9200 is again making it disabled by default.
Using our standard
Test document.docx
I had NVDA read through the document, ensuring that revisions were still announced where expected. Plus sections.
I tested a separate document with multiple columns, to ensure that NVDA announced which column I was in.
On my Microsoft Surface Pro 4, plugged in with Power profile set to 100%, many lines have gone from taking 550 ms to now taking around 170 ms to start reading.
also I found it useful to set the view to draft mode for best performance -- something we should probably always recommend to users.

Known issues with pull request:

None.

Change log entry:

Bug fixes:

  • Navigating content in Microsoft Word is now between 2 and 3 times faster for most documents.
…r only one layout column, remove some debugging code, and turn off screenUpdating while collecting text formatting.
… more efficiently, similarly to how we fetch comments and spelling errors.
}
long start=0;
if(_com_dispatch_raw_propget(pDispatchRevisionScope,wdDISPID_RANGE_START,VT_I4,&start)!=S_OK) {
continue;
Copy link
Collaborator

@leonardder leonardder Jan 31, 2019

Just to make sure, don't we need to log anything when one of these continue statements is reached, e.g. when we can fetch the type and start, but not the end? That might indicate that something is broken

@@ -945,7 +963,8 @@ void detectAndGenerateColumnFormatXML(IDispatchPtr pDispatchRange, wostringstrea
}
xmlStream <<L"text-column-number=\"" << columnNumber << "\" ";

// Finally, double check that we calculated the full width of the document
/*
The following commented out code to the end of this function can be used to double check that we calculated the full width of the document
Copy link
Collaborator

@leonardder leonardder Jan 31, 2019

Rather than commenting this out, would it make sense to add an additional nvdaHelperDebugFlag? May be you've already thought about this and thought it wouldn't be worth it. That's ok, I just wanted to bring up the idea.

Copy link
Member

@feerrenrut feerrenrut Jan 31, 2019

Also, please remove / comment out / put behind a flag, the debug logging on line 920. I seem to recall that the logging from C++ took quite a long time.

LOG_DEBUG(L"ItemNumber: " << itemNumber
	<< " rangePos: " << rangePos
	<< " colStartPos: " << colStartPos);

Copy link
Member Author

@michaelDCurran michaelDCurran Feb 3, 2019

LOG_DEBUG is defined to nothing by default, I.e. none of those tokens within the brackets will be compiled, unless nvdahelperLogLevel is debug.

long revStart=get<0>(i);
long revEnd=get<1>(i);
long revType=get<2>(i);
if(!(chunkStartOffset>=revEnd||chunkEndOffset<=revStart)) {
Copy link
Collaborator

@leonardder leonardder Jan 31, 2019

I somehow find this hard to read. I assume this is the same as:

Suggested change
if(!(chunkStartOffset>=revEnd||chunkEndOffset<=revStart)) {
if(chunkStartOffset<revEnd&&chunkEndOffset>revStart) {

@leonardder
Copy link
Collaborator

@leonardder leonardder commented Jan 31, 2019

I still prefer a look from @feerrenrut, i'm getting better at C++ but COM interaction is still a bit tricky. I will also do some performance tests.

@leonardder
Copy link
Collaborator

@leonardder leonardder commented Jan 31, 2019

Based on #5750 (comment), here is some performance data regarding table navigation,.

str:

  1. Set the desired options in NVDA
  2. Open this document
  3. Enable debug timeSinceINput logging
  4. In the document, press ctrl+alt+right arrow
  5. Then, press ctrl+alt+leftArrow

Below are results for the time between keypress and speech

Situation Master right master left speedUpMSWordObjectModel right speedUpMSWordObjectModel left
Pages/spelling/changes disabled 0.121 0.145 0.150 0.176
Pages enabled 0.425 0.345 0.710 0.225
Pages/changes enabled 0.575 0.667 0.925 0.445
Pages/spelling/changes enabled 3.593 5.599 3.750 5.077

This was with braille enabled. These tests are not very scientific, yet I'd have expected more clear differences. I believe you when you're saying that this improves things, but may be we should be careful about statements like twice faster, as for some situations, this might not apply

@michaelDCurran
Copy link
Member Author

@michaelDCurran michaelDCurran commented Jan 31, 2019

@leonardder
Copy link
Collaborator

@leonardder leonardder commented Jan 31, 2019

Are you absolutely sure that you have exactly the same NVDA config for both, and that nvdaHelper was compiled the same way for both?

The tests with master were performed with latest Alpha, whereas this pr's tested were performed from source. I will mitigate this difference by using a try build for a subsequent test in which I will take the average of at least three equivalent table movement commands.

And of course, you double checked that NVDA was not using UIA for either test? I.e. the role for the document was edit, not document?

Yes.

@leonardder
Copy link
Collaborator

@leonardder leonardder commented Jan 31, 2019

Here is a new test, based om the average of 3 rounds instead of just one

Situation master right master left speedUpMSWordObjectModel right speedUpMSWordObjectModel left
Pages/spelling/changes disabled 0.137 0.148 0.19 0.211
Pages enabled 0.396 0.382 0.340 0.276
Pages/changes enabled 0.593 0.719 0.418 0.425
Pages/spelling/changes enabled 3.636 5.522 3.241 5.00

This is with braille off, and certainly shows that the code that deals with revisions has been improved. Both builds were installed on my system.

@@ -945,7 +963,8 @@ void detectAndGenerateColumnFormatXML(IDispatchPtr pDispatchRange, wostringstrea
}
xmlStream <<L"text-column-number=\"" << columnNumber << "\" ";

// Finally, double check that we calculated the full width of the document
/*
The following commented out code to the end of this function can be used to double check that we calculated the full width of the document
Copy link
Member

@feerrenrut feerrenrut Jan 31, 2019

Also, please remove / comment out / put behind a flag, the debug logging on line 920. I seem to recall that the logging from C++ took quite a long time.

LOG_DEBUG(L"ItemNumber: " << itemNumber
	<< " rangePos: " << rangePos
	<< " colStartPos: " << colStartPos);

if(_com_dispatch_raw_propget(pDispatchWindow,wdDISPID_WINDOW_SELECTION,VT_DISPATCH,&pDispatchSelection)!=S_OK||!pDispatchSelection) {
LOG_DEBUGWARNING(L"application.selection failed");
return;
}
//Disable screen updating as we will be moving the selection temporarily
_com_dispatch_raw_propput(pDispatchApplication,wdDISPID_APPLICATION_SCREENUPDATING,VT_BOOL,false);
Copy link
Member

@feerrenrut feerrenrut Jan 31, 2019

This seems error prone, any early exit or future refactor could mean that screen updating is not turned back on.

@feerrenrut
Copy link
Member

@feerrenrut feerrenrut commented Jan 31, 2019

I think it's worth trying to get to the bottom of the differences in performance improvement.

  • It would be sensible we are all testing with the same document.
  • Mick mentioned that he tested in draft mode, we should all do the same.
  • Perf measurements should be added to the word code, before and after this change.
    • Timing only the changed code will help to reduce noise in the measurements.
    • Consider nvdaHelper/common/PerfTimer.h
  • Ensure both the before and after are built in the same way.

@lukaszgo1
Copy link
Contributor

@lukaszgo1 lukaszgo1 commented Feb 1, 2019

This pr creates duplicate branches speedUpMSWordObjectModel and speedupMSWordObjectModel differing only by capital U and causing a new branch to appear with each git pull. Can one of those be deleted?

@michaelDCurran
Copy link
Member Author

@michaelDCurran michaelDCurran commented Feb 3, 2019

@michaelDCurran
Copy link
Member Author

@michaelDCurran michaelDCurran commented Feb 3, 2019

…pecifically from within each in-process call, disable it from Python the first time it is required in a core cycle, re-enabling it at the end of the core cycle.
@michaelDCurran
Copy link
Member Author

@michaelDCurran michaelDCurran commented Feb 4, 2019

@leonardder: I cannot at all reproduce the massive slowdown in the document you used for the tests. Even with pages/changes/spelling enabled, I'm getting numbers like 0.23, not at all anything like 3.5 or higher. I'm not sure what language this is in, perhaps it is because I don't have a dictionary installed for that language, therefore spelling is really fast?

@michaelDCurran
Copy link
Member Author

@michaelDCurran michaelDCurran commented Feb 4, 2019

Ah, it is Dutch :) Question is how to force MS Office to get a dictionary.

@michaelDCurran
Copy link
Member Author

@michaelDCurran michaelDCurran commented Feb 4, 2019

With the Dutch language pack installed, I can reproduce it now.

…fetch costly formatting info such as spelling errors and editor revisions, even if the user has these turned on.
@michaelDCurran
Copy link
Member Author

@michaelDCurran michaelDCurran commented Feb 4, 2019

Moving left and right in the test table is now down to 0.23 on my system. When speaking for unit paragraph or cell, we no longer fetch spelling errors or editor revisions as these can be very costly. This info will still automatically be spoken for character, word and line of course.

@leonardder
Copy link
Collaborator

@leonardder leonardder commented Feb 4, 2019

@michaelDCurran commented on 3 Feb 2019, 23:04 CET:

I would recommend that we change the general functionality for table
movement to only speak the first paragraph for a given cell. What are
your thoughts on this?

I think this is a very good idea, as long as we somehow document this change for users and make it consistent for all edit controls.

Have you done any testing with the test document.docx referenced by this
pr?

Not yet. I will do this later today

@leonardder
Copy link
Collaborator

@leonardder leonardder commented Feb 4, 2019

@michaelDCurran commented on 4 Feb 2019, 01:45 CET:

Ah, it is Dutch :) Question is how to force MS Office to get a dictionary.

This is not Dutch, it is fake Latin, see lipsum.com. But I definitely had Dutch spell checking on when testing.
@michaelDCurran commented on 4 Feb 2019, 02:31 CET:

When speaking for unit ... cell, we no longer fetch spelling errors or editor revisions as these can be very costly.

This means that table navigation does not report any spelling errors any more. Sometimes, table navigation is the only way one can effectively move through a table, and especially if the table has small cells, I'm not sure whether such a change would be appreciated.

I wonder whether we could do anything with regard to the "Report formatting changes after the cursor (can cause a lag)" option in document formatting settings. It might make sense to implement this for Word

@michaelDCurran
Copy link
Member Author

@michaelDCurran michaelDCurran commented Feb 4, 2019

@michaelDCurran
Copy link
Member Author

@michaelDCurran michaelDCurran commented Feb 4, 2019

@leonardder
Copy link
Collaborator

@leonardder leonardder commented Feb 4, 2019

…, don't fetch costly formatting info such as spelling errors and editor revisions, even if the user has these turned on."

This reverts commit 6ea9d0f.
…f the next cell, otherwise it may take a very long time to collect all content for the cell.
@@ -343,6 +343,30 @@
u'\uF0FC' : u'\u2714', # Wingdings
}

class ScreenUpdatingDisabler(object):
Copy link
Collaborator

@leonardder leonardder Feb 4, 2019

While I understand the idea behind this, it doesn't look very pythonic to me. Is there any chance this can be implemented like a context manager?

Copy link
Member Author

@michaelDCurran michaelDCurran Feb 4, 2019

Not really, as there isn't actually a common point at which we could use a with block to control the lifetime of the context manager. Its lifetime affects anything between the time it was created and the end of the core cycle. I guess we could possibly override caretMovementScriptHelper and wrap the super call in a with statement. But there may be other situations other than caret movement where this could be used. Right now it is placed above each nvdahelper call, which ensures that if it is not disabled already, it will be now.

Copy link
Collaborator

@leonardder leonardder Feb 4, 2019

Agreed that in that case, the current solution might be best. I think we must make sure that it doesn't cause any visual issues, though, since screen updating might now be off longer than before.

@leonardder
Copy link
Collaborator

@leonardder leonardder commented Feb 4, 2019

It might still make sense to no longer report spelling errors and revision info when navigating by paragraph, regardless whether table navigation reports paragraphs or only the first line. I'd say that the paragraph movement commands are only used for quick scanning or reading, not within the process of authoring in which spelling errors and revisions are important.

…ll not be announced. It is important that navigating by paragraph is performant as it is used for quick skimming.
# Therefore, only speak the first line of the cell.
newInfo.collapse()
newInfo.expand(textInfos.UNIT_LINE)
speech.speakTextInfo(newInfo,reason=controlTypes.REASON_CARET, unit=textInfos.UNIT_LINE)
newInfo.collapse()
Copy link
Collaborator

@leonardder leonardder Feb 6, 2019

This now collapses twice, which means two extra com calls, one to collapse the range and one to get the new ends offset. Could we do anything about this, i.e. update the caret after the first collapse and than expand to line?

Also, may be you could optimize collapse while at it. It now fetches self._rangeObj.end in collapse without doing anything with it if end is not True. Something like this:

-		newEndOffset = self._rangeObj.end
 		# the new endOffset should not have become smaller than the old endOffset, this could cause an infinite loop in
 		# a case where you called move end then collapse until the size of the range is no longer being reduced.
 		# For an example of this see sayAll (specifically readTextHelper_generator in sayAllHandler.py)
-		if end and newEndOffset < oldEndOffset :
+		if end and self._rangeObj.end < oldEndOffset :

@@ -1150,6 +1180,13 @@ def script_previousColumn(self,gesture):

class WordDocument(Window):

def _get_screenUpdatingDisabler(self):
Copy link
Collaborator

@leonardder leonardder Feb 6, 2019

May be explicitly state that this should be cached?

Suggested change
def _get_screenUpdatingDisabler(self):
_cache_screenUpdatingDisabler = True
def _get_screenUpdatingDisabler(self):

@@ -351,6 +328,45 @@ bool collectCommentOffsets(IDispatchPtr pDispatchRange, vector<pair<long,long>>&
return !commentVector.empty();
}

bool collectRevisionOffsets(IDispatchPtr pDispatchRange, vector<tuple<long,long,long>>& revisionsVector) {
Copy link
Collaborator

@leonardder leonardder Feb 6, 2019

The spelling error equivalent of this function fetches the application object and checks whether it is sandboxed. Just to make sure, might this be a requirement for this new implementation? On the contrary, can we somehow avoid this sandbox check for spelling errors in some versions of word?

Copy link
Member Author

@michaelDCurran michaelDCurran Feb 7, 2019

The sandbox check was added for spelling errors before it was refacted into that function. I.e. MS Word would crash if range.spellingErrors.cound was ever called, no matter how big the range. I never found this to be the case for revisions. We could possibly version check where we need to look at sandbox, but I think the bug existed for 2010 and higher, so it would only slightly improve 2007. Still, we could revisit this again in future with a bit more testing.

Copy link
Member

@feerrenrut feerrenrut Feb 8, 2019

There seems to be two space characters at the start of this line.

@@ -983,8 +1005,13 @@ void winword_getTextInRange_helper(HWND hwnd, winword_getTextInRange_args* args)
LOG_DEBUGWARNING(L"AccessibleObjectFromWindow failed");
return;
}
//Get the current selection
IDispatchPtr pDispatchSelection=NULL;
IDispatchPtr pDispatchApplication=NULL;
Copy link
Collaborator

@leonardder leonardder Feb 6, 2019

Do we still need this?

@Adriani90
Copy link
Collaborator

@Adriani90 Adriani90 commented Feb 7, 2019

Regarding table navigation, just a thought from my side:
Reading only the first paragraph or the first line in a table cell will actually weaken the efficiency. Note that in many cases people need to read tables loaded with much information quite fast, kind of skim reading. For that purpose, many people turn off table reporting and cell coordinates as well as column and row headings. In this case, navigating with arrow key in a table makes no sense at all because you don't get the coordinates. Only table navigation will help understanding the context as fast as possible. So reading the entire cell content is actually quite important.

I agree with stopping to report track changes and spelling errors while navigating by paragraph. Most people use browse mode or elements list to navigate between them anyway.

@leonardder
Copy link
Collaborator

@leonardder leonardder commented Feb 7, 2019

Reading only the first paragraph or the first line in a table cell will actually weaken the efficiency.

While this is true, this also applies to the major performance issue caused by reading the whole cell instead of only the first line. Having said that, changing this behaviour for every application only because the Word performance is bad sounds a bit too drastic.

@Adriani90: What do you think about the other way to improve this, reading the whole cell when navigating tables, thereby not speaking spelling and revisions?

@Adriani90
Copy link
Collaborator

@Adriani90 Adriani90 commented Feb 7, 2019

What do you think about the other way to improve this, reading the whole cell when navigating tables, thereby not speaking spelling and revisions?
in my view this would be ok for the same reason like reading by paragraph.

@Adriani90
Copy link
Collaborator

@Adriani90 Adriani90 commented Feb 7, 2019

I noticed also a Performance issue especially when a table cell contains a list with bullets compared to a cell without bullets. I wonder if NVDA can handle the lists in MS Word in a different way, fetching the symbols maybe differently?

@michaelDCurran
Copy link
Member Author

@michaelDCurran michaelDCurran commented Feb 7, 2019

Okay, so as to not make this pr too large for 2019.1, I have decided to not do the proposed changes for sections and text columns in this pr. We already have a significant speed-up in many scenarios. I have again switched back to announcing the entire table cell when navigating by cell, however, like with paragraphs, spelling errors are disabled for performance reasons. In the end I did not bother disabling editor revisions for cells or paragraphs, as this was not at all the cause of the performance hit in that document.
Also, I have gone back to disabling screen updating in-process, so as to not be concirned about whether that change affected visual things. However, the screen updating code is now in a RAAI class which ensures it will be re-enabled at the end of the scope it it is created in.
Both @feerrunrut and @leonardder: I believe I have addressed all your review comments, either by making changes, or removing some of the changes.
Testing from various people now suggests that there is significant speed-up for navigating large table cells, and moving by line in general. I'm sure we can go further in future, but I think this is a step in the right direction.

@dnz3d4c
Copy link

@dnz3d4c dnz3d4c commented Feb 8, 2019

I expect this pr to be merged quickly. I am use MS word mainly in company. I would like to experience the performance improvement through these results.

// A class that disables MS Word screen updating while it is alive.
class ScreenUpdatingDisabler {
private:
IDispatchPtr pDispatchApplication {nullptr};
Copy link
Collaborator

@leonardder leonardder Feb 8, 2019

I've not seen this kind of declaration earlier. What's the difference with this and IDispatchPtr pDispatchApplication = nullptr;?

Copy link
Member Author

@michaelDCurran michaelDCurran Feb 8, 2019

It is new c++ syntax that allows you to provide the default value of a variable at declaration time. You can't use = for an instance variable in this context. It avoids having to initialize it in the constructor.

Copy link
Member

@feerrenrut feerrenrut left a comment

A few suggestions, happy for this to be merged when you are ready.

@@ -58,6 +58,35 @@ constexpr int formatConfig_initialFormatFlags =(formatConfig_reportPage|formatCo
constexpr wchar_t PAGE_BREAK_VALUE = L'\x0c';
constexpr wchar_t COLUMN_BREAK_VALUE = L'\x0e';

// A class that disables MS Word screen updating while it is alive.
class ScreenUpdatingDisabler {
Copy link
Member

@feerrenrut feerrenrut Feb 8, 2019

Nice.

@@ -351,6 +328,45 @@ bool collectCommentOffsets(IDispatchPtr pDispatchRange, vector<pair<long,long>>&
return !commentVector.empty();
}

bool collectRevisionOffsets(IDispatchPtr pDispatchRange, vector<tuple<long,long,long>>& revisionsVector) {
Copy link
Member

@feerrenrut feerrenrut Feb 8, 2019

There seems to be two space characters at the start of this line.

@@ -351,6 +359,45 @@ bool collectCommentOffsets(IDispatchPtr pDispatchRange, vector<pair<long,long>>&
return !commentVector.empty();
}

bool collectRevisionOffsets(IDispatchPtr pDispatchRange, vector<tuple<long,long,long>>& revisionsVector) {
IDispatchPtr pDispatchRevisions=NULL;
Copy link
Member

@feerrenrut feerrenrut Feb 8, 2019

Would you mind converting these to use nullptr instead of NULL?

@@ -351,6 +359,45 @@ bool collectCommentOffsets(IDispatchPtr pDispatchRange, vector<pair<long,long>>&
return !commentVector.empty();
}

bool collectRevisionOffsets(IDispatchPtr pDispatchRange, vector<tuple<long,long,long>>& revisionsVector) {
IDispatchPtr pDispatchRevisions=NULL;
if(_com_dispatch_raw_propget(pDispatchRange,wdDISPID_RANGE_REVISIONS,VT_DISPATCH,&pDispatchRevisions)!=S_OK||!pDispatchRevisions) {
Copy link
Member

@feerrenrut feerrenrut Feb 8, 2019

Could you convert these checks to get the result first, then check for success? They are currently so long, it makes it easy to miss other conditions for the branch.

Suggested change
if(_com_dispatch_raw_propget(pDispatchRange,wdDISPID_RANGE_REVISIONS,VT_DISPATCH,&pDispatchRevisions)!=S_OK||!pDispatchRevisions) {
auto res = _com_dispatch_raw_propget(pDispatchRange,wdDISPID_RANGE_REVISIONS,VT_DISPATCH,&pDispatchRevisions);
if(res!=S_OK || !pDispatchRevisions) {

// Disable screen updating until the end of this scope
ScreenUpdatingDisabler sud{pDispatchApplication};
//Get the current selection
IDispatchPtr pDispatchSelection=NULL;
Copy link
Member

@feerrenrut feerrenrut Feb 8, 2019

use nullptr instead

@michaelDCurran michaelDCurran changed the title Speed up ms word object model by 2x Speed ups to ms word object model Feb 11, 2019
@michaelDCurran michaelDCurran merged commit 960983e into master Feb 11, 2019
1 check passed
@nvaccessAuto nvaccessAuto added this to the 2019.1 milestone Feb 11, 2019
@surfer0627
Copy link
Contributor

@surfer0627 surfer0627 commented Jan 13, 2021

What's New in 2019.1:

Responsiveness in Microsoft Word when navigating by line, paragraph or table cell may be significantly improved in some documents. A reminder that for best performance, set Microsoft Word to Draft view with alt+w,e after opening a document.

Interestingly, Word command Ctrl + Alt + N change to draft view.

In NVDA side, this command starts or restarts NVDA.

@zstanecic
Copy link
Contributor

@zstanecic zstanecic commented Jan 13, 2021

@surfer0627
Copy link
Contributor

@surfer0627 surfer0627 commented Jan 13, 2021

@zstanecic,
I will change the NVDA keystroke.
Thanks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Linked issues

Successfully merging this pull request may close these issues.

None yet

9 participants