Adding a new database gets longer the more databases exist (listDatabase hits again)

Depending on the number of existing databases, it turns out that the creation time increases. It turns out listDatabases is called during the creation.

Question : is this call (listDatabase) originated from Percona or is it from MongoDB ?

{
“t”: {
“$date”: “2022-01-24T13:46:28.014+00:00”
},
“s”: “I”,
“c”: “COMMAND”,
“id”: 51803,
“ctx”: “conn277”,
“msg”: “Slow query”,
“attr”: {
“type”: “command”,
“ns”: “admin.$cmd”,
“command”: {
“listDatabases”: 1,
“maxTimeMS”: 600000,
“lsid”: {
“id”: {
“$uuid”: “e4858e8d-b4f3-4813-9db0-2b52643e6218”
},
“uid”: {
“$binary”: {
“base64”: “YGti/c5Tn4R/bgcsJkGhJh0d/qtIaBxXR/b+7uzn4M0=”,
“subType”: “0”
}
}
},
“$readPreference”: {
“mode”: “primaryPreferred”
},
“$clusterTime”: {
“clusterTime”: {
“$timestamp”: {
“t”: 1643031982,
“i”: 1
}
},
“signature”: {
“hash”: {
“$binary”: {
“base64”: “0zndY6QZhQTibmGSshvJT06DYos=”,
“subType”: “0”
}
},
“keyId”: 7056733904161472534
}
},
“$audit”: {
“$impersonatedUsers”: [
{
“user”: “db_9307”,
“db”: “db_9307”
}
],
“$impersonatedRoles”: [
{
“role”: “dbOwner”,
“db”: “db_9307”
}
]
},
“$client”: {
“driver”: {
“name”: “mongo-java-driver|legacy”,
“version”: “3.12.8”
},
“os”: {
“type”: “Windows”,
“name”: “Windows 10”,
“architecture”: “amd64”,
“version”: “10.0”
},
“platform”: “Java/Oracle Corporation/1.8.0_191-b12”,
“mongos”: {
“host”: “xxx-mongodb01-cluster-mongos-547975446f-4st85:27017”,
“client”: “127.0.0.1:41310”,
“version”: “4.4.10-11”
}
},
“$configServerState”: {
“opTime”: {
“ts”: {
“$timestamp”: {
“t”: 1643031982,
“i”: 1
}
},
“t”: 6
}
},
“$db”: “admin”
},
“numYields”: 0,
“reslen”: 595375,
“locks”: {
“ParallelBatchWriterMode”: {
“acquireCount”: {
“r”: 10300
}
},
“ReplicationStateTransition”: {
“acquireCount”: {
“w”: 10300
}
},
“Global”: {
“acquireCount”: {
“r”: 10300
}
},
“Database”: {
“acquireCount”: {
“r”: 10299
}
},
“Collection”: {
“acquireCount”: {
“r”: 51504
}
},
“Mutex”: {
“acquireCount”: {
“r”: 10299
}
},
“oplog”: {
“acquireCount”: {
“r”: 1
}
}
},
“storage”: {},
“protocol”: “op_msg”,
“durationMillis”: 5849
}
}

1 Like

Pls close - it’s MongoDB related

1 Like

Hello @jamoser! Are you tracking it on MongoDB side somehow?
Which version of MongoDB is it?

1 Like

As I said, you can close the ticket because it’s MongoDB related

1 Like

@jamoser I understand that it is MongoDB related, but I’m thinking we can fix it in Percona Server for MongoDB itself.

1 Like

I’ve already placed a ticket → https://jira.mongodb.org/browse/SERVER-62909

But seems this issue has already been fixed for 5.2 - but not for the 4.x version

1 Like

If it helps to analyse - some code snippets:

Creation of DB - approx xxx ms:

		    MongoDatabase db =  mongoClient.getDatabase(tenantId);
		    BasicDBObject command = new BasicDBObject("createUser", tenantId).append("pwd", myPwd).append("roles",
                    Collections.singletonList(new BasicDBObject("role", "dbOwner").append("db", tenantId)));
		    db.runCommand(command);

Add first collection - approx xx’xxx ms when having 50k databases, only here listDatabases() is called (?!), which takes xx’xxx ms:

		MongoDatabase database = mongoClient.getDatabase(tenantId);
		MongoCollection<Document> collection = database.getCollection("first_coll");
		collection.insertOne(first_coll_doc);

Add second collection - approx xx ms, no listDatabases() is called:

		MongoDatabase database = mongoClient.getDatabase(tenantId);
		MongoCollection<Document> collection = database.getCollection("second_coll");
		collection.insertOne(second_coll_doc);
1 Like

I have to revoke my request to close the ticket. After all I am not sure if this is related to Percona.

Could you please check if listDatabase is called by “Percona code” ? (Mainly because SHARDING is not part of the original MongoDB code).

1 Like

Hello @jamoser
Percona code does not call listDatabase.
That SHARDING message with id = 21950 is part of original MongoDB code. Here is v4.4 source: https://github.com/mongodb/mongo/blob/v4.4/src/mongo/db/s/database_sharding_state.cpp#L123-L127
But that message was removed in v5.0 so I guess your log snippet is from v4.4 or probably v4.2.

2 Likes

but I’m thinking we can fix it in Percona Server for MongoDB itself.

Ok - the Mongodb guys are a little bit helpless

→ if you guys could pick up this issue, that would be great !

Thanks & Regards
John

1 Like

@jamoser do you see the same behavior in 5.0?

1 Like

@spronin yes - and according to MongoDB, they say the slow execution of listdatabases() is fixed in version 5.2

1 Like

Are you talking about https://jira.mongodb.org/browse/SERVER-57357 or something else?

1 Like

@Igor_Solodovnikov … well that is what they claim.

1 Like

I am little bit stuck here - the mongodb team wants me to send the data from the diagnostic.data folder

bash-4.4$
bash-4.4$ ls diagnostic.data/
metrics.2022-02-22T23-51-01Z-00000 metrics.2022-02-26T02-56-01Z-00000 metrics.2022-03-01T06-49-10Z-00000 …

is there something related to Percona ?

1 Like

And again could you check on your side, if you call listDatabases() during the creation of the first collection of a newly created database ?

(PS: if someone can show me where to look for in the git repo, I could dig through the code myself)

1 Like

Percona code has no additional calls to listDatabases(). So all listDatabases() calls are inherited from upstream.

2 Likes

I think diagnostic.data folder is equivalent in PSMDB and in upstream MongoDB.

2 Likes

I’ve installed Install MongoDB Community Kubernetes Operator | MongoDB with MongoDB Version 4.4.6 on the same GKE env and the issue is not existent.

So the issue of the topic is related to Percona. Could you pls fix this issue.

1 Like

@Igor_Solodovnikov I think this is wrong and I am happy to prove that to you.

1 Like