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.

Sign up for GitHub

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

Jump to bottom

Long MongoDB queries - performance #22193

Closed
emikolajczak opened this issue May 31, 2021 · 14 comments
Closed

Long MongoDB queries - performance #22193

emikolajczak opened this issue May 31, 2021 · 14 comments

Comments

@emikolajczak
Copy link

emikolajczak commented May 31, 2021 •
edited
Loading

Description:

Hi, after upgrade to 3.14.0 I see in MongoDB logs a lots notifications about long last queries as below example

2021-05-28T10:46:50.657+0200 I COMMAND [conn322090] command rocketchat.rocketchat_message command: find { find: "rocketchat_message", filter: { _hidden: { $ne: true }, rid: "pwcbshayJiYEzQhJt", tcount: { $exists: true } }, sort: { tlm: -1 }, projection: { joinCode: 0, members: 0, importIds: 0, e2e: 0 }, limit: 25, returnKey: false, showRecordId: false, lsid: { id: UUID("13b58f4a-bb53-4300-8715-dc11ddc145dc") }, $clusterTime: { clusterTime: Timestamp(1622191610, 53), signature: { hash: BinData(0, B4E712374B9B6A2DF772871112E9BFFB109EB878), keyId: 6945063607709204546 } }, $db: "rocketchat" } planSummary: IXSCAN { tcount: 1, tlm: 1 } keysExamined:43586 docsExamined:43586 hasSortStage:1 cursorExhausted:1 numYields:340 nreturned:25 reslen:14672 locks:{ Global: { acquireCount: { r: 341 } }, Database: { acquireCount: { r: 341 } }, Collection: { acquireCount: { r: 341 } } } storage:{} protocol:op_msg 356ms

Before upgrade, on 3.9.7 version no entries about this query. I think it may be a cause heaviest load on DB.

Also graph for Meteor facts looks strange. In time this jumps of mongo-livedata time-spent-in-QUERYING-phase is see slow down of Rocket.Chat (greyed out messages i.e.)

image

EDIT:

From time to time you can observe spikes in Meteor facts

image

Let me know if you need more graphs or data for analysis.

Steps to reproduce:

  1. Check MongoDb logs for long processing queries
  2. Check Meteor facts graph in Metrics

Expected behavior:

No long processing operations in Db logs

Actual behavior:

A lot of long processing queries

Server Setup Information:

  • Version of Rocket.Chat Server: 3.14.0
  • Operating System: Centos7
  • Deployment Method: docker-compose
  • Number of Running Instances: 33
  • DB Replicaset Oplog: YES
  • NodeJS Version: v12.22.1
  • MongoDB Version: 4.0.14

Client Setup Information

  • Desktop App or Browser Version: all
  • Operating System: Windows 10

Additional context

Relevant logs:
@johncrisp
Copy link

Hi Emil and thanks for reporting this.

There are a number of performance related Issues that you and Anton have reported recently.

I am wondering if we should collect them up and add them to our list of things to be looked at?

@emikolajczak
Copy link
Author

Hi John,
I think yes, performance issues are crucial in my opinion.

@artemChernitsov
Copy link

I have the same issue too.

@emikolajczak
Copy link
Author

emikolajczak commented Jun 2, 2021 •
edited
Loading

I suspect that this not optimal query was introduced in this feature 2b5831b

EDIT:
Also this query looks not optimal
2021-06-02T10:53:57.948+0200 I COMMAND [conn488219] command rocketchat.rocketchat_message command: count { count: "rocketchat_message", query: { _hidden: { $ne: true }, rid: "ErugisFhNTY95nF7StZHfLkDnPBkPSR6zx", tcount: { $exists: true } }, $clusterTime: { clusterTime: Timestamp(1622624037, 54), signature: { hash: BinData(0, 8BF8A07A142B7567727454F3D7DED0A9486105A5), keyId: 6945063607709204546 } }, $db: "rocketchat" } planSummary: IXSCAN { tcount: 1, tlm: 1 } keysExamined:42835 docsExamined:42835 numYields:334 reslen:170 locks:{ Global: { acquireCount: { r: 335 } }, Database: { acquireCount: { r: 335 } }, Collection: { acquireCount: { r: 335 } } } storage:{} protocol:op_msg 348ms

@ankar84
Copy link

ankar84 commented Jun 9, 2021

Also this query looks not optimal

I guess it could be done for statistics count (info page).
In fact we can Disable Statistics Generator in Admin UI- Troubleshoot page.
image
I'm afraid to disable it because of this warning and may cause other missing information around the system! - maybe somewhere else something will broke.

@ankar84
Copy link

ankar84 commented Jun 9, 2021

And I think it would be really great if all search queries and statistics generation was dedicated to secondary mongodb node, which idle now all the time.
@johncrisp what do you think about it?

@ankar84 ankar84 mentioned this issue Jun 9, 2021
Closed
@ankar84
Copy link

ankar84 commented Jun 11, 2021 •
edited
Loading

Another example of find and count queries (I don't why there is so much similar queries) could lead to high mongodb CPU load
image

June 11th 2021, 11:12:46.692 | s-rc-db-02 | COMMAND  [conn41569] command rocketchat.rocketchat_message command: find { find: "rocketchat_message", filter: { _hidden: { $ne: true }, $text: { $search: "Ошибка дубликат. Введенные данные отличаются от данных в ЕВА.Отличия: Адрес факти�..." }, rid: "pXij9bp8PjTFkd2GY", tcount: { $exists: true } }, sort: { tlm: -1 }, projection: { joinCode: 0, members: 0, importIds: 0, e2e: 0 }, limit: 25, returnKey: false, showRecordId: false, lsid: { id: UUID("9f2f3bed-d01d-481f-a8b0-68013c0fefc0") }, $clusterTime: { clusterTime: Timestamp(1623399139, 98), signature: { hash: BinData(0, 5ABB3E1D611EE7242E616039AD81052188CEEDAA), keyId: 6920770581193293826 } }, $db: "rocketchat" } planSummary: IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 } keysExamined:3248752 docsExamined:5893352 hasSortStage:1 cursorExhausted:1 numYields:25387 nreturned:25 queryHash:2588F27B planCacheKey:911B0AA7 reslen:25714 locks:{ ReplicationStateTransition: { acquireCount: { w: 25389 } }, Global: { acquireCount: { r: 25389 } }, Database: { acquireCount: { r: 25389 } }, Collection: { acquireCount: { r: 25389 } }, Mutex: { acquireCount: { r: 2 } } } storage:{ data: { bytesRead: 3 } } protocol:op_msg 24766ms
June 11th 2021, 11:12:46.692 | s-rc-db-02 | COMMAND  [conn41568] command rocketchat.rocketchat_message command: find { find: "rocketchat_message", filter: { _hidden: { $ne: true }, $text: { $search: "Ошибка дубликат. Введенные данные отличаются от данных в ЕВА.Отличия: Адрес факти�..." }, rid: "pXij9bp8PjTFkd2GY", tcount: { $exists: true } }, sort: { tlm: -1 }, projection: { joinCode: 0, members: 0, importIds: 0, e2e: 0 }, limit: 25, returnKey: false, showRecordId: false, lsid: { id: UUID("d327da45-71a8-4ba4-bea8-83ba1e368d14") }, $clusterTime: { clusterTime: Timestamp(1623399117, 117), signature: { hash: BinData(0, A623661040777069267E386B52527A1B7C8E4630), keyId: 6920770581193293826 } }, $db: "rocketchat" } planSummary: IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 } keysExamined:3248752 docsExamined:5893352 hasSortStage:1 cursorExhausted:1 numYields:25385 nreturned:25 queryHash:2588F27B planCacheKey:911B0AA7 reslen:25714 locks:{ ReplicationStateTransition: { acquireCount: { w: 25387 } }, Global: { acquireCount: { r: 25387 } }, Database: { acquireCount: { r: 25387 } }, Collection: { acquireCount: { r: 25387 } }, Mutex: { acquireCount: { r: 2 } } } storage:{} protocol:op_msg 24661ms
June 11th 2021, 11:12:46.692 | s-rc-db-02 | COMMAND  [conn41563] command rocketchat.rocketchat_message command: find { find: "rocketchat_message", filter: { _hidden: { $ne: true }, $text: { $search: "Ошибка дубликат. Введенные данные отличаются от данных в ЕВА.Отличия: Адрес факти�..." }, rid: "pXij9bp8PjTFkd2GY", tcount: { $exists: true } }, sort: { tlm: -1 }, projection: { joinCode: 0, members: 0, importIds: 0, e2e: 0 }, limit: 25, returnKey: false, showRecordId: false, lsid: { id: UUID("0bb05573-8824-49ae-96fc-d0506c202806") }, $clusterTime: { clusterTime: Timestamp(1623399139, 98), signature: { hash: BinData(0, 5ABB3E1D611EE7242E616039AD81052188CEEDAA), keyId: 6920770581193293826 } }, $db: "rocketchat" } planSummary: IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 } keysExamined:3248752 docsExamined:5893352 hasSortStage:1 cursorExhausted:1 numYields:25387 nreturned:25 queryHash:2588F27B planCacheKey:911B0AA7 reslen:25714 locks:{ ReplicationStateTransition: { acquireCount: { w: 25389 } }, Global: { acquireCount: { r: 25389 } }, Database: { acquireCount: { r: 25389 } }, Collection: { acquireCount: { r: 25389 } }, Mutex: { acquireCount: { r: 2 } } } storage:{ data: { bytesRead: 1 } } protocol:op_msg 24914ms
June 11th 2021, 11:11:58.692 | s-rc-db-02 | COMMAND  [conn41563] command rocketchat.rocketchat_message command: count { count: "rocketchat_message", query: { _hidden: { $ne: true }, $text: { $search: "Ошибка дубликат. Введенные данные отличаются от данных в ЕВА.Отличия: Адрес факти�..." }, rid: "pXij9bp8PjTFkd2GY", tcount: { $exists: true } }, $clusterTime: { clusterTime: Timestamp(1623399096, 117), signature: { hash: BinData(0, 1D9BAB4F7B31357DD29E00D5D9F927A0C2AF385B), keyId: 6920770581193293826 } }, $db: "rocketchat" } planSummary: IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 } keysExamined:3248721 docsExamined:5893296 numYields:25386 queryHash:37B2DC84 planCacheKey:CAA00240 reslen:170 locks:{ ReplicationStateTransition: { acquireCount: { w: 25388 } }, Global: { acquireCount: { r: 25388 } }, Database: { acquireCount: { r: 25388 } }, Collection: { acquireCount: { r: 25388 } }, Mutex: { acquireCount: { r: 2 } } } storage:{ data: { bytesRead: 884225, timeReadingMicros: 1598 } } protocol:op_msg 21634ms
June 11th 2021, 11:12:21.693 | s-rc-db-02 | COMMAND  [conn41568] command rocketchat.rocketchat_message command: count { count: "rocketchat_message", query: { _hidden: { $ne: true }, $text: { $search: "Ошибка дубликат. Введенные данные отличаются от данных в ЕВА.Отличия: Адрес факти�..." }, rid: "pXij9bp8PjTFkd2GY", tcount: { $exists: true } }, $clusterTime: { clusterTime: Timestamp(1623399116, 53), signature: { hash: BinData(0, 352D2E387C471756097E15DA64ED53F81BAAB9B0), keyId: 6920770581193293826 } }, $db: "rocketchat" } planSummary: IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 } keysExamined:3248737 docsExamined:5893324 numYields:25387 queryHash:37B2DC84 planCacheKey:CAA00240 reslen:170 locks:{ ReplicationStateTransition: { acquireCount: { w: 25389 } }, Global: { acquireCount: { r: 25389 } }, Database: { acquireCount: { r: 25389 } }, Collection: { acquireCount: { r: 25389 } }, Mutex: { acquireCount: { r: 2 } } } storage:{} protocol:op_msg 23809ms
June 11th 2021, 11:12:21.692 | s-rc-db-02 | COMMAND  [conn41567] command rocketchat.rocketchat_message command: count { count: "rocketchat_message", query: { _hidden: { $ne: true }, $text: { $search: "Ошибка дубликат. Введенные данные отличаются от данных в ЕВА.Отличия: Адрес факти�..." }, rid: "pXij9bp8PjTFkd2GY", tcount: { $exists: true } }, $clusterTime: { clusterTime: Timestamp(1623399116, 55), signature: { hash: BinData(0, 352D2E387C471756097E15DA64ED53F81BAAB9B0), keyId: 6920770581193293826 } }, $db: "rocketchat" } planSummary: IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 } keysExamined:3248735 docsExamined:5893322 numYields:25388 queryHash:37B2DC84 planCacheKey:CAA00240 reslen:170 locks:{ ReplicationStateTransition: { acquireCount: { w: 25390 } }, Global: { acquireCount: { r: 25390 } }, Database: { acquireCount: { r: 25390 } }, Collection: { acquireCount: { r: 25390 } }, Mutex: { acquireCount: { r: 2 } } } storage:{ data: { bytesRead: 776636, timeReadingMicros: 1197 } } protocol:op_msg 23643ms
June 11th 2021, 11:12:21.692 | s-rc-db-02 | COMMAND  [conn41569] command rocketchat.rocketchat_message command: count { count: "rocketchat_message", query: { _hidden: { $ne: true }, $text: { $search: "Ошибка дубликат. Введенные данные отличаются от данных в ЕВА.Отличия: Адрес факти�..." }, rid: "pXij9bp8PjTFkd2GY", tcount: { $exists: true } }, $clusterTime: { clusterTime: Timestamp(1623399116, 55), signature: { hash: BinData(0, 352D2E387C471756097E15DA64ED53F81BAAB9B0), keyId: 6920770581193293826 } }, $db: "rocketchat" } planSummary: IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 } keysExamined:3248735 docsExamined:5893322 numYields:25388 queryHash:37B2DC84 planCacheKey:CAA00240 reslen:170 locks:{ ReplicationStateTransition: { acquireCount: { w: 25390 } }, Global: { acquireCount: { r: 25390 } }, Database: { acquireCount: { r: 25390 } }, Collection: { acquireCount: { r: 25390 } }, Mutex: { acquireCount: { r: 2 } } } storage:{ data: { bytesRead: 36769, timeReadingMicros: 83 } } protocol:op_msg 23582ms
June 11th 2021, 11:12:21.692 | s-rc-db-02 | COMMAND  [conn41566] command rocketchat.rocketchat_message command: count { count: "rocketchat_message", query: { _hidden: { $ne: true }, $text: { $search: "Ошибка дубликат. Введенные данные отличаются от данных в ЕВА.Отличия: Адрес факти�..." }, rid: "pXij9bp8PjTFkd2GY", tcount: { $exists: true } }, $clusterTime: { clusterTime: Timestamp(1623399116, 53), signature: { hash: BinData(0, 352D2E387C471756097E15DA64ED53F81BAAB9B0), keyId: 6920770581193293826 } }, $db: "rocketchat" } planSummary: IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 } keysExamined:3248735 docsExamined:5893322 numYields:25387 queryHash:37B2DC84 planCacheKey:CAA00240 reslen:170 locks:{ ReplicationStateTransition: { acquireCount: { w: 25389 } }, Global: { acquireCount: { r: 25389 } }, Database: { acquireCount: { r: 25389 } }, Collection: { acquireCount: { r: 25389 } }, Mutex: { acquireCount: { r: 2 } } } storage:{ data: { bytesRead: 237434, timeReadingMicros: 468 } } protocol:op_msg 23582ms
June 11th 2021, 11:11:36.695 | s-rc-db-02 | COMMAND  [conn41563] command rocketchat.rocketchat_message command: find { find: "rocketchat_message", filter: { _hidden: { $ne: true }, $text: { $search: "Ошибка дубликат. Введенные данные отличаются от данных в ЕВА.Отличия: Адрес факти�..." }, rid: "pXij9bp8PjTFkd2GY", tcount: { $exists: true } }, sort: { tlm: -1 }, projection: { joinCode: 0, members: 0, importIds: 0, e2e: 0 }, limit: 25, returnKey: false, showRecordId: false, lsid: { id: UUID("8aa8d708-5643-464a-b4b7-63c7b7477c2a") }, $clusterTime: { clusterTime: Timestamp(1623399076, 30), signature: { hash: BinData(0, 646A04C96B76F55240936B509BA438F4A535050D), keyId: 6920770581193293826 } }, $db: "rocketchat" } planSummary: IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 } keysExamined:3248702 docsExamined:5893266 hasSortStage:1 cursorExhausted:1 numYields:25385 nreturned:25 queryHash:2588F27B planCacheKey:911B0AA7 reslen:26071 locks:{ ReplicationStateTransition: { acquireCount: { w: 25387 } }, Global: { acquireCount: { r: 25387 } }, Database: { acquireCount: { r: 25387 } }, Collection: { acquireCount: { r: 25387 } }, Mutex: { acquireCount: { r: 2 } } } storage:{} protocol:op_msg 19889ms
June 11th 2021, 11:11:16.693 | s-rc-db-02 | COMMAND  [conn41568] command rocketchat.rocketchat_message command: count { count: "rocketchat_message", query: { _hidden: { $ne: true }, $text: { $search: "Ошибка дубликат. Введенные данные отличаются от данных в ЕВА.Отличия: Адрес факти�..." }, rid: "pXij9bp8PjTFkd2GY", tcount: { $exists: true } }, $clusterTime: { clusterTime: Timestamp(1623399054, 54), signature: { hash: BinData(0, FF0EA69DADF7F128A29AF0468BD04BB53DCC71ED), keyId: 6920770581193293826 } }, $db: "rocketchat" } planSummary: IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 } keysExamined:3248667 docsExamined:5893234 numYields:25385 queryHash:37B2DC84 planCacheKey:CAA00240 reslen:170 locks:{ ReplicationStateTransition: { acquireCount: { w: 25387 } }, Global: { acquireCount: { r: 25387 } }, Database: { acquireCount: { r: 25387 } }, Collection: { acquireCount: { r: 25387 } }, Mutex: { acquireCount: { r: 2 } } } storage:{ data: { bytesRead: 291541, timeReadingMicros: 969 } } protocol:op_msg 21680ms

@ankar84 ankar84 mentioned this issue Jun 15, 2021
Merged
10 tasks
@danielfariati
Copy link

One query that is causing a high CPU in our mongo is the one used by "Search messages" feature, inside a chat room.

Sample query:

{"find": "rocketchat_message", "filter": {"$text": {"$search": "text"}, "t": {"$ne": "rm"}, "_hidden": {"$ne": true}, "rid": "rQGcHzjtdmboD8ijT"}, "sort": {"ts": new NumberInt("-1")}, "projection": {"score": {"$meta": "textScore"}}, "limit": new NumberInt("10"), "returnKey": false, "showRecordId": false, "lsid": {"id": new UUID("7e3e73d6-5681-4f01-ac9c-c4b28d10563d")}, "$clusterTime": {"clusterTime": new Timestamp(24, 1624650911), "signature": {"hash": new BinData(0, "SsFxamVYlty4vBUqOMwK2ak1wys="), "keyId": new NumberLong("6929517290681532417")}}, "$db": "rocketchat", "$readPreference": {"mode": "secondaryPreferred"}}

docsExamined: 1658624
planSummary: IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }

I believe that an index using room id (rid) would solve this problem.
The instance spiked from ~10% to 100% CPU usage when this query was executed.

@ankar84
Copy link

ankar84 commented Jun 26, 2021 •
edited
Loading

{"mode": "secondaryPreferred"}

Hello, Daniel!
That query made a CPU peak on secondary or primary node of your mongodb? According to mode it must be on secondary which is great. In my case all expensive queries are on primary node which lead to freezes in messaging for users.

Did you enable global search is Admin UI?

Upd.
By the way, I just enabled Global search with default provider and test it a bit because today is a weekend and very low traffic on our RC deployment. Results a pretty good, according to mongo logs all my global search queries was executed on secondary node. I even started htop on secondary node and made global searches - CPU was a bit higher on my queries.
One thing is remain unclear to me - operations graph didn't show my activity at all.
image

@danielfariati
Copy link

Hey, @ankar84.

Secondary, thankfully.
No, global search is not enabled.

@guba-jeckerman
Copy link

Are there other tables that would benefit from added indexes?

@ankar84
Copy link

ankar84 commented Jul 19, 2021

No, global search is not enabled.

Yeap, I enabled it, but still see CPU peaks on primary node
image

@ankar84
Copy link

ankar84 commented Jul 27, 2021 •
edited
Loading

another example of expensive query

COMMAND  [conn193345] command rocketchat.rocketchat_message command: count { count: "rocketchat_message", query: { _hidden: { $ne: true }, $text: { $search: "а как" }, rid: "T4XJ8nLDiCsJ8zPco", tcount: { $exists: true } }, $clusterTime: { clusterTime: Timestamp(1627359964, 20), signature: { hash: BinData(0, 74AA86B0772BFD658C9CF679B7CA3442385E2E7E), keyId: 6947176989316874242 } }, $db: "rocketchat" } planSummary: IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 } keysExamined:2381813 docsExamined:4494470 numYields:18610 queryHash:37B2DC84 planCacheKey:CAA00240 reslen:170 locks:{ ReplicationStateTransition: { acquireCount: { w: 18612 } }, Global: { acquireCount: { r: 18612 } }, Database: { acquireCount: { r: 18612 } }, Collection: { acquireCount: { r: 18612 } }, Mutex: { acquireCount: { r: 2 } } } storage:{} protocol:op_msg 14369ms
COMMAND  [conn200465] command rocketchat.rocketchat_message command: find { find: "rocketchat_message", filter: { _hidden: { $ne: true }, $text: { $search: "Не введено поле 'Ули�..." }, rid: "pXij9bp8PjTFkd2GY", tcount: { $exists: true } }, sort: { tlm: -1 }, projection: { joinCode: 0, members: 0, importIds: 0, e2e: 0 }, limit: 25, returnKey: false, showRecordId: false, lsid: { id: UUID("29eee306-44dc-4aa8-a9d3-6d22f95ebd22") }, $clusterTime: { clusterTime: Timestamp(1627442216, 2), signature: { hash: BinData(0, 0CBC3B7E1B05E694F2532D4FB4825530D7A9F732), keyId: 6947176989316874242 } }, $db: "rocketchat" } planSummary: IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 }, IXSCAN { _fts: "text", _ftsx: 1 } keysExamined:5171885 docsExamined:8644710 hasSortStage:1 cursorExhausted:1 numYields:40411 nreturned:25 queryHash:2588F27B planCacheKey:911B0AA7 reslen:22288 locks:{ ReplicationStateTransition: { acquireCount: { w: 40413 } }, Global: { acquireCount: { r: 40413 } }, Database: { acquireCount: { r: 40413 } }, Collection: { acquireCount: { r: 40413 } }, Mutex: { acquireCount: { r: 2 } } } storage:{} protocol:op_msg 28499ms

@ankar84 ankar84 mentioned this issue Aug 26, 2021
Draft
@sampaiodiego
Copy link
Member

hey guys.. the slow queries using tcount or tlm are threads related. we have added the appropriate indexes on #22879

the indexes will be released on 3.18.0 but are already available at 3.18.0-rc.0 if you want to try it out.

you can also try applying the indexes manually if you don't want to try a new version (see https://github.com/RocketChat/Rocket.Chat/pull/22879/files#diff-7329ec5df7668119aeae5fc2b79061127fd3059bd0ff3b2e9eaf9c36236dbf2cR33-R34)

if you try it out, pls let me know if they help.. thx.

@ankar84 ankar84 mentioned this issue Aug 27, 2021
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
7 participants
@danielfariati @ankar84 @sampaiodiego @guba-jeckerman @artemChernitsov @emikolajczak @johncrisp