[SERVER-21690] Text Search - Performance Regression in 3.2.0 RC4 Created: 30/Nov/15  Updated: 03/Dec/15  Resolved: 01/Dec/15

Status: Closed
Project: Core Server
Component/s: Text Search
Affects Version/s: 3.2.0-rc4
Fix Version/s: 3.2.0-rc6

Type: Bug Priority: Major - P3
Reporter: Stuart Hall Assignee: J Rassi
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File createIndex.js     File testQuery_all.js    
Issue Links:
Duplicate
Related
is related to SERVER-19936 Performance pass on unicode-aware tex... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Steps To Reproduce:

See above

Sprint: QuInt D (12/14/15)
Participants:

 Description   

MongoDB 3.2.0 RC4 appears to have a substantial performance regression with full text searching

Test Data
3000 books obtained from Project Gutenberg (http://web.eecs.umich.edu/~lahiri/gutenberg_dataset.html) stored in MongoDB as follows:

    {
      author : "Abraham Lincoln",
      title : "Letters",
      body : "<full text of book>"
    }

This data was then indexed using an "all fields" index:

db.books.createIndex( { "$**" : "text" } );

This produces a test dataset of around 1.1GB with a text index of 155MB (measured with WT)

Test process
This data was processed into different versions of MongoDB and various simple searches were run using words and phrases of different occurence frequencies in the dataset. This was done using the following, simple query shape in an aggregation pipeline, with the ultimate goal being to report the number of books per author containing the search word:

db.books.aggregate([
{ 
	$match : { 
		$text : { 
			$search : "house" 
		} 
	} 
},
{ 
	$group : { 
		_id : { 
			author : "$author" 
		}, 
		count : { 
			$sum : 1 
		} 
	} 
}, 
{ 
	$sort : { 
		count : -1 
	} 
} ]);

The words used are as follows:

  • slaveholder
  • hound
  • "gigantic hound"
  • cheese
  • house

A simple test script ("testQuery_all.js") is attached to automate this process.

Test results
All of these results were taken at the third run (i.e. to ensure that data was as warm as possible). In the case of the 3.2 results, mongod ran one core flat-out for the entire query duration.

Version Engine Total Query Duration (ms)
2.6.11 MMAPv1 5308
3.0.7 MMAPv1 5306
3.0.7 WT Snappy 6625
3.2.0 RC4 MMAPv1 26157
3.2.0 RC4 WT Snappy 639862

Full results are available here:
https://goo.gl/s4pU9j

Source data is here:
https://dl.dropboxusercontent.com/u/6076108/books.bson.gz
Note: text index needs to be manually applied to this data:

db.books.createIndex( { "$**" : "text" } );



 Comments   
Comment by J Rassi [ 03/Dec/15 ]

I really appreciate the report and your testing efforts. Thanks again, and keep posted for updates on SERVER-19936.

Comment by Stuart Hall [ 03/Dec/15 ]

Hi Jason,

Here are the results of my testing. Just to be absolutely sure here, I've re-run all of my tests as my previous run were done on battery, so the CPU was being throttled which would have made these results incomparable with the previous set:

Version Engine Total Query Duration (ms)
2.6.11 MMAPv1 4906
3.0.7 MMAPv1 3749
3.0.7 WT Snappy 5247
3.2.0 rc4 MMAPv1 21323
3.2.0-rc4 WT Snappy 396004
3.2.0-rc6 MMAPv1 21118
3.2.0-rc6 WT Snappy 23131

(Source data here: https://goo.gl/VJfR5p)

Based on this, I would probably agree with what you said; that half of this problem is fixed and we're left with a specific degradation on phrase matching in the V3 text index, which is more apparent from the raw test timings.

In order to confirm this, I tested 3.2.0-rc6 against the V2 text index format:

Version Engine Text Index Version Total Query Duration (ms)
3.0.7 WT Snappy v2 5247
3.2.0-rc6 WT Snappy v2 5351
3.2.0-rc6 WT Snappy v3 23131

On the basis of this, I can confirm your findings and the fix for this half of the problem. I'll keep an eye on the other ticket (SERVER-19936) and hopefully this will also get a fix soon.

Thanks,

Stuart H.

Comment by Stuart Hall [ 03/Dec/15 ]

Hi Jason,

Thanks for the update and the fix. I'll re-test against 3.2.0-rc6 this evening and will report back.

SH

Comment by J Rassi [ 03/Dec/15 ]

I've identified two independent performance issues from the test results reported:

  1. Phrase matching in text index version 3 (with default settings) is significantly slower than in text index version 2.
  2. With WiredTiger, text queries that incur yields are significantly slower before 3.1.0 as compared to 3.1.0 or later.

#1 above has been previously reported at SERVER-19936. I left a follow-up comment with updated performance data.

#2 has not been reported previously, and has been fixed for 3.2.0-rc6 in this ticket under the above commit, and a regression test has been pushed to mongo-perf (ec26ca98). This is a regression introduced by SERVER-17062 (5ffcf2f2), specifically in the introduction of the "is suspicious" check for working set members (which is skipped for MMAPv1). This check performs key generation on the fetched documents, which is prohibitively expensive for text indexes. As of the above commit, text searches now eagerly fetch when seeing a new RecordId for the first time; as such, the TEXT_OR stage no longer keeps LOC_AND_IDX members across yields, and these members are no longer marked as "suspicious".

Stuart, would you be willing to re-run your tests against 3.2.0-rc6?

Comment by Githook User [ 01/Dec/15 ]

Author:

{u'username': u'jrassi', u'name': u'Jason Rassi', u'email': u'rassi@10gen.com'}

Message: SERVER-21690 TextOrStage should fetch doc when RecordId first observed
Branch: master
https://github.com/mongodb/mongo/commit/72d5149270c6b3f78d0563d765075f1cfa926d66

Comment by Stuart Hall [ 30/Nov/15 ]

No problem at all. I'll keep an eye out for an updated build with a fix and will re-test.

SH

Comment by Martin Bligh [ 30/Nov/15 ]

stuart.hall@masternaut.com Thanks very much for the very clear and easy to reproduce bug report. We think we understand the cause of this now, and will be addressing very soon.

Comment by Stuart Hall [ 30/Nov/15 ]

Hi Ramon,

I wiped the DB data folder and performed the following process:

  1. Insert 3000 books
  2. Add text index
  3. Query data

I then stopped the mongod and have attached the single diagnostic file (metrics.2015-11-30T16-53-52Z-00000) to the URL above.

Results were quicker (393,775ms) than before, but this is probably because my laptop is powered rather than running on battery, so will run the CPU quicker. Either way, they are still 75x slower than 2.6.11

Thanks,

Stuart H.

Comment by Ramon Fernandez Marina [ 30/Nov/15 ]

stuart.hall@masternaut.com, can you please compress the contents of <dbpath>/diagnostic.data and upload them here?

Thanks,
Ramón.

Comment by Stuart Hall [ 30/Nov/15 ]

One detail I forgot to add - in each case, I imported the data into a clean instance of mongod and created the index directly on the data. The textIndexVersion was therefore the default used by that given combination of engine and version. (i.e. version 2 for 2.6.11 and 3.0.7 and version 3 for 3.2.0 RC4). I've not done any testing of mixing engine and index versions at this time.

Generated at Thu Feb 08 03:58:07 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.