RocketChat
Slow response on opening channels in Mobile clients
Description:
Specially on mobile clients, when opening a channel getting new messages is very slow.
Steps to reproduce:
- Open Rocketchat on mobile
- Open channel
- Getting new messages takes a long time
Expected behavior:
Expected new messages to be delivered more rapidly
Actual behavior:
Getting new messages takes a long time
Server Setup Information:
- Version of Rocket.Chat Server: 6.11.3
- License Type: (do not know)
- Number of Users: > 100
- Operating System: Debian GNU/Linux 12
- Deployment Method: docker
- Number of Running Instances: 1
- DB Replicaset Oplog: (do not know)
- NodeJS Version: (do not know)
- MongoDB Version: 5.0
Client Setup Information
- Desktop App or Browser Version: 4.53.0.66079
- Operating System: Android 14
Additional context
I created a new index and the response time improved a lot
db.rocketchat_message.createIndex( { rid: 1, _updatedAt: 1 } )
Relevant logs:
{"level":35,"time":"2024-10-07T10:34:50.213Z","pid":1,"hostname":"3d5f89fd59e3","name":"API","method":"GET","url":"/api/v1/chat.syncMessages?roomId=AxLTJYLDYRyjjCLnL&lastUpdate=2024-10-01T14%3A23%3A11.361Z","userId":"6bLmqqHnXR9uYznnx","userAgent":"RC Mobile; android 14; v4.53.0 (66079)","host":"<redacted>","remoteIP":"172.16.190.6","status":200,"responseTime":120623}
{"t":{"$date":"2024-10-07T10:34:50.192+00:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn423","msg":"Slow query","attr":{"type":"command","ns":"rocketchat.rocketchat_message","command":{"find":"rocketchat_message","filter":{"_hidden":{"$ne":true},"rid":"AxLTJYLDYRyjjCLnL","_updatedAt":{"$gt":{"$date":"2024-10-01T14:23:11.361Z"}}},"sort":{"ts":-1},"lsid":{"id":{"$uuid":"aa3781a4-cf09-402d-aa8c-6493ff6f8ad5"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1728297168,"i":1}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$db":"rocketchat"},"planSummary":"IXSCAN { _updatedAt: 1 }","keysExamined":17519,"docsExamined":17519,"hasSortStage":true,"fromMultiPlanner":true,"cursorExhausted":true,"numYields":4537,"nreturned":54,"queryHash":"631DE22B","planCacheKey":"C84C94B6","reslen":51127,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":4538}},"Global":{"acquireCount":{"r":4538}},"Mutex":{"acquireCount":{"r":1}}},"readConcern":{"level":"local","provenance":"implicitDefault"},"storage":{"data":{"bytesRead":476778307,"timeReadingMicros":103564456}},"remote":"172.31.0.3:53238","protocol":"op_msg","durationMillis":120595}}
Executing the query in mongosh :
db.rocketchat_message.find({ _hidden: { $ne: true }, rid: "AxLTJYLDYRyjjCLnL", _updatedAt: { $gt: ISODate("2024-10-01T14:23:11.361Z") } }).explain('executionStats')
it show for executionStats:
nReturned: 57,
executionTimeMillis: 66040,
totalKeysExamined: 19604,
totalDocsExamined: 19604,
License Type: (do not know) Check in your Admin pages.
What sort of file storage are you using?
Also please follow the debugging guide:
Ensure you’re running the latest version of Rocket.Chat. An update might resolve your issue.
https://developer.rocket.chat/docs/contribute-through-bug-reporting
- License Type: Enterprise
What sort of file storage are you using?
ext4
I started with a fresh installation of rocketchat using the latest version and the index _updatedAt_1 does not exist. I do not know where it came from.
Disabling that index _updatedAt_1 and the new index rid_1__updatedAt_1
db.rocketchat_message.hideIndex("_updatedAt_1")
db.rocketchat_message.hideIndex("rid_1__updatedAt_1")
the query uses rid_1_t_1_u._id_1 and takes 209749 ms:
rs0 [direct: primary] rocketchat> db.rocketchat_message.find({ _hidden: { $ne: true }, rid: "AxLTJYLDYRyjjCLnL", _updatedAt: { $gt: ISODate("2024-10-01T14:23:11.361Z") } }).explain('executionStats')
{
explainVersion: '1',
queryPlanner: {
namespace: 'rocketchat.rocketchat_message',
indexFilterSet: false,
parsedQuery: {
'$and': [
{ rid: { '$eq': 'AxLTJYLDYRyjjCLnL' } },
{ _updatedAt: { '$gt': ISODate('2024-10-01T14:23:11.361Z') } },
{ _hidden: { '$not': { '$eq': true } } }
]
},
maxIndexedOrSolutionsReached: false,
maxIndexedAndSolutionsReached: false,
maxScansToExplodeReached: false,
winningPlan: {
stage: 'FETCH',
filter: {
'$and': [
{ _hidden: { '$not': { '$eq': true } } },
{
_updatedAt: { '$gt': ISODate('2024-10-01T14:23:11.361Z') }
}
]
},
inputStage: {
stage: 'IXSCAN',
keyPattern: { rid: 1, t: 1, 'u._id': 1 },
indexName: 'rid_1_t_1_u._id_1',
isMultiKey: false,
isUnique: false,
isSparse: false,
isPartial: false,
indexVersion: 1,
direction: 'forward',
indexBounds: {
rid: [ '["AxLTJYLDYRyjjCLnL", "AxLTJYLDYRyjjCLnL"]' ],
t: [ '[MinKey, MaxKey]' ],
'u._id': [ '[MinKey, MaxKey]' ]
}
}
},
rejectedPlans: [
{
stage: 'FETCH',
filter: { _hidden: { '$not': { '$eq': true } } },
inputStage: {
stage: 'IXSCAN',
keyPattern: { rid: 1, ts: 1, _updatedAt: 1 },
indexName: 'rid_1_ts_1__updatedAt_1',
isMultiKey: false,
multiKeyPaths: { rid: [], ts: [], _updatedAt: [] },
isUnique: false,
isSparse: false,
isPartial: false,
indexVersion: 2,
direction: 'forward',
indexBounds: {
rid: [ '["AxLTJYLDYRyjjCLnL", "AxLTJYLDYRyjjCLnL"]' ],
ts: [ '[MinKey, MaxKey]' ],
_updatedAt: [
'(new Date(1727792591361), new Date(9223372036854775807)]'
]
}
}
},
{
stage: 'FETCH',
filter: {
'$and': [
{ _hidden: { '$not': { '$eq': true } } },
{
_updatedAt: { '$gt': ISODate('2024-10-01T14:23:11.361Z') }
}
]
},
inputStage: {
stage: 'IXSCAN',
keyPattern: { rid: 1, tcount: 1 },
indexName: 'rid_1_tcount_1',
isMultiKey: false,
multiKeyPaths: { rid: [], tcount: [] },
isUnique: false,
isSparse: false,
isPartial: false,
indexVersion: 2,
direction: 'forward',
indexBounds: {
rid: [ '["AxLTJYLDYRyjjCLnL", "AxLTJYLDYRyjjCLnL"]' ],
tcount: [ '[MinKey, MaxKey]' ]
}
}
}
]
},
executionStats: {
executionSuccess: true,
nReturned: 165,
executionTimeMillis: 209749,
totalKeysExamined: 40638,
totalDocsExamined: 40638,
executionStages: {
stage: 'FETCH',
filter: {
'$and': [
{ _hidden: { '$not': { '$eq': true } } },
{
_updatedAt: { '$gt': ISODate('2024-10-01T14:23:11.361Z') }
}
]
},
nReturned: 165,
executionTimeMillisEstimate: 135633,
works: 40639,
advanced: 165,
needTime: 40473,
needYield: 0,
saveState: 7910,
restoreState: 7910,
isEOF: 1,
docsExamined: 40638,
alreadyHasObj: 0,
inputStage: {
stage: 'IXSCAN',
nReturned: 40638,
executionTimeMillisEstimate: 412,
works: 40639,
advanced: 40638,
needTime: 0,
needYield: 0,
saveState: 7910,
restoreState: 7910,
isEOF: 1,
keyPattern: { rid: 1, t: 1, 'u._id': 1 },
indexName: 'rid_1_t_1_u._id_1',
isMultiKey: false,
isUnique: false,
isSparse: false,
isPartial: false,
indexVersion: 1,
direction: 'forward',
indexBounds: {
rid: [ '["AxLTJYLDYRyjjCLnL", "AxLTJYLDYRyjjCLnL"]' ],
t: [ '[MinKey, MaxKey]' ],
'u._id': [ '[MinKey, MaxKey]' ]
},
keysExamined: 40638,
seeks: 1,
dupsTested: 0,
dupsDropped: 0
}
}
},
command: {
find: 'rocketchat_message',
filter: {
_hidden: { '$ne': true },
rid: 'AxLTJYLDYRyjjCLnL',
_updatedAt: { '$gt': ISODate('2024-10-01T14:23:11.361Z') }
},
'$db': 'rocketchat'
},
serverInfo: {
host: '592b0eaee581',
port: 27017,
version: '5.0.28',
gitVersion: 'a8f8b8e1e271f236e761d0138e2418d0a114c941'
},
serverParameters: {
internalQueryFacetBufferSizeBytes: 104857600,
internalQueryFacetMaxOutputDocSizeBytes: 104857600,
internalLookupStageIntermediateDocumentMaxSizeBytes: 104857600,
internalDocumentSourceGroupMaxMemoryBytes: 104857600,
internalQueryMaxBlockingSortMemoryUsageBytes: 104857600,
internalQueryProhibitBlockingMergeOnMongoS: 0,
internalQueryMaxAddToSetBytes: 104857600,
internalDocumentSourceSetWindowFieldsMaxMemoryBytes: 104857600
},
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1729172564, i: 2 }),
signature: {
hash: Binary.createFromBase64('AAAAAAAAAAAAAAAAAAAAAAAAAAA=', 0),
keyId: Long('0')
}
},
operationTime: Timestamp({ t: 1729172564, i: 2 })
}
Unhiding the new index db.rocketchat_message.unhideIndex("rid_1__updatedAt_1") the query takes 2307 ms:
db.rocketchat_message.find({ _hidden: { $ne: true }, rid: "AxLTJYLDYRyjjCLnL", _updatedAt: { $gt: ISODate("2024-10-01T14:23:11.361Z") } }).explain('executionStats')
{
explainVersion: '1',
queryPlanner: {
namespace: 'rocketchat.rocketchat_message',
indexFilterSet: false,
parsedQuery: {
'$and': [
{ rid: { '$eq': 'AxLTJYLDYRyjjCLnL' } },
{ _updatedAt: { '$gt': ISODate('2024-10-01T14:23:11.361Z') } },
{ _hidden: { '$not': { '$eq': true } } }
]
},
maxIndexedOrSolutionsReached: false,
maxIndexedAndSolutionsReached: false,
maxScansToExplodeReached: false,
winningPlan: {
stage: 'FETCH',
filter: { _hidden: { '$not': { '$eq': true } } },
inputStage: {
stage: 'IXSCAN',
keyPattern: { rid: 1, _updatedAt: 1 },
indexName: 'rid_1__updatedAt_1',
isMultiKey: false,
multiKeyPaths: { rid: [], _updatedAt: [] },
isUnique: false,
isSparse: false,
isPartial: false,
indexVersion: 2,
direction: 'forward',
indexBounds: {
rid: [ '["AxLTJYLDYRyjjCLnL", "AxLTJYLDYRyjjCLnL"]' ],
_updatedAt: [
'(new Date(1727792591361), new Date(9223372036854775807)]'
]
}
}
},
rejectedPlans: [
{
stage: 'FETCH',
filter: { _hidden: { '$not': { '$eq': true } } },
inputStage: {
stage: 'IXSCAN',
keyPattern: { rid: 1, ts: 1, _updatedAt: 1 },
indexName: 'rid_1_ts_1__updatedAt_1',
isMultiKey: false,
multiKeyPaths: { rid: [], ts: [], _updatedAt: [] },
isUnique: false,
isSparse: false,
isPartial: false,
indexVersion: 2,
direction: 'forward',
indexBounds: {
rid: [ '["AxLTJYLDYRyjjCLnL", "AxLTJYLDYRyjjCLnL"]' ],
ts: [ '[MinKey, MaxKey]' ],
_updatedAt: [
'(new Date(1727792591361), new Date(9223372036854775807)]'
]
}
}
},
{
stage: 'FETCH',
filter: {
'$and': [
{ _hidden: { '$not': { '$eq': true } } },
{
_updatedAt: { '$gt': ISODate('2024-10-01T14:23:11.361Z') }
}
]
},
inputStage: {
stage: 'IXSCAN',
keyPattern: { rid: 1, tcount: 1 },
indexName: 'rid_1_tcount_1',
isMultiKey: false,
multiKeyPaths: { rid: [], tcount: [] },
isUnique: false,
isSparse: false,
isPartial: false,
indexVersion: 2,
direction: 'forward',
indexBounds: {
rid: [ '["AxLTJYLDYRyjjCLnL", "AxLTJYLDYRyjjCLnL"]' ],
tcount: [ '[MinKey, MaxKey]' ]
}
}
},
{
stage: 'FETCH',
filter: {
'$and': [
{ _hidden: { '$not': { '$eq': true } } },
{
_updatedAt: { '$gt': ISODate('2024-10-01T14:23:11.361Z') }
}
]
},
inputStage: {
stage: 'IXSCAN',
keyPattern: { rid: 1, t: 1, 'u._id': 1 },
indexName: 'rid_1_t_1_u._id_1',
isMultiKey: false,
isUnique: false,
isSparse: false,
isPartial: false,
indexVersion: 1,
direction: 'forward',
indexBounds: {
rid: [ '["AxLTJYLDYRyjjCLnL", "AxLTJYLDYRyjjCLnL"]' ],
t: [ '[MinKey, MaxKey]' ],
'u._id': [ '[MinKey, MaxKey]' ]
}
}
}
]
},
executionStats: {
executionSuccess: true,
nReturned: 166,
executionTimeMillis: 2307,
totalKeysExamined: 166,
totalDocsExamined: 166,
executionStages: {
stage: 'FETCH',
filter: { _hidden: { '$not': { '$eq': true } } },
nReturned: 166,
executionTimeMillisEstimate: 221,
works: 167,
advanced: 166,
needTime: 0,
needYield: 0,
saveState: 65,
restoreState: 65,
isEOF: 1,
docsExamined: 166,
alreadyHasObj: 0,
inputStage: {
stage: 'IXSCAN',
nReturned: 166,
executionTimeMillisEstimate: 0,
works: 167,
advanced: 166,
needTime: 0,
needYield: 0,
saveState: 65,
restoreState: 65,
isEOF: 1,
keyPattern: { rid: 1, _updatedAt: 1 },
indexName: 'rid_1__updatedAt_1',
isMultiKey: false,
multiKeyPaths: { rid: [], _updatedAt: [] },
isUnique: false,
isSparse: false,
isPartial: false,
indexVersion: 2,
direction: 'forward',
indexBounds: {
rid: [ '["AxLTJYLDYRyjjCLnL", "AxLTJYLDYRyjjCLnL"]' ],
_updatedAt: [
'(new Date(1727792591361), new Date(9223372036854775807)]'
]
},
keysExamined: 166,
seeks: 1,
dupsTested: 0,
dupsDropped: 0
}
}
},
command: {
find: 'rocketchat_message',
filter: {
_hidden: { '$ne': true },
rid: 'AxLTJYLDYRyjjCLnL',
_updatedAt: { '$gt': ISODate('2024-10-01T14:23:11.361Z') }
},
'$db': 'rocketchat'
},
serverInfo: {
host: '592b0eaee581',
port: 27017,
version: '5.0.28',
gitVersion: 'a8f8b8e1e271f236e761d0138e2418d0a114c941'
},
serverParameters: {
internalQueryFacetBufferSizeBytes: 104857600,
internalQueryFacetMaxOutputDocSizeBytes: 104857600,
internalLookupStageIntermediateDocumentMaxSizeBytes: 104857600,
internalDocumentSourceGroupMaxMemoryBytes: 104857600,
internalQueryMaxBlockingSortMemoryUsageBytes: 104857600,
internalQueryProhibitBlockingMergeOnMongoS: 0,
internalQueryMaxAddToSetBytes: 104857600,
internalDocumentSourceSetWindowFieldsMaxMemoryBytes: 104857600
},
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1729173436, i: 1 }),
signature: {
hash: Binary.createFromBase64('AAAAAAAAAAAAAAAAAAAAAAAAAAA=', 0),
keyId: Long('0')
}
},
operationTime: Timestamp({ t: 1729173436, i: 1 })
}
- License Type: Enterprise
Open a ticket with support.
It's what you pay for and you will get a better response there than here.
What sort of file storage are you using?
ext4
Ok. Did you empty out GridFS before changing filestore?
I started with a fresh installation of rocketchat using the latest version and the index
_updatedAt_1does not exist. I do not know where it came from.
Please don't paste long logs here as it takes it hard to read. Use pastebin or similar.
No idea why you have done any of this or what you are trying to prove.
As per my debug notes, do the basics first.
Tell us about your general server hardware setup and reverse proxy.
Have you checked your websockets are working correctly - GridFS & websockets being the main cause of most speed issues.
Approximately how many channels/messages?
I am not the admin of this Rocketchat installation. I was just asked to help debug the slow performance. The logs pointed me towards the slow query.
Ok. Did you empty out GridFS before changing filestore?
do not know.
No idea why you have done any of this or what you are trying to prove.
Was trying to prove that a new index was needed.
As per my debug notes, do the basics first.
I thought I did. Did I miss anything ?
Have you checked your websockets are working correctly - GridFS & websockets being the main cause of most speed issues.
No. How to do that ? Can not find anything on it. Also, how does that explain the slow queries ?
Approximately how many channels/messages?
does this answer your question ?
rs0 [direct: primary] rocketchat> db.rocketchat_message.stats().count
7633136
rs0 [direct: primary] rocketchat> db.rocketchat_room.stats().count
15637
As per my debug notes, do the basics first.
I thought I did. Did I miss anything ?
Yup.
Have you checked your websockets are working correctly - GridFS & websockets being the main cause of most speed issues.
No. How to do that ? Can not find anything on it. Also, how does that explain the slow queries ?
So this shows the first reply is untrue because the FAQ tells you how to do this. Go back and read it all.
Rocket can handle 10s of thousand concurrent users with the right setup. You probably don't need to hack the database.
I am not the admin of this Rocketchat installation
In that case you need to get the admin on the case because they have info you need. You almost certainly won't fix it otherwise.
You are still guessing rather than doing the basic debugging and providing answers required.
Websockets, file storage, and reverse proxy are the first things to check. Tick them off.
does this answer your question ?
Yup. So with over 7+ million messages and 15+ thousand you probably have a busy server so we need to know some more information on your whole server setup.
Number of Running Instances: 1
You say >100 users. You may need more horsepower.
https://docs.rocket.chat/v1/docs/system-requirements
Alternatively if you have an Enterprise licence you can contact support....
This issue has been marked as stale because there has been no further activity in the last 10 days. If the issue remains stale for the next 4 days (a total of 14 days with no activity), then it will be assumed that the question has been resolved and the issue will be automatically closed.
![github-actions[bot] avatar](https://avatars.githubusercontent.com/in/15368?v=4 "Published by a pub.dev verified publisher"){kind=small}