Roadmap Reveal 🗺 What's next for Rocket.Chat, Sep 22

Rocketchat stock in gray-out when sending messages

Description

Hi,
its more than a year we launched rocketchat-server and using it, as data grows on database (now it is nearly 60GB) in some conditions or some periods of day, users could not send message properly. the wirte the message but even the user hit the enter, message stock in gray-out mode and user must wait for about 1 or two minutes. in some cases, user must reload the application and write the message again. although user refresh the rocketchat-app it can not refreshed and application took long time to load the history.

I checkd the DB. in the mentioned problem, we face high IO on db.
Also, I check DB commands which run on db and count them as bellow:
on a secondary node:

 702228 rocketchat.rocketchat_message
 324635 rocketchat.$cmd
 186477 rocketchat.rocketchat_message_read_receipt
 148297 rocketchat.rocketchat_notification_queue
 123513 rocketchat.rocketchat_subscription
  32141 rocketchat.usersSessions
  30451 rocketchat.instances
  27433 rocketchat.users
  18676 rocketchat.rocketchat_sessions
  13065 rocketchat.rocketchat__trash
   6838 rocketchat.rocketchat_room
   5046 rocketchat.meteor_oauth_pendingCredentials
   4802 rocketchat.meteor_oauth_pendingRequestTokens
   3108 rocketchat.rocketchat_cron_history
   1442 rocketchat.rocketchat_uploads
    575 rocketchat._raix_push_app_tokens
    185 rocketchat.rocketchat_avatars
    161 rocketchat.rocketchat_settings
    158 rocketchat.rocketchat_oembed_cache
    109 rocketchat.ufsTokens
     45 rocketchat.meteor_accounts_loginServiceConfiguration
     39 rocketchat.rocketchat_roles
     35 rocketchat.rocketchat_permissions
     28 rocketchat.rocketchat_integrations
     27 rocketchat.rocketchat_raw_imports
     19 rocketchat.rocketchat_statistics
     19 rocketchat.rocketchat_export_operations
     17 rocketchat.rocketchat_custom_emoji
     16 rocketchat.rocketchat_custom_sounds
     14 rocketchat.rocketchat_custom_user_status
     13 rocketchat.rocketchat_avatars.files
     10 rocketchat.rocketchat_banner
      8 rocketchat.rocketchat_avatars.chunks
      7 rocketchat.rocketchat_apps_persistence
      6 rocketchat.rocketchat_apps_logs
      5 rocketchat.migrations
      4 rocketchat.rocketchat_team_member
      3 rocketchat.rocketchat_uploads.chunks
      2 rocketchat.view_livechat_queue_status
      2 rocketchat.rocketchat_team
      2 rocketchat.rocketchat_livechat_agent_activity
      1 rocketchat.rocketchat_reports
      1 rocketchat.rocketchat_omnichannel_queue
      1 rocketchat.rocketchat_nps_vote
      1 rocketchat.rocketchat_nps
      1 rocketchat.rocketchat_livechat_visitor
      1 rocketchat.rocketchat_livechat_business_hours
      1 rocketchat.rocketchat_invites
      1 rocketchat.rocketchat_import_data
      1 rocketchat.rocketchat_import
      1 rocketchat.rocketchat_email_message_history
      1 rocketchat.rocketchat_email_inbox
      1 rocketchat.rocketchat_banner_dismiss
      1 rocketchat.rocketchat_apps_scheduler
      1 rocketchat.omnichannel_scheduler
      1 rocketchat.omnichannel_auto_close_on_hold_scheduler
      1 rocketchat

and primary node:

  97314 rocketchat.$cmd
  77429 rocketchat.rocketchat_message
  58285 rocketchat.rocketchat_message_read_receipt
  42701 rocketchat.rocketchat_notification_queue
  41081 rocketchat.rocketchat_subscription
   9036 rocketchat.usersSessions
   8374 rocketchat.instances
   8086 rocketchat.users
   6313 rocketchat.rocketchat_sessions
   5274 rocketchat.rocketchat__trash
   1724 rocketchat.rocketchat_room
   1395 rocketchat.meteor_oauth_pendingCredentials
   1339 rocketchat.meteor_oauth_pendingRequestTokens
   1013 rocketchat.rocketchat_uploads
    847 rocketchat.rocketchat_cron_history
    138 rocketchat._raix_push_app_tokens
     51 rocketchat.rocketchat_settings
     46 rocketchat.rocketchat_oembed_cache
     27 rocketchat.ufsTokens
     25 rocketchat.rocketchat_avatars
     17 rocketchat.meteor_accounts_loginServiceConfiguration
      8 rocketchat.rocketchat_integrations
      6 rocketchat.rocketchat_raw_imports
      5 rocketchat.rocketchat_statistics
      4 rocketchat.rocketchat_permissions
      4 rocketchat.rocketchat_avatars.chunks
      4 rocketchat.rocketchat_apps_logs
      3 rocketchat.rocketchat_invites
      2 rocketchat.view_livechat_queue_status
      2 rocketchat.rocketchat_roles
      2 rocketchat.rocketchat_custom_user_status
      2 rocketchat.rocketchat_apps
      1 rocketchat.rocketchat_livechat_business_hours
      1 rocketchat.rocketchat_import
      1 rocketchat.rocketchat_custom_sounds
      1 rocketchat.rocketchat_custom_emoji
      1 rocketchat.rocketchat_avatars.files

I appreciate any help.

Server Setup Information

  • Version of Rocket.Chat Server:
  • Operating System: 3.16.3
  • Number of Running Instances: 2 app server and 3 DB
  • DB Replicaset Oplog: yes
  • NodeJS Version: v12.18.4
  • MongoDB Version: 4.0.18 / mmapv1 (oplog Enabled)
  • Proxy: haproxy
  • Firewalls involved: no

Some additonal logs from mongoDB

2021-08-23T15:26:57.310+0430 I COMMAND  [conn102] command rocketchat.rocketchat_notification_queue command: findAndModify { findAndModify: "rocketchat_notification_queue", query: { $and: [ { $or: [ { sending: { $exists: false } }, { sending: { $lte: new Date(1629715917146) } } ] }, { $or: [ { schedule: { $exists: false } }, { schedule: { $lte: new Date(1629716217146) } } ] }, { error: { $exists: false } } ] }, sort: { ts: 1 }, new: false, remove: false, upsert: false, update: { $set: { sending: new Date(1629716217146) } }, lsid: { id: UUID("40732ffa-a5f0-4821-ae9b-43cc3975261e") }, $clusterTime: { clusterTime: Timestamp(1629716216, 65), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: "rocketchat" } planSummary: IXSCAN { ts: 1 } keysExamined:8 docsExamined:8 nMatched:0 nModified:0 numYields:0 reslen:217 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, MMAPV1Journal: { acquireCount: { w: 1 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 162221 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { W: 1 } } } protocol:op_msg 162ms
2021-08-23T15:26:55.117+0430 I COMMAND  [conn102] command rocketchat.rocketchat_notification_queue command: findAndModify { findAndModify: "rocketchat_notification_queue", query: { $and: [ { $or: [ { sending: { $exists: false } }, { sending: { $lte: new Date(1629715915007) } } ] }, { $or: [ { schedule: { $exists: false } }, { schedule: { $lte: new Date(1629716215007) } } ] }, { error: { $exists: false } } ] }, sort: { ts: 1 }, new: false, remove: false, upsert: false, update: { $set: { sending: new Date(1629716215007) } }, lsid: { id: UUID("40732ffa-a5f0-4821-ae9b-43cc3975261e") }, $clusterTime: { clusterTime: Timestamp(1629716214, 69), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: "rocketchat" } planSummary: IXSCAN { ts: 1 } keysExamined:8 docsExamined:8 nMatched:0 nModified:0 numYields:0 reslen:217 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, MMAPV1Journal: { acquireCount: { w: 1 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 105189 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { W: 1 } } } protocol:op_msg 105ms
2021-08-23T15:26:52.987+0430 I COMMAND  [conn103] command rocketchat.rocketchat_notification_queue command: findAndModify { findAndModify: "rocketchat_notification_queue", query: { $and: [ { $or: [ { sending: { $exists: false } }, { sending: { $lte: new Date(1629715912672) } } ] }, { $or: [ { schedule: { $exists: false } }, { schedule: { $lte: new Date(1629716212672) } } ] }, { error: { $exists: false } } ] }, sort: { ts: 1 }, new: false, remove: false, upsert: false, update: { $set: { sending: new Date(1629716212672) } }, lsid: { id: UUID("6d3ef2ef-61ca-424f-8ae3-78eac97de4c9") }, $clusterTime: { clusterTime: Timestamp(1629716212, 66), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: "rocketchat" } planSummary: IXSCAN { ts: 1 } keysExamined:8 docsExamined:8 nMatched:0 nModified:0 numYields:0 reslen:217 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, MMAPV1Journal: { acquireCount: { w: 1 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 313639 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { W: 1 } } } protocol:op_msg 314ms
2021-08-23T15:26:50.672+0430 I COMMAND  [conn101] command rocketchat.rocketchat_notification_queue command: findAndModify { findAndModify: "rocketchat_notification_queue", query: { $and: [ { $or: [ { sending: { $exists: false } }, { sending: { $lte: new Date(1629715910048) } } ] }, { $or: [ { schedule: { $exists: false } }, { schedule: { $lte: new Date(1629716210048) } } ] }, { error: { $exists: false } } ] }, sort: { ts: 1 }, new: false, remove: false, upsert: false, update: { $set: { sending: new Date(1629716210048) } }, lsid: { id: UUID("62cdd23b-4e4f-41bd-9783-5a5fc779bfd0") }, $clusterTime: { clusterTime: Timestamp(1629716209, 67), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: "rocketchat" } planSummary: IXSCAN { ts: 1 } keysExamined:8 docsExamined:8 nMatched:0 nModified:0 numYields:0 reslen:217 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, MMAPV1Journal: { acquireCount: { w: 1 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 621430 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { W: 1 } } } protocol:op_msg 621ms
2021-08-23T15:26:45.960+0430 I COMMAND  [conn102] command rocketchat.rocketchat_notification_queue command: findAndModify { findAndModify: "rocketchat_notification_queue", query: { $and: [ { $or: [ { sending: { $exists: false } }, { sending: { $lte: new Date(1629715905190) } } ] }, { $or: [ { schedule: { $exists: false } }, { schedule: { $lte: new Date(1629716205190) } } ] }, { error: { $exists: false } } ] }, sort: { ts: 1 }, new: false, remove: false, upsert: false, update: { $set: { sending: new Date(1629716205190) } }, lsid: { id: UUID("40732ffa-a5f0-4821-ae9b-43cc3975261e") }, $clusterTime: { clusterTime: Timestamp(1629716204, 138), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: "rocketchat" } planSummary: IXSCAN { ts: 1 } keysExamined:8 docsExamined:8 nMatched:0 nModified:0 numYields:0 reslen:217 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, MMAPV1Journal: { acquireCount: { w: 1 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 768880 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { W: 1 } } } protocol:op_msg 769ms
2021-08-23T15:26:43.158+0430 I COMMAND  [conn104] command rocketchat.rocketchat_notification_queue command: findAndModify { findAndModify: "rocketchat_notification_queue", query: { $and: [ { $or: [ { sending: { $exists: false } }, { sending: { $lte: new Date(1629715903023) } } ] }, { $or: [ { schedule: { $exists: false } }, { schedule: { $lte: new Date(1629716203023) } } ] }, { error: { $exists: false } } ] }, sort: { ts: 1 }, new: false, remove: false, upsert: false, update: { $set: { sending: new Date(1629716203023) } }, lsid: { id: UUID("62cdd23b-4e4f-41bd-9783-5a5fc779bfd0") }, $clusterTime: { clusterTime: Timestamp(1629716202, 8), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: "rocketchat" } planSummary: IXSCAN { ts: 1 } keysExamined:8 docsExamined:8 nMatched:0 nModified:0 numYields:0 reslen:217 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, MMAPV1Journal: { acquireCount: { w: 1 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 132952 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { W: 1 } } } protocol:op_msg 133ms
2021-08-23T15:26:38.975+0430 I COMMAND  [conn104] command rocketchat.rocketchat_notification_queue command: findAndModify { findAndModify: "rocketchat_notification_queue", query: { $and: [ { $or: [ { sending: { $exists: false } }, { sending: { $lte: new Date(1629715898832) } } ] }, { $or: [ { schedule: { $exists: false } }, { schedule: { $lte: new Date(1629716198832) } } ] }, { error: { $exists: false } } ] }, sort: { ts: 1 }, new: false, remove: false, upsert: false, update: { $set: { sending: new Date(1629716198832) } }, lsid: { id: UUID("62cdd23b-4e4f-41bd-9783-5a5fc779bfd0") }, $clusterTime: { clusterTime: Timestamp(1629716197, 65), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: "rocketchat" } planSummary: IXSCAN { ts: 1 } keysExamined:8 docsExamined:8 nMatched:0 nModified:0 numYields:0 reslen:217 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, MMAPV1Journal: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 140306 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { W: 1 }, acquireWaitCount: { W: 1 }, timeAcquiringMicros: { W: 1761 } } } protocol:op_msg 142ms
2021-08-23T15:26:38.974+0430 I COMMAND  [conn112] command rocketchat.rocketchat_notification_queue command: findAndModify { findAndModify: "rocketchat_notification_queue", query: { $and: [ { $or: [ { sending: { $exists: false } }, { sending: { $lte: new Date(1629715898856) } } ] }, { $or: [ { schedule: { $exists: false } }, { schedule: { $lte: new Date(1629716198856) } } ] }, { error: { $exists: false } } ] }, sort: { ts: 1 }, new: false, remove: false, upsert: false, update: { $set: { sending: new Date(1629716198856) } }, lsid: { id: UUID("c7c3413c-dc95-485c-9727-e98fdc3944e4") }, $clusterTime: { clusterTime: Timestamp(1629716197, 65), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: "rocketchat" } planSummary: IXSCAN { ts: 1 } keysExamined:8 docsExamined:8 nMatched:0 nModified:0 numYields:0 reslen:217 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, MMAPV1Journal: { acquireCount: { w: 1 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 116718 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { W: 1 } } } protocol:op_msg 117ms
2021-08-23T15:26:36.830+0430 I COMMAND  [conn114] command rocketchat.rocketchat_notification_queue command: findAndModify { findAndModify: "rocketchat_notification_queue", query: { $and: [ { $or: [ { sending: { $exists: false } }, { sending: { $lte: new Date(1629715896351) } } ] }, { $or: [ { schedule: { $exists: false } }, { schedule: { $lte: new Date(1629716196351) } } ] }, { error: { $exists: false } } ] }, sort: { ts: 1 }, new: false, remove: false, upsert: false, update: { $set: { sending: new Date(1629716196351) } }, lsid: { id: UUID("26137f0a-b2b7-4412-939a-b21bfc607fd9") }, $clusterTime: { clusterTime: Timestamp(1629716194, 7), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: "rocketchat" } planSummary: IXSCAN { ts: 1 } keysExamined:8 docsExamined:8 nMatched:0 nModified:0 numYields:0 reslen:217 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, MMAPV1Journal: { acquireCount: { w: 1 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 477661 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { W: 1 } } } protocol:op_msg 478ms

Found!

As you see on the description, I counted the queries have been run on the DB and sorted them by number of execution.
There is a feature in every telecommunication which called read_receipt. in the Rocketchat you can disable it but still application works properly. The difference is just you can not find who has been read your text in a channel/group.

What happen when this feature is enable?!!
Assume that you have a profile and joined in at least 20 channels/groups and each one has at least 10 member in it.
for every text that sending to each channel/group, a write query is called on the DB on collection rocketchat_message_read_receipt. A 20-member-channel must updated with 20 unique query called to show you all of the members has been read your text.

In my experience, I have 3-node replica set mongoDB that has a collection rocketchat_message_read_receipt with 25 GB of size. On the other hand the total size of all messages on the DB was just 2.6 GB.
Awesome !!! or terrible feature.