RocketChat / Rocket.Chat

The communications platform that puts data protection first.
https://rocket.chat/
Other
40.49k stars 10.55k forks source link

Slow response on opening channels in Mobile clients #33509

Open froque opened 3 weeks ago

froque commented 3 weeks ago

Description:

Specially on mobile clients, when opening a channel getting new messages is very slow.

Steps to reproduce:

  1. Open Rocketchat on mobile
  2. Open channel
  3. 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:

Client Setup Information

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,
reetp commented 3 weeks ago

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

froque commented 2 weeks ago

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 })
}
reetp commented 2 weeks ago
  • 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_1 does 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?

froque commented 1 week ago

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
reetp commented 1 week ago

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....