Description
I just migrated a RocketChat server from a manual installation to a snapshot installation by performing a dump/restore. I checked before that it had the same version of RocketChat as well as mongodb.
The problem is that since this migration, RocktChat has become very slow. Chat doesn’t load anymore, it’s hard to connect, messages don’t get sent or they take a long time.
I tried to go directly to port 3000 without the apache reverse proxy to make sure it wasn’t the problem.
Server Setup Information
- Version of Rocket.Chat Server: 4.3.1
- Operating System: Ubuntu 18.04.3 LTS
- Deployment Method: snap
- Number of Running Instances: 1
- DB Replicaset Oplog:
- NodeJS Version: 8.11.4
- MongoDB Version: 3.4.20
- Proxy: apache
Any additional Information
RocketChat server logs:
Summary
Jan 08 10:19:23 rocketchat-2 rocketchat-server.rocketchat-server[46163]: TIMEOUT QUERY OPERATION { observeKey: '{“ordered”:false,“collectionName”:“users”,“selector”:{“_i
Jan 08 10:19:23 rocketchat-2 rocketchat-server.rocketchat-server[46163]: writesToCommitWhenWeReachSteadyLength: 0,
Jan 08 10:19:23 rocketchat-2 rocketchat-server.rocketchat-server[46163]: cursorDescription: '{“collectionName”:“users”,“selector”:{”_id":“DKcvMputtgtxC6sYT”},“options”
Jan 08 10:19:23 rocketchat-2 rocketchat-server.rocketchat-server[46163]: Exception in setInterval callback: SwitchedToQuery {}
Jan 08 10:20:00 rocketchat-2 rocketchat-server.rocketchat-server[46163]: { Error: ENOENT: no such file or directory, stat ‘/tmp/zipFiles/oAHkFqcSMruzqR5ab.zip’
Jan 08 10:20:00 rocketchat-2 rocketchat-server.rocketchat-server[46163]: errno: -2,
Jan 08 10:20:00 rocketchat-2 rocketchat-server.rocketchat-server[46163]: code: ‘ENOENT’,
Jan 08 10:20:00 rocketchat-2 rocketchat-server.rocketchat-server[46163]: syscall: ‘stat’,
Jan 08 10:20:00 rocketchat-2 rocketchat-server.rocketchat-server[46163]: path: ‘/tmp/zipFiles/oAHkFqcSMruzqR5ab.zip’ }
Jan 08 10:20:11 rocketchat-2 rocketchat-server.rocketchat-server[46163]: Exception in defer callback: Error: Phase unexpectedly STEADY
Jan 08 10:20:11 rocketchat-2 rocketchat-server.rocketchat-server[46163]: at OplogObserveDriver._doneQuerying (packages/mongo/oplog_observe_driver.js:802:13)
Jan 08 10:20:11 rocketchat-2 rocketchat-server.rocketchat-server[46163]: at packages/mongo/oplog_observe_driver.js:700:14
Jan 08 10:20:11 rocketchat-2 rocketchat-server.rocketchat-server[46163]: at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1234:12)
Jan 08 10:20:11 rocketchat-2 rocketchat-server.rocketchat-server[46163]: at packages/meteor.js:550:25
Jan 08 10:20:11 rocketchat-2 rocketchat-server.rocketchat-server[46163]: at runWithEnvironment (packages/meteor.js:1286:24)
Jan 08 10:22:00 rocketchat-2 rocketchat-server.rocketchat-server[46163]: { Error: ENOENT: no such file or directory, stat ‘/tmp/zipFiles/oAHkFqcSMruzqR5ab.zip’
Jan 08 10:22:00 rocketchat-2 rocketchat-server.rocketchat-server[46163]: errno: -2,
Jan 08 10:22:00 rocketchat-2 rocketchat-server.rocketchat-server[46163]: code: ‘ENOENT’,
Jan 08 10:22:00 rocketchat-2 rocketchat-server.rocketchat-server[46163]: syscall: ‘stat’,
Jan 08 10:22:00 rocketchat-2 rocketchat-server.rocketchat-server[46163]: path: ‘/tmp/zipFiles/oAHkFqcSMruzqR5ab.zip’ }
Apache logs:
Summary
[Wed Jan 08 10:19:30.068980 2020] [proxy_http:error] [pid 54238:tid 140191952004864] (70007)The timeout specified has expired: [client 185.14.128.253:53104] AH01102: error reading status line from remote server localhost:3000
[Wed Jan 08 10:19:30.069354 2020] [proxy:error] [pid 54238:tid 140191952004864] [client 185.10.10.10:53104] AH00898: Error reading from remote server returned by /hooks/2RJY5XAp5um5
Mongodb logs:
Summary
Jan 08 11:01:45 rocketchat-2 rocketchat-server.rocketchat-mongo[41506]: 2020-01-08T11:01:45.968+0100 I COMMAND [conn23] command parties.rocketchat_uploads.chunks comman
d: find { find: “rocketchat_uploads.chunks”, filter: { files_id: “7NZghcWYuoGbmZGcJ” }, sort: { n: 1 }, returnKey: false, showRecordId: false, $clusterTime: { clusterTim
e: Timestamp(1578477447, 6), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: “parties” } planSummary: COLLSCAN keysExamined:0
docsExamined:128852 hasSortStage:1 cursorExhausted:1 numYields:4337 nreturned:1 reslen:187744 locks:{ Global: { acquireCount: { r: 8676 } }, Database: { acquireCount: {
r: 4338 } }, Collection: { acquireCount: { r: 4338 } } } protocol:op_query 86738ms
Jan 08 11:02:25 rocketchat-2 rocketchat-server.rocketchat-mongo[41506]: 2020-01-08T11:02:25.420+0100 I NETWORK [conn21] end connection 127.0.0.1:51782 (6 connections no
w open)
Jan 08 11:02:26 rocketchat-2 rocketchat-server.rocketchat-mongo[41506]: 2020-01-08T11:02:26.197+0100 I NETWORK [conn20] end connection 127.0.0.1:51778 (5 connections no
w open)
Jan 08 11:03:12 rocketchat-2 rocketchat-server.rocketchat-mongo[41506]: 2020-01-08T11:03:12.171+0100 I COMMAND [conn24] command parties.rocketchat_uploads.chunks comman
d: find { find: “rocketchat_uploads.chunks”, filter: { files_id: “z8TabFiAZyQTgpsf4” }, sort: { n: 1 }, returnKey: false, showRecordId: false, $clusterTime: { clusterTim
e: Timestamp(1578477706, 5), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: “parties” } planSummary: COLLSCAN keysExamined:0
docsExamined:128852 hasSortStage:1 cursorExhausted:1 numYields:4309 nreturned:1 reslen:161187 locks:{ Global: { acquireCount: { r: 8620 } }, Database: { acquireCount: {
r: 4310 } }, Collection: { acquireCount: { r: 4310 } } } protocol:op_query 86151ms
Jan 08 11:03:12 rocketchat-2 rocketchat-server.rocketchat-mongo[41506]: 2020-01-08T11:03:12.171+0100 I COMMAND [conn25] command parties.rocketchat_uploads.chunks comman
d: find { find: “rocketchat_uploads.chunks”, filter: { files_id: “z8TabFiAZyQTgpsf4” }, sort: { n: 1 }, returnKey: false, showRecordId: false, $clusterTime: { clusterTim
e: Timestamp(1578477619, 15), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: “parties” } planSummary: COLLSCAN keysExamined:
0 docsExamined:128852 hasSortStage:1 cursorExhausted:1 numYields:4310 nreturned:1 reslen:161187 locks:{ Global: { acquireCount: { r: 8622 } }, Database: { acquireCount:
{ r: 4311 } }, Collection: { acquireCount: { r: 4311 } } } protocol:op_query 86172ms