MongoCursorTimeoutException (80)

[ngarafol]

Dont know if this is duplicate of #764 or not :)

Version
master at 627be8f on 1.12.1

Steps to reproduce the bug

1. Login to learning locker URL

Expected behaviour
User should login in administration dashboard

Actual behaviour
User is presented with MongoCursorTimeoutException error.

localhost:27017: Read timed out after reading 0 bytes, waited for 30.000000 seconds

Additional information
OS: Debian 8 x64
Browser: Chromium Version 50.0.2661.94 (64-bit)
MongoDB version 3.2
php5-mongo module version 1.5.7
Mongo database seems to work, background task emitting records from moodle log to LRS seems to work.

Stacktrace:

1. MongoCursorTimeoutException
   …/­vendor/­jenssegers/­mongodb/­src/­Jenssegers/­Mongodb/­Query/­Builder.php262
2. MongoCursor rewind
   <#unknown>0
3. iterator_to_array
   …/­vendor/­jenssegers/­mongodb/­src/­Jenssegers/­Mongodb/­Query/­Builder.php262
4. Jenssegers\Mongodb\Query\Builder getFresh
   …/­vendor/­laravel/­framework/­src/­Illuminate/­Database/­Query/­Builder.php1384
5. Illuminate\Database\Query\Builder get
   …/­vendor/­jenssegers/­mongodb/­src/­Jenssegers/­Mongodb/­Query/­Builder.php126
6. Jenssegers\Mongodb\Query\Builder get
   …/­vendor/­laravel/­framework/­src/­Illuminate/­Database/­Query/­Builder.php1369
7. Illuminate\Database\Query\Builder first
   …/­app/­locker/­data/­dashboards/­BaseDashboard.php59
8. app\locker\data\dashboards\BaseDashboard statementDays
   …/­app/­locker/­data/­dashboards/­BaseDashboard.php84
9. app\locker\data\dashboards\BaseDashboard statementAvgCount
   …/­app/­locker/­data/­dashboards/­BaseDashboard.php23
10. app\locker\data\dashboards\BaseDashboard getStats
    …/­app/­locker/­data/­dashboards/­AdminDashboard.php17
11. app\locker\data\dashboards\AdminDashboard getFullStats
    …/­app/­controllers/­SiteController.php40
12. SiteController index
    <#unknown>0
13. call_user_func_array
    …/­vendor/­laravel/­framework/­src/­Illuminate/­Routing/­Controller.php231
14. Illuminate\Routing\Controller callAction
    …/­vendor/­laravel/­framework/­src/­Illuminate/­Routing/­ControllerDispatcher.php93
15. Illuminate\Routing\ControllerDispatcher call
    …/­vendor/­laravel/­framework/­src/­Illuminate/­Routing/­ControllerDispatcher.php62
16. Illuminate\Routing\ControllerDispatcher dispatch
    …/­vendor/­laravel/­framework/­src/­Illuminate/­Routing/­Router.php967
17. Illuminate\Routing\Router Illuminate\Routing{closure}
    <#unknown>0
18. call_user_func_array
    …/­vendor/­laravel/­framework/­src/­Illuminate/­Routing/­Route.php109
19. Illuminate\Routing\Route run
    …/­vendor/­laravel/­framework/­src/­Illuminate/­Routing/­Router.php1033
20. Illuminate\Routing\Router dispatchToRoute
    …/­vendor/­laravel/­framework/­src/­Illuminate/­Routing/­Router.php1001
21. Illuminate\Routing\Router dispatch
    …/­vendor/­laravel/­framework/­src/­Illuminate/­Foundation/­Application.php775
22. Illuminate\Foundation\Application dispatch
    …/­vendor/­laravel/­framework/­src/­Illuminate/­Foundation/­Application.php745
23. Illuminate\Foundation\Application handle
    …/­vendor/­itsgoingd/­clockwork/­Clockwork/­Support/­Laravel/­ClockworkLegacyMiddleware.php20
24. Clockwork\Support\Laravel\ClockworkLegacyMiddleware handle
    …/­vendor/­laravel/­framework/­src/­Illuminate/­Session/­Middleware.php72
25. Illuminate\Session\Middleware handle
    …/­vendor/­laravel/­framework/­src/­Illuminate/­Cookie/­Queue.php47
26. Illuminate\Cookie\Queue handle
    …/­vendor/­laravel/­framework/­src/­Illuminate/­Cookie/­Guard.php51
27. Illuminate\Cookie\Guard handle
    …/­vendor/­stack/­builder/­src/­Stack/­StackedHttpKernel.php23
28. Stack\StackedHttpKernel handle
    …/­vendor/­laravel/­framework/­src/­Illuminate/­Foundation/­Application.php641
29. Illuminate\Foundation\Application run
    …/­public/­index.php49

[ht2]

Simply said, the query running on login is simply taking longer than the 30 seconds Mongo is configured to allow. However, I'm not 100% which query would even by taking that long - especially on login.

Could you provide some rough details as to the state of the database/application? E.g. how many LRS's you have setup with how many statements in total and on average in each? The query is failing at BaseDashboard.php#59, which is simply a query to grab the most recent statement....

https://github.com/LearningLocker/learninglocker/blob/develop/app/locker/data/dashboards/BaseDashboard.php#L59

Can I check - have you manually configured any indexes in the database?

[ngarafol]

There is one LRS currently with 4168529 statements and counting. Database size is 8.804GB so roughly 2KB per statement.

I did not configure any indexes manually.

[ht2]

OK, this will definitely be an indexing issue - LL is not configured out of the box to run at enterprise scale (which you are definitely straying into).

So to start I would make sure you check out my blog entry about indexing in LL here: https://learninglocker.net/blog/learning-locker-v1-12/

And then I would also suggest you think about contacting us here at HT2 directly about your solution and the kinds of challenges we know you are going to face moving at that kind of scale.

For the moment, try adding those indexes manually and see if it helps, I believe it will. A word of warning, this will create huge amounts of extra data to your MongoDB size (roughly 25% of the total data size, which is different to the compressed Wired Tiger storage size..). Let me know if that makes a difference to your load times though.

[ht2]

(and whilst I do implore you read through that blog, here is the tl;dr...)

db.statements.createIndex({stored: 1})
db.statements.createIndex({timestamp: 1})
db.statements.createIndex({active: 1})
db.statements.createIndex({voided:1})
db.statements.createIndex({lrs_id:1})
db.statements.createIndex({lrs_id:1, active:-1, voided:1})
db.statements.createIndex({lrs_id:1, 'statement.actor.mbox':1} )
db.statements.createIndex({'statement.actor.mbox':1})
db.statements.createIndex({lrs_id:1, 'statement.actor.account.name':1, 'statement.actor.account.homePage':1})
db.statements.createIndex({lrs_id:1, 'statement.actor.mbox':1} )
db.statements.createIndex({lrs_id:1, 'statement.verb.id':1})
db.statements.createIndex({lrs_id:1, 'statement.object.id':1})
db.statements.createIndex({lrs_id: 1, stored:-1})
db.statements.createIndex({lrs_id: 1, timestamp:-1})
db.statements.createIndex({'statement.id':1, lrs_id:1})

[ryasmi]

Closing this. I'll reopen if @ngarafol decides that didn't resolve the issue.

[ngarafol]

This fixed the issue with admin dashboard. Now new issue is with LRS view. There is still timeout of 30 seconds on url learning-locker-site/site#lrs. Looking at code, it tries to get count of records in statements collection that already has 20 indexes. Lrs collection has only one record due to using only one LRS. Do I need any more indexes for it to work properly?

[ht2]

I pushed some updated code yesterday to develop that attempts to get the count to use a hint for the right index, so try pulling from develop (ensure you run a composer install as some of the new dependencies are important).

However, that shouldn't be affecting the counts on the site#lrs page. Can you ensure you have the {lrs_id:1, active:-1, voided:1} index in place on the statements collection?

[ngarafol]

Yes, I have that index:

{
"v" : 1,
"key" : {
"lrs_id" : 1,
"active" : -1,
"voided" : 1
},
"name" : "lrs_id_1_active_-1_voided_1",
"ns" : "LearningLocker.statements"
},

Ok, will try new code from develop branch ;)

[ngarafol]

Hmm develop branch behaves the same. Looking at mongo queries, there is cursorExhausted:1 in few queries.

2016-05-19T15:23:17.089+0200 I COMMAND [conn83] command admin.$cmd command: ping { ping: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:37 locks:{} protocol:op_query 0ms
2016-05-19T15:23:17.089+0200 I COMMAND [conn83] command admin.$cmd command: isMaster { isMaster: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:178 locks:{} protocol:op_query 0ms
2016-05-19T15:23:17.090+0200 I COMMAND [conn83] query LearningLocker.sessions query: { _id: "60e8289377b5b8f3346dbe88c0f90c83a1a6b355" } planSummary: IDHACK ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:391 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 0ms
2016-05-19T15:23:17.390+0200 I COMMAND [conn83] query LearningLocker.users query: { _id: ObjectId('572c3f00dd4239d3148b4567') } planSummary: IDHACK ntoreturn:1 ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:326 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 273ms
2016-05-19T15:23:17.409+0200 I COMMAND [conn83] query LearningLocker.lrs planSummary: COLLSCAN ntoreturn:0 ntoskip:0 keysExamined:0 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:397 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } 17ms
2016-05-19T15:23:47.467+0200 I NETWORK [initandlisten] connection accepted from 127.0.0.1:55991 #87 (13 connections now open)
2016-05-19T15:23:47.467+0200 I COMMAND [conn87] command admin.$cmd command: isMaster { isMaster: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:178 locks:{} protocol:op_query 0ms
2016-05-19T15:23:47.467+0200 I COMMAND [conn87] command admin.$cmd command: buildInfo { buildInfo: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:1122 locks:{} protocol:op_query 0ms
2016-05-19T15:23:47.469+0200 I COMMAND [conn87] command LearningLocker.$cmd command: saslStart { saslStart: 1, mechanism: "SCRAM-SHA-1", payload: "xxx", autoAuthorize: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:226 locks:{} protocol:op_query 1ms
2016-05-19T15:23:47.484+0200 I COMMAND [conn87] command LearningLocker.$cmd command: saslContinue { saslContinue: 1, conversationId: 1, payload: "Yz1iaXdzLHI9ZmU5YTljNzZhZGM2MWRiYjA3NzNlMmMyMWM0Mjg5Y2FkNWMzZjE4MTg4NC9DZ0VDdTd1dHl5LzRGUVdGU0tMUUV0MGVQSDZxLHA9a1VESHRZQmY0Ti9BQVhTQkZxRGowKzZaQkVZPQ==" } keyUpdates:0 writeConflicts:0 numYields:0 reslen:118 locks:{} protocol:op_query 0ms
2016-05-19T15:23:47.485+0200 I ACCESS [conn87] Successfully authenticated as principal debian on LearningLocker
2016-05-19T15:23:47.485+0200 I COMMAND [conn87] command LearningLocker.$cmd command: saslContinue { saslContinue: 1, conversationId: 1, payload: "" } keyUpdates:0 writeConflicts:0 numYields:0 reslen:78 locks:{} protocol:op_query 0ms
2016-05-19T15:23:47.485+0200 I COMMAND [conn87] command admin.$cmd command: ping { ping: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:37 locks:{} protocol:op_query 0ms
2016-05-19T15:23:47.486+0200 I WRITE [conn87] update LearningLocker.sessions query: { _id: "60e8289377b5b8f3346dbe88c0f90c83a1a6b355" } update: { $set: { payload: BinData(2, 613A343A7B733A363A225F746F6B656E223B733A34303A2279714A655A4C38564F59497876543363756E79414C5633554362454C4E4E6C7965714130566C576C223B733A353A...), last_activity: new Date(1463664227466) } } keysExamined:1 docsExamined:1 nMatched:1 nModified:1 keyUpdates:0 writeConflicts:0 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } 0ms
2016-05-19T15:23:47.486+0200 I COMMAND [conn87] command LearningLocker.$cmd command: update { update: "sessions", updates: [ { q: { _id: "60e8289377b5b8f3346dbe88c0f90c83a1a6b355" }, u: { $set: { payload: BinData(2, 613A343A7B733A363A225F746F6B656E223B733A34303A2279714A655A4C38564F59497876543363756E79414C5633554362454C4E4E6C7965714130566C576C223B733A353A...), last_activity: new Date(1463664227466) } }, multi: false, upsert: true } ], writeConcern: { w: 1 } } keyUpdates:0 writeConflicts:0 numYields:0 reslen:55 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_query 0ms