[SERVER-17078] show databases taking extraordinarily long with wiredTiger Created: 27/Jan/15  Updated: 18/Jul/16  Resolved: 26/Jun/15

Status: Closed
Project: Core Server
Component/s: Performance, WiredTiger
Affects Version/s: 3.0.0-rc6
Fix Version/s: 3.0.5, 3.1.5

Type: Bug Priority: Major - P3
Reporter: Chad Kreimendahl Assignee: Michael Cahill (Inactive)
Resolution: Done Votes: 3
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Microsoft Word Logfile.CSV    
Issue Links:
Depends
is depended on by WT-1973 MongoDB changes for WiredTiger 2.7.0 Closed
Related
related to SERVER-16353 listDatabases is very slow on wiredti... Closed
related to WT-1634 Opening a cursor with many tables is ... Closed
is related to SERVER-25025 Improve startup time when there are t... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Completed:
Steps To Reproduce:

"show databases" or doing a listdatabases command through the api/C#/java/etc.

Participants:
Linked BF Score: 0

 Description   
Issue Status as of Jul 14, 2015

ISSUE SUMMARY
When using the WiredTiger storge engine, methods to collect the size of each database for the output of the show databases operation in the mongo shell are inefficent, particularly with larger numbers of databases, collections, and indexes.

USER IMPACT
The show databases operation in the mongo shell can take a long time to return the listing of databases.

WORKAROUNDS
None.

AFFECTED VERSIONS
MongoDB 3.0.0 through 3.0.4.

FIX VERSION
The fix is included in the 3.0.5 production release.

Original description

When running the show databases command, with only 20 databases, we're seeing extremely long response times, typically of 60-90 seconds.

Based on previous conversations, I'm curious if this might be related to checking database sizes and/or stating files.

> show databases
Admin              0.000GB
BTest              0.003GB
Config             0.000GB
Customer-Fox       0.012GB
Customer-CBS       0.040GB
Customer-NBC       0.004GB
Elmah              0.000GB
MBTest             0.004GB
Master             0.033GB
Monitoring         0.021GB
OCRM               0.009GB
OCarp              0.085GB
ODev               0.134GB
OP                 0.041GB
Provisions         0.002GB
Queue              0.009GB
local              0.000GB



 Comments   
Comment by Githook User [ 10/Jul/15 ]

Author:

{u'username': u'michaelcahill', u'name': u'Michael Cahill', u'email': u'michael.cahill@mongodb.com'}

Message: SERVER-17078 Faster WT stats for storageSize

(cherry picked from commit c7bab6f8cfbd610ff1690cefaccb6fc83658f517)
Branch: v3.0
https://github.com/mongodb/mongo/commit/9a200e2eabc59a0ac421f4cf7ec7b1c30971f9f3

Comment by Githook User [ 29/Jun/15 ]

Author:

{u'username': u'michaelcahill', u'name': u'Michael Cahill', u'email': u'michael.cahill@mongodb.com'}

Message: SERVER-17078 Move the statistics=(size) support into the block manager.

(cherry picked from commit b956408d23d6abe21ce3f833c92d3ee011cfc845)
Branch: mongodb-3.0
https://github.com/wiredtiger/wiredtiger/commit/597dddd70578fe4b6e6533fba1a76899f9e4f99f

Comment by Githook User [ 29/Jun/15 ]

Author:

{u'username': u'michaelcahill', u'name': u'Michael Cahill', u'email': u'michael.cahill@mongodb.com'}

Message: SERVER-17078 Add a "statistics=(size)" mode to statistics cursors that just gets the filesize without opening anything.

(cherry picked from commit 74cea8701c115b9327523691659ed68c86c1f652)
Branch: mongodb-3.0
https://github.com/wiredtiger/wiredtiger/commit/a0c9c24db632dfed6df03f300375ea2a275898ef

Comment by Michael Cahill (Inactive) [ 15/Jun/15 ]

paul.reed, the fast "size" mode is enabled by default for listDatabases with WiredTiger in MongoDB master here: https://github.com/mongodb/mongo/commit/c7bab6f8cfbd610ff1690cefaccb6fc83658f517

A backport to the 3.0 branch is in progress.

If you are requesting that listDatabases not return size information at all, can you please vote for SERVER-3181?

Comment by Paul Reed [ 12/Jun/15 ]

Will "Size" become the default option and would really like the ability to be able listDatabases - without size requirements - this becoming the fastest method.

Comment by Githook User [ 10/Jun/15 ]

Author:

{u'username': u'michaelcahill', u'name': u'Michael Cahill', u'email': u'michael.cahill@mongodb.com'}

Message: Add a "statistics=(size)" mode to statistics cursors that just gets the filesize without opening anything.

refs SERVER-17078
Branch: develop
https://github.com/wiredtiger/wiredtiger/commit/74cea8701c115b9327523691659ed68c86c1f652

Comment by Githook User [ 10/Jun/15 ]

Author:

{u'username': u'michaelcahill', u'name': u'Michael Cahill', u'email': u'michael.cahill@mongodb.com'}

Message: SERVER-17078 Faster WT stats for storageSize
Branch: master
https://github.com/mongodb/mongo/commit/c7bab6f8cfbd610ff1690cefaccb6fc83658f517

Comment by Zhou Jiaqing [ 15/May/15 ]

This issue blocked our upgrade process.
We have a mongodb cluster, which has 15 databases, and about 800 collections in each. The cluster run on four shards, each shard contains 3 nodes, one primary and two secondaries
After we switch primary from 3.0.2 with mmap engine to 3.0.2 with wt engine, we found it's very slow to execute "listDatabases" command. After several listDatabases command submitted, the whole cluster got blocked, no insertion and deletions can be executed at that time.
Finally we have to switch primary back to mmap engine.

Hope someone will fix this problem soon. wt engine is really attractive to us!

Comment by Paul Reed [ 13/May/15 ]

This is a major issue for me.
I cannot push to WiredTiger until this is resolved - currently listDatabases can take anywhere from up to 2 minutes to return for me.
I have many databases each with many collections inside.
If its the case of calculating the size which is the difference between the storage engines, could we simply have an option which does not return this size, but just the names.

Comment by Bruce Lucas (Inactive) [ 14/Apr/15 ]

Hi João,

I suspect that the issue with creating a new database is not connected to this ticket. I created 1000 empty databases, with no significant performance degradation between creating the first db and creating the 1000th. So it seems that the simple number of dbs is not an issue with creating a new one, and that distinguishes it from the issue on this ticket, which manifests simply due to the number of dbs.

So please open a new ticket as you suggested. While doing so, would you be able to reproduce the problem while runnng the following data collection script, which collects serverStatus information once per second:

  mongo --eval "while(true) {print(JSON.stringify(db.serverStatus({tcmalloc:1}))); sleep(1000)}" >ss.log

Please reproduce the problem as follows:

  • start the data collection script
  • wait 5 minutes to establish a baseline in the serverStatus time series
  • create a new collection, noting as closely as possible the time when you issue the command
  • note the time when the create completes
  • wait another 5 minutes to again establish a post-creation baseline
  • then terminate the data collection

When you open the new ticket, please attach ss.log, the mongod log file covering the repro, and the timeline.

Thanks,
Bruce

Comment by João Soares [ 14/Apr/15 ]

Hi, we are using multi tenancy on the database level, so each of our clients get its own database. We currently have more than 1 thousand databases and issuing

show dbs

takes us several minutes to get a result.

We are also experiencing some really slow performance on a first write to a new database.

Steps to reproduce:

use new_database_name
db.new_collection.insert({ new: true })

Does anyone know if these two problems are somehow related? I haven't found any ticket related to my second issue but I can open one...

Comment by Daniel Pasette (Inactive) [ 23/Feb/15 ]

WIth the understanding that this can be improved substantially, you should see that subsequent calls to listDatabases are much faster.

Comment by Chad Kreimendahl [ 23/Feb/15 ]

This is specifically making any call to listDatabases take extraordinarily long. This makes "DatabaseExists()" calls in C# quite long.

Comment by Daniel Pasette (Inactive) [ 09/Feb/15 ]

The size on disk can be quite different than the size of the documents stored in-memory. In mmap because of record padding and in wired tiger because of compression. I would venture to say that the size is not "necessary" – it's an interface that was designed when getting the value was extremely cheap.

Comment by Chad Kreimendahl [ 09/Feb/15 ]

Is it possible to get the in-memory size vs on-disk size? Would they correlate well? Is size necessary when listing databases?

Comment by Daniel Pasette (Inactive) [ 08/Feb/15 ]

We have a fix in WT which makes this about 50% faster, but that's not really enough.
Looks like we will have to change how we calculate the size for listDatabases. Maybe use the sizeStorer collection rather than stat'ing each individual file.

Comment by Chad Kreimendahl [ 05/Feb/15 ]

Thanks for the update. For us this causes substantial issues when our code migration tool runs our "database upgrade" functions, which list each database, open them and see what work needs to be done for when we deploy new code. Ultimately we only do that about once a month, so it's not terrible. The UI tools we use for manually editing on our own systems, including dev take a long time to open because of this... however, it's not a show stopper, as it doesn't get called when using our software.

Comment by Daniel Pasette (Inactive) [ 05/Feb/15 ]

Work is in progress on this, but not leaving this in as a showstopper. We'll evaluate solutions when they are prepared.

Comment by Mark Benvenuto [ 04/Feb/15 ]

Basically, the issue is that we have two O(N) loops where N = 2 * Collections + User Indexes that hurt performance during the statistics scan.

Repro script

for(i = 0; i < 8000; i++ ) { c = db.getCollection("i" + i); j = { b : 1 }; c.createIndex( j ); }

VS Profiler Trace

Function Name	Module Name	Inclusive Samples	Exclusive Samples	Inclusive Samples %	Exclusive Samples %
mongo::Command::execCommand	mongod.exe	21,841	0	94.07	0.00
mongo::_execCommand	mongod.exe	21,841	0	94.07	0.00
mongo::CmdListDatabases::run	mongod.exe	21,841	0	94.07	0.00
mongo::KVDatabaseCatalogEntry::sizeOnDisk	mongod.exe	21,841	7	94.07	0.03
mongo::WiredTigerKVEngine::getIdentSize	mongod.exe	11,318	1	48.75	0.00
mongo::WiredTigerUtil::getIdentSize	mongod.exe	11,306	3	48.69	0.01
mongo::WiredTigerUtil::getStatisticsValueAs<__int64>	mongod.exe	11,290	1	48.63	0.00
mongo::WiredTigerUtil::getStatisticsValueAs<__int64>	mongod.exe	11,289	3	48.62	0.01
mongo::WiredTigerUtil::getStatisticsValue	mongod.exe	11,286	3	48.61	0.01
__session_open_cursor	mongod.exe	11,252	3	48.46	0.01
__wt_open_cursor	mongod.exe	11,233	1	48.38	0.00
__wt_curstat_open	mongod.exe	11,226	2	48.35	0.01
__wt_curstat_init	mongod.exe	11,111	0	47.86	0.00
__wt_curstat_table_init	mongod.exe	11,110	1	47.85	0.00
__wt_curstat_open	mongod.exe	10,366	0	44.65	0.00
__wt_curstat_init	mongod.exe	10,249	1	44.14	0.00
__wt_curstat_colgroup_init	mongod.exe	10,246	3	44.13	0.01
__wt_curstat_init	mongod.exe	10,228	0	44.05	0.00
__curstat_file_init	mongod.exe	10,228	1	44.05	0.00
__wt_session_get_btree_ckpt	mongod.exe	10,156	2	43.74	0.01
__wt_session_get_btree	mongod.exe	10,137	75	43.66	0.32
__wt_conn_btree_get	mongod.exe	9,745	1	41.97	0.00
__conn_btree_open	mongod.exe	9,733	2	41.92	0.01
__wt_btree_open	mongod.exe	9,652	0	41.57	0.00
__wt_block_manager_open	mongod.exe	7,878	0	33.93	0.00
__wt_block_open	mongod.exe	7,875	3,283	33.92	14.14
__wt_open	mongod.exe	4,297	3,839	18.51	16.53

The problem is this code in __wt_open and __wt_block_open. This is where ~30% of the time is spent just checking the stats of the collection in this particular stack trace.

	__wt_spin_lock(session, &conn->fh_lock);
	TAILQ_FOREACH(tfh, &conn->fhqh, q)
		if (strcmp(name, tfh->name) == 0) {
			++tfh->ref;
			*fhp = tfh;
			matched = 1;
			break;
		}

Comment by Chad Kreimendahl [ 03/Feb/15 ]

Anything?

Comment by Chad Kreimendahl [ 28/Jan/15 ]

Here's the output from a process monitor of what happens with mongod when I run show databases.

Comment by Chad Kreimendahl [ 28/Jan/15 ]

Sure. Of note: this does run quite a bit faster on a system with SSDs, but it's still 10 seconds, while fully pegging CPU. Also, when getting the stats on databases for you, I noticed that db.stats() takes quite a bit of time. It seems to correlate fairly well with the number of indexes in a given database, versus size.

 

  • Windows Server 2012 R2 or Windows 8.1 – essentially equivalent OS
  • CPU Load of 1-3% prior to run
  • CPU Load equivalent of 1 core while running
  • No meaningful disk operations happening on either hardware (8.1) or virtual machine (2012r2)
  • At least 2-4GB of free memory
  • No swap usage
  • Databases: 16
  • Collections: 1306 – ranging from 1 to 261 per database
  • Objects: 1.16mil – ranging from 4 to 557,000
  • DataSize: 1G – ranging from 6k to 421m
  • Indexes: 7407 – ranging from 1 to 1788
  • IndexSize: 124M – ranging from 36k to 28m
Comment by Ramon Fernandez Marina [ 28/Jan/15 ]

sallgeud, can you please provide some more details about your setup and what kind of load it has? I launched both a stand-alone node and a 3-node replica set (on the same machine) and fired up 700 processes inserting data in 30 databases, each with 10 collections. The load on my system is past 300:

$ w
 11:19:11 up 67 days, 21:38,  1 user,  load average: 344.64, 197.55, 82.80

but even under these conditions running the "show databases" command takes only a fraction of a second.

Comment by Chad Kreimendahl [ 27/Jan/15 ]

Of note is that it also appears to be using the entirety of a core of a CPU, no real change in memory usage and no substantial io load on the disks.

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