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.

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

River issuing too many queries to oplog.rs #164

Closed
ramv opened this issue Nov 4, 2013 · 16 comments
Closed

River issuing too many queries to oplog.rs #164

ramv opened this issue Nov 4, 2013 · 16 comments

Comments

@ramv
Copy link

ramv commented Nov 4, 2013

We have an issue with the river mongodb. Every 2 weeks the river issues queries to Oplog.rs that essentially brings the system to a grinding halt. We are running our servers on MongoLab's dedicated cluster. The ops support engineers at MongoLab indicated that the queries being issued to oplog.sys are the ones that seem to be causing this. Anyone experienced this? Any pointers? Is there a recommended configuration that is better suited for MongoLab?

Our River config

curl -XPUT "http://localhost:9200/_river/savvy_<REPLACE WITH COLLECTION NAME>/_meta" -d '
{
    "type": "mongodb",
    "mongodb": {
        "servers": [
            {
                "host": "<REPLACE WITH THE FIRST SERVER NAME>",
                "port": <REPLACE WITH PORT>
            },
            {
                "host": "<REPLACE WITH THE SECOND SERVER NAME>",
                "port": <REPLACE WITH SPORT>
            }
        ],
        "options": {
            "secondary_read_preference": true
        },
        "credentials": [
            {
                "db": "admin",
                "user": "<REPLACE WITH USERNAME FOR ADMIN DATABASE>",
                "password": "<REPLACE THE PASSWORD>"
            }
        ],
        "db": "savvy",
        "collection": "<REPLACE WITH COLLECTION NAME>"
    },
    "index": {
        "name": "<REPLACE WITH COLLECTION NAME>",
        "bulk_size": 200,
        "throttle_size": 500,
        "type": "<REPLACE WITH COLLECTION NAME>"
    }
}'
@richardwilly98
Copy link
Owner

It could be related to #123. I change the oplog.rs filter following the recommendations.

This change will be available in release 1.7.2

@ramv
Copy link
Author

ramv commented Nov 4, 2013

Thanks for the prompt response! Will wait for 1.7.2. Great plugin!

@richardwilly98
Copy link
Owner

@ramv
Version 1.7.2 has been released this week. Could you please provide feedback?
Let me know if you still have this issue. If that's the case could you please provide more details about the queries causing it?

@ramv
Copy link
Author

ramv commented Nov 15, 2013

will do. I will push the update today.

On Fri, Nov 15, 2013 at 2:15 AM, Richard Louapre
notifications@github.comwrote:

@ramv https://github.com/ramv
Version 1.7.2 has been released this week. Could you please provide
feedback?
Let me know if you still have this issue. If that's the case could you
please provide more details about the queries causing it?


Reply to this email directly or view it on GitHubhttps://github.com//issues/164#issuecomment-28559199
.

Best Regards,

Ram Viswanadha

@ramv
Copy link
Author

ramv commented Nov 15, 2013

hmm .. can't get authenticated

[2013-11-15 17:24:06,759][INFO ][river.mongodb            ] mongoServersSettings: [{port=41158, host=ds041158-a0.mongolab.com}, {port=41158, host=ds041158-a1.mongolab.com}]
[2013-11-15 17:24:06,760][INFO ][river.mongodb            ] Server: ds041158-a0.mongolab.com - 41158
[2013-11-15 17:24:06,767][INFO ][river.mongodb            ] Server: ds041158-a1.mongolab.com - 41158
[2013-11-15 17:24:06,802][INFO ][river.mongodb            ] mongoServersSettings: [{port=41158, host=ds041158-a0.mongolab.com}, {port=41158, host=ds041158-a1.mongolab.com}]
[2013-11-15 17:24:06,802][INFO ][river.mongodb            ] Server: ds041158-a0.mongolab.com - 41158
[2013-11-15 17:24:06,802][INFO ][river.mongodb            ] Server: ds041158-a1.mongolab.com - 41158
[2013-11-15 17:24:06,829][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Using mongodb server(s): host [ds041158-a0.mongolab.com], port [41158]
[2013-11-15 17:24:06,829][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Using mongodb server(s): host [ds041158-a1.mongolab.com], port [41158]
[2013-11-15 17:24:06,831][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoDB River Plugin version: [1.7.2]
[2013-11-15 17:24:06,868][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] starting mongodb stream. options: secondaryreadpreference [true], drop_collection [false], include_collection [], throttlesize [500], gridfs [false], filter [{ }], db [savvy], collection [products], script [null], indexing to [products]/[product]
[2013-11-15 17:24:06,929][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoAdminUser: <username> - isAuthenticated: false
[2013-11-15 17:24:06,929][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Authenticate admin with 
[2013-11-15 17:24:09,174][INFO ][org.elasticsearch.river.mongodb.Slurper] Authenticate admin with
[2013-11-15 17:33:57,287][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] closing mongodb stream river
[2013-11-15 17:33:57,287][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Closing Mongo client
[2013-11-15 17:33:57,288][INFO ][org.elasticsearch.river.mongodb.Indexer] river-mongodb indexer interrupted

I tried logging on to the server with same creds and was able to

localhost:~ram$ mongo ds041158-a0.mongolab.com:41158/admin -u <user> -p <password>
MongoDB shell version: 2.4.6
connecting to: ds041158-a0.mongolab.com:41158/admin
rs-ds041158:PRIMARY> use local;
switched to db local
rs-ds041158:PRIMARY> show collections;
oplog.rs
slaves
startup_log
system.indexes
system.replset
system.users
rs-ds041158:PRIMARY> 

@richardwilly98
Copy link
Owner

Can you please increase the log level [1]?

Please provide the full ES log file.

[1] -https://github.com/richardwilly98/elasticsearch-river-mongodb/wiki#troubleshooting

@ramv
Copy link
Author

ramv commented Nov 16, 2013

[2013-11-16 00:54:29,445][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoAdminUser: savvyadmin_prev_es - isAuthenticated: false
[2013-11-16 00:54:29,445][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Authenticate admin with savvyadmin_prev_es
[2013-11-16 00:54:29,652][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] serverStatus: { "serverUsed" : "ds041158-a0.mongolab.com/10.164.39.201:41158" , "host" : "h001111.mongolab.com:41158" , "version" : "2.4.5" , "process" : "mongod" , "pid" : 8297 , "uptime" : 8140271.0 , "uptimeMillis" : 8140271344 , "uptimeEstimate" : 6997787.0 , "localTime" : { "$date" : "2013-11-16T00:54:19.925Z"} , "asserts" : { "regular" : 0 , "warning" : 0 , "msg" : 0 , "user" : 909 , "rollovers" : 0} , "backgroundFlushing" : { "flushes" : 135665 , "total_ms" : 6689269 , "average_ms" : 49.3072568459072 , "last_ms" : 40 , "last_finished" : { "$date" : "2013-11-16T00:53:31.157Z"}} , "connections" : { "current" : 212 , "available" : 19788 , "totalCreated" : 5720524} , "cursors" : { "totalOpen" : 3 , "clientCursors_size" : 3 , "timedOut" : 678 , "totalNoTimeout" : 1} , "dur" : { "commits" : 29 , "journaledMB" : 0.065536 , "writeToDataFilesMB" : 0.063151 , "compression" : 0.6877676097724792 , "commitsInWriteLock" : 0 , "earlyCommits" : 0 , "timeMs" : { "dt" : 3015 , "prepLogBuffer" : 0 , "writeToJournal" : 34 , "writeToDataFiles" : 0 , "remapPrivateView" : 0}} , "extra_info" : { "note" : "fields vary by platform" , "heap_usage_bytes" : 73389016 , "page_faults" : 48865} , "globalLock" : { "totalTime" : 8140271344000 , "lockTime" : 36177851262 , "currentQueue" : { "total" : 0 , "readers" : 0 , "writers" : 0} , "activeClients" : { "total" : 0 , "readers" : 0 , "writers" : 0}} , "indexCounters" : { "accesses" : 48325606 , "hits" : 48325606 , "misses" : 0 , "resets" : 0 , "missRatio" : 0.0} , "locks" : { "." : { "timeLockedMicros" : { "R" : 1925332396 , "W" : 36177851262 , "r" : 0 , "w" : 23} , "timeAcquiringMicros" : { "R" : 6351920584 , "W" : 1654590848}} , "admin" : { "timeLockedMicros" : { "r" : 673023564 , "w" : 0} , "timeAcquiringMicros" : { "r" : 58519031 , "w" : 0}} , "local" : { "timeLockedMicros" : { "r" : 6621510543 , "w" : 1676423994} , "timeAcquiringMicros" : { "r" : 15027254206 , "w" : 531788672}} , "savvy1" : { "timeLockedMicros" : { "r" : 922552 , "w" : 17989} , "timeAcquiringMicros" : { "r" : 152347 , "w" : 46207}} , "savvy" : { "timeLockedMicros" : { "r" : 31696766230268 , "w" : 33388038525} , "timeAcquiringMicros" : { "r" : 29768396314720 , "w" : 59076398644}} , "config" : { "timeLockedMicros" : { "r" : 17241207 , "w" : 36159} , "timeAcquiringMicros" : { "r" : 3094653 , "w" : 47243}} , "test" : { "timeLockedMicros" : { "r" : 14233886 , "w" : 21991191} , "timeAcquiringMicros" : { "r" : 1728654 , "w" : 5338745}}} , "network" : { "bytesIn" : 5.4908274855E10 , "bytesOut" : 3.7344419832E10 , "numRequests" : 628997384} , "opcounters" : { "insert" : 289100 , "query" : 561869810 , "update" : 13760776 , "delete" : 19314 , "getmore" : 18761615 , "command" : 37726913} , "opcountersRepl" : { "insert" : 0 , "query" : 0 , "update" : 0 , "delete" : 0 , "getmore" : 0 , "command" : 0} , "recordStats" : { "accessesNotInMemory" : 24904 , "pageFaultExceptionsThrown" : 12220 , "admin" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0} , "config" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0} , "local" : { "accessesNotInMemory" : 1 , "pageFaultExceptionsThrown" : 0} , "savvy" : { "accessesNotInMemory" : 24902 , "pageFaultExceptionsThrown" : 12220} , "savvy1" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0} , "test" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0}} , "repl" : { "setName" : "rs-ds041158" , "ismaster" : true , "secondary" : false , "hosts" : [ "ds041158-a0.mongolab.com:41158" , "ds041158-a1.mongolab.com:41158"] , "arbiters" : [ "ds041158-r0.mongolab.com:41158"] , "primary" : "ds041158-a0.mongolab.com:41158" , "me" : "ds041158-a0.mongolab.com:41158"} , "writeBacksQueued" : false , "mem" : { "bits" : 64 , "resident" : 637 , "virtual" : 10922 , "supported" : true , "mapped" : 5230 , "mappedWithJournal" : 10460} , "metrics" : { "document" : { "deleted" : 10579 , "inserted" : 289100 , "returned" : 83213429 , "updated" : 12131403} , "getLastError" : { "wtime" : { "num" : 37 , "totalMillis" : 0} , "wtimeouts" : 0} , "operation" : { "fastmod" : 9336047 , "idhack" : 9313199 , "scanAndOrder" : 489} , "queryExecutor" : { "scanned" : 1184731541429} , "record" : { "moves" : 317856} , "repl" : { "apply" : { "batches" : { "num" : 0 , "totalMillis" : 0} , "ops" : 0} , "buffer" : { "count" : 0 , "maxSizeBytes" : 268435456 , "sizeBytes" : 0} , "network" : { "bytes" : 0 , "getmores" : { "num" : 0 , "totalMillis" : 0} , "ops" : 0 , "readersCreated" : 4} , "oplog" : { "insert" : { "num" : 9686892 , "totalMillis" : 38493} , "insertBytes" : 2075715158} , "preload" : { "docs" : { "num" : 0 , "totalMillis" : 0} , "indexes" : { "num" : 0 , "totalMillis" : 0}}} , "ttl" : { "deletedDocuments" : 0 , "passes" : 135660}} , "ok" : 1.0}
[2013-11-16 00:54:29,655][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] serverStatus: { "serverUsed" : "ds041158-a0.mongolab.com/10.164.39.201:41158" , "host" : "h001111.mongolab.com:41158" , "version" : "2.4.5" , "process" : "mongod" , "pid" : 8297 , "uptime" : 8140271.0 , "uptimeMillis" : 8140271344 , "uptimeEstimate" : 6997787.0 , "localTime" : { "$date" : "2013-11-16T00:54:19.925Z"} , "asserts" : { "regular" : 0 , "warning" : 0 , "msg" : 0 , "user" : 909 , "rollovers" : 0} , "backgroundFlushing" : { "flushes" : 135665 , "total_ms" : 6689269 , "average_ms" : 49.3072568459072 , "last_ms" : 40 , "last_finished" : { "$date" : "2013-11-16T00:53:31.157Z"}} , "connections" : { "current" : 212 , "available" : 19788 , "totalCreated" : 5720524} , "cursors" : { "totalOpen" : 3 , "clientCursors_size" : 3 , "timedOut" : 678 , "totalNoTimeout" : 1} , "dur" : { "commits" : 29 , "journaledMB" : 0.065536 , "writeToDataFilesMB" : 0.063151 , "compression" : 0.6877676097724792 , "commitsInWriteLock" : 0 , "earlyCommits" : 0 , "timeMs" : { "dt" : 3015 , "prepLogBuffer" : 0 , "writeToJournal" : 34 , "writeToDataFiles" : 0 , "remapPrivateView" : 0}} , "extra_info" : { "note" : "fields vary by platform" , "heap_usage_bytes" : 73389016 , "page_faults" : 48865} , "globalLock" : { "totalTime" : 8140271344000 , "lockTime" : 36177851262 , "currentQueue" : { "total" : 0 , "readers" : 0 , "writers" : 0} , "activeClients" : { "total" : 0 , "readers" : 0 , "writers" : 0}} , "indexCounters" : { "accesses" : 48325606 , "hits" : 48325606 , "misses" : 0 , "resets" : 0 , "missRatio" : 0.0} , "locks" : { "." : { "timeLockedMicros" : { "R" : 1925332396 , "W" : 36177851262 , "r" : 0 , "w" : 23} , "timeAcquiringMicros" : { "R" : 6351920584 , "W" : 1654590848}} , "admin" : { "timeLockedMicros" : { "r" : 673023564 , "w" : 0} , "timeAcquiringMicros" : { "r" : 58519031 , "w" : 0}} , "local" : { "timeLockedMicros" : { "r" : 6621510543 , "w" : 1676423994} , "timeAcquiringMicros" : { "r" : 15027254206 , "w" : 531788672}} , "savvy1" : { "timeLockedMicros" : { "r" : 922552 , "w" : 17989} , "timeAcquiringMicros" : { "r" : 152347 , "w" : 46207}} , "savvy" : { "timeLockedMicros" : { "r" : 31696766230268 , "w" : 33388038525} , "timeAcquiringMicros" : { "r" : 29768396314720 , "w" : 59076398644}} , "config" : { "timeLockedMicros" : { "r" : 17241207 , "w" : 36159} , "timeAcquiringMicros" : { "r" : 3094653 , "w" : 47243}} , "test" : { "timeLockedMicros" : { "r" : 14233886 , "w" : 21991191} , "timeAcquiringMicros" : { "r" : 1728654 , "w" : 5338745}}} , "network" : { "bytesIn" : 5.4908274855E10 , "bytesOut" : 3.7344419832E10 , "numRequests" : 628997384} , "opcounters" : { "insert" : 289100 , "query" : 561869810 , "update" : 13760776 , "delete" : 19314 , "getmore" : 18761615 , "command" : 37726913} , "opcountersRepl" : { "insert" : 0 , "query" : 0 , "update" : 0 , "delete" : 0 , "getmore" : 0 , "command" : 0} , "recordStats" : { "accessesNotInMemory" : 24904 , "pageFaultExceptionsThrown" : 12220 , "admin" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0} , "config" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0} , "local" : { "accessesNotInMemory" : 1 , "pageFaultExceptionsThrown" : 0} , "savvy" : { "accessesNotInMemory" : 24902 , "pageFaultExceptionsThrown" : 12220} , "savvy1" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0} , "test" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0}} , "repl" : { "setName" : "rs-ds041158" , "ismaster" : true , "secondary" : false , "hosts" : [ "ds041158-a0.mongolab.com:41158" , "ds041158-a1.mongolab.com:41158"] , "arbiters" : [ "ds041158-r0.mongolab.com:41158"] , "primary" : "ds041158-a0.mongolab.com:41158" , "me" : "ds041158-a0.mongolab.com:41158"} , "writeBacksQueued" : false , "mem" : { "bits" : 64 , "resident" : 637 , "virtual" : 10922 , "supported" : true , "mapped" : 5230 , "mappedWithJournal" : 10460} , "metrics" : { "document" : { "deleted" : 10579 , "inserted" : 289100 , "returned" : 83213429 , "updated" : 12131403} , "getLastError" : { "wtime" : { "num" : 37 , "totalMillis" : 0} , "wtimeouts" : 0} , "operation" : { "fastmod" : 9336047 , "idhack" : 9313199 , "scanAndOrder" : 489} , "queryExecutor" : { "scanned" : 1184731541429} , "record" : { "moves" : 317856} , "repl" : { "apply" : { "batches" : { "num" : 0 , "totalMillis" : 0} , "ops" : 0} , "buffer" : { "count" : 0 , "maxSizeBytes" : 268435456 , "sizeBytes" : 0} , "network" : { "bytes" : 0 , "getmores" : { "num" : 0 , "totalMillis" : 0} , "ops" : 0 , "readersCreated" : 4} , "oplog" : { "insert" : { "num" : 9686892 , "totalMillis" : 38493} , "insertBytes" : 2075715158} , "preload" : { "docs" : { "num" : 0 , "totalMillis" : 0} , "indexes" : { "num" : 0 , "totalMillis" : 0}}} , "ttl" : { "deletedDocuments" : 0 , "passes" : 135660}} , "ok" : 1.0}
[2013-11-16 00:54:29,655][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] process: mongod
[2013-11-16 00:54:29,659][INFO ][org.elasticsearch.river.mongodb.Slurper] Authenticate admin with savvyadmin_prev_es
[2013-11-16 00:54:29,715][INFO ][cluster.metadata         ] [savvy_es_chef_node_2] [_river] update_mapping [savvy_products] (dynamic)
[2013-11-16 00:54:29,769][DEBUG][river.mongodb.util       ] setRiverStatus called with savvy_products - INITIAL_IMPORT_FAILED

@richardwilly98
Copy link
Owner

It does not look like an authentication issue.

How did you come to that conclusion?

Initial import fails if you try to use an index with existing data.

So that's your case please use the new parameter skip_initial_import (see
wiki for mode details)

On Friday, November 15, 2013, Ram Viswanadha wrote:

[2013-11-16 00:54:29,445][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoAdminUser: savvyadmin_prev_es - isAuthenticated: false
[2013-11-16 00:54:29,445][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Authenticate admin with savvyadmin_prev_es
[2013-11-16 00:54:29,652][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] serverStatus: { "serverUsed" : "ds041158-a0.mongolab.com/10.164.39.201:41158" , "host" : "h001111.mongolab.com:41158" , "version" : "2.4.5" , "process" : "mongod" , "pid" : 8297 , "uptime" : 8140271.0 , "uptimeMillis" : 8140271344 , "uptimeEstimate" : 6997787.0 , "localTime" : { "$date" : "2013-11-16T00:54:19.925Z"} , "asserts" : { "regular" : 0 , "warning" : 0 , "msg" : 0 , "user" : 909 , "rollovers" : 0} , "backgroundFlushing" : { "flushes" : 135665 , "total_ms" : 6689269 , "average_ms" : 49.3072568459072 , "last_ms" : 40 , "last_finished" : { "$date" : "2013-11-16T00:53:31.157Z"}} , "connections" : { "current" : 212 , "available" : 19788 , "totalCreated" : 5720524} , "cursors" : { "totalOpen" : 3 , "clientCursors_size" : 3 , "timedOut" : 678 , "totalNoTimeout" : 1} , "dur" : { "commits" : 29 , "journaledMB" : 0.065536 , "writeToDataFilesMB" : 0.063151 , "compression" : 0.6877676097724792 , "commitsInWri
teLock" : 0 , "earlyCommits" : 0 , "timeMs" : { "dt" : 3015 , "prepLogBuffer" : 0 , "writeToJournal" : 34 , "writeToDataFiles" : 0 , "remapPrivateView" : 0}} , "extra_info" : { "note" : "fields vary by platform" , "heap_usage_bytes" : 73389016 , "page_faults" : 48865} , "globalLock" : { "totalTime" : 8140271344000 , "lockTime" : 36177851262 , "currentQueue" : { "total" : 0 , "readers" : 0 , "writers" : 0} , "activeClients" : { "total" : 0 , "readers" : 0 , "writers" : 0}} , "indexCounters" : { "accesses" : 48325606 , "hits" : 48325606 , "misses" : 0 , "resets" : 0 , "missRatio" : 0.0} , "locks" : { "." : { "timeLockedMicros" : { "R" : 1925332396 , "W" : 36177851262 , "r" : 0 , "w" : 23} , "timeAcquiringMicros" : { "R" : 6351920584 , "W" : 1654590848}} , "admin" : { "timeLockedMicros" : { "r" : 673023564 , "w" : 0} , "timeAcquiringMicros" : { "r" : 58519031 , "w" : 0}} , "local" : { "timeLockedMicros" : { "r" : 6621510543 , "w" : 1676423994} , "timeAcquiringMicros" : { "r" : 15027254
206 , "w" : 531788672}} , "savvy1" : { "timeLockedMicros" : { "r" : 922552 , "w" : 17989} , "timeAcquiringMicros" : { "r" : 152347 , "w" : 46207}} , "savvy" : { "timeLockedMicros" : { "r" : 31696766230268 , "w" : 33388038525} , "timeAcquiringMicros" : { "r" : 29768396314720 , "w" : 59076398644}} , "config" : { "timeLockedMicros" : { "r" : 17241207 , "w" : 36159} , "timeAcquiringMicros" : { "r" : 3094653 , "w" : 47243}} , "test" : { "timeLockedMicros" : { "r" : 14233886 , "w" : 21991191} , "timeAcquiringMicros" : { "r" : 1728654 , "w" : 5338745}}} , "network" : { "bytesIn" : 5.4908274855E10 , "bytesOut" : 3.7344419832E10 , "numRequests" : 628997384} , "opcounters" : { "insert" : 289100 , "query" : 561869810 , "update" : 13760776 , "delete" : 19314 , "getmore" : 18761615 , "command" : 37726913} , "opcountersRepl" : { "insert" : 0 , "query" : 0 , "update" : 0 , "delete" : 0 , "getmore" : 0 , "command" : 0} , "recordStats" : { "accessesNotInMemory" : 24904 , "pageFaultExceptionsThrown"
: 12220 , "admin" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0} , "config" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0} , "local" : { "accessesNotInMemory" : 1 , "pageFaultExceptionsThrown" : 0} , "savvy" : { "accessesNotInMemory" : 24902 , "pageFaultExceptionsThrown" : 12220} , "savvy1" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0} , "test" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0}} , "repl" : { "setName" : "rs-ds041158" , "ismaster" : true , "secondary" : false , "hosts" : [ "ds041158-a0.mongolab.com:41158" , "ds041158-a1.mongolab.com:41158"] , "arbiters" : [ "ds041158-r0.mongolab.com:41158"] , "primary" : "ds041158-a0.mongolab.com:41158" , "me" : "ds041158-a0.mongolab.com:41158"} , "writeBacksQueued" : false , "mem" : { "bits" : 64 , "resident" : 637 , "virtual" : 10922 , "supported" : true , "mapped" : 5230 , "mappedWithJournal" : 10460} , "metrics" : { "document" : { "deleted" : 10579 , "inserted"
: 289100 , "returned" : 83213429 , "updated" : 12131403} , "getLastError" : { "wtime" : { "num" : 37 , "totalMillis" : 0} , "wtimeouts" : 0} , "operation" : { "fastmod" : 9336047 , "idhack" : 9313199 , "scanAndOrder" : 489} , "queryExecutor" : { "scanned" : 1184731541429} , "record" : { "moves" : 317856} , "repl" : { "apply" : { "batches" : { "num" : 0 , "totalMillis" : 0} , "ops" : 0} , "buffer" : { "count" : 0 , "maxSizeBytes" : 268435456 , "sizeBytes" : 0} , "network" : { "bytes" : 0 , "getmores" : { "num" : 0 , "totalMillis" : 0} , "ops" : 0 , "readersCreated" : 4} , "oplog" : { "insert" : { "num" : 9686892 , "totalMillis" : 38493} , "insertBytes" : 2075715158} , "preload" : { "docs" : { "num" : 0 , "totalMillis" : 0} , "indexes" : { "num" : 0 , "totalMillis" : 0}}} , "ttl" : { "deletedDocuments" : 0 , "passes" : 135660}} , "ok" : 1.0}
[2013-11-16 00:54:29,655][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] serverStatus: { "serverUsed" : "ds041158-a0.mongolab.com/10.164.39.201:41158" , "host" : "h001111.mongolab.com:41158" , "version" : "2.4.5" , "process" : "mongod" , "pid" : 8297 , "uptime" : 8140271.0 , "uptimeMillis" : 8140271344 , "uptimeEstimate" : 6997787.0 , "localTime" : { "$date" : "2013-11-16T00:54:19.925Z"} , "asserts" : { "regular" : 0 , "warning" : 0 , "msg" : 0 , "user" : 909 , "rollovers" : 0} , "backgroundFlushing" : { "flushes" : 135665 , "total_ms" : 6689269 , "average_ms" : 49.3072568459072 , "last_ms" : 40 , "last_finished" : { "$date" : "2013-11-16T00:53:31.157Z"}} , "connections" : { "current" : 212 , "available" : 19788 , "totalCreated" : 5720524} , "cursors" : { "totalOpen" : 3 , "clientCursors_size" : 3 , "timedOut" : 678 , "totalNoTimeout" : 1} , "dur" : { "commits" : 29 , "journaledMB" : 0.065536 , "writeToDataFilesMB" : 0.063151 , "compression" : 0.6877676097724792 , "commitsInWri
teLock" : 0 , "earlyCommits" : 0 , "timeMs" : { "dt" : 3015 , "prepLogBuffer" : 0 , "writeToJournal" : 34 , "writeToDataFiles" : 0 , "remapPrivateView" : 0}} , "extra_info" : { "note" : "fields vary by platform" , "heap_usage_bytes" : 73389016 , "page_faults" : 48865} , "globalLock" : { "totalTime" : 8140271344000 , "lockTime" : 36177851262 , "currentQueue" : { "total" : 0 , "readers" : 0 , "writers" : 0} , "activeClients" : { "total" : 0 , "readers" : 0 , "writers" : 0}} , "indexCounters" : { "accesses" : 48325606 , "hits" : 48325606 , "misses" : 0 , "resets" : 0 , "missRatio" : 0.0} , "locks" : { "." : { "timeLockedMicros" : { "R" : 1925332396 , "W" : 36177851262 , "r" : 0 , "w" : 23} , "timeAcquiringMicros" : { "R" : 6351920584 , "W" : 1654590848}} , "admin" : { "timeLockedMicros" : { "r" : 673023564 , "w" : 0} , "timeAcquiringMicros" : { "r" : 58519031 , "w" : 0}} , "local" : { "timeLockedMicros" : { "r" : 6621510543 , "w" : 1676423994} , "timeAcquiringMicros" : { "r" : 15027254
206 , "w" : 531788672}} , "savvy1" : { "timeLockedMicros" : { "r" : 922552 , "w" : 17989} , "timeAcquiringMicros" : { "r" : 152347 , "w" : 46207}} , "savvy" : { "timeLockedMicros" : { "r" : 31696766230268 , "w" : 33388038525} , "timeAcquiringMicros" : { "r" : 29768396314720 , "w" : 59076398644}} , "config" : { "timeLockedMicros" : { "r" : 17241207 , "w" : 36159} , "timeAcquiringMicros" : { "r" : 3094653 , "w" : 47243}} , "test" : { "timeLockedMicros" : { "r" : 14233886 , "w" : 21991191} , "timeAcquiringMicros" : { "r" : 1728654 , "w" : 5338745}}} , "network" : { "bytesIn" : 5.4908274855E10 , "bytesOut" : 3.7344419832E10 , "numRequests" : 628997384} , "opcounters" : { "insert" : 289100 , "query" : 561869810 , "update" : 13760776 , "delete" : 19314 , "getmore" : 18761615 , "command" : 37726913} , "opcountersRepl" : { "insert" : 0 , "query" : 0 , "update" : 0 , "delete" : 0 , "getmore" : 0 , "command" : 0} , "recordStats" : { "accessesNotInMemory" : 24904 , "pageFaultExceptionsThrown"
: 12220 , "admin" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0} , "config" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0} , "local" : { "accessesNotInMemory" : 1 , "pageFaultExceptionsThrown" : 0} , "savvy" : { "accessesNotInMemory" : 24902 , "pageFaultExceptionsThrown" : 12220} , "savvy1" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0} , "test" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0}} , "repl" : { "setName" : "rs-ds041158" , "ismaster" : true , "secondary" : false , "hosts" : [ "ds041158-a0.mongolab.com:41158" , "ds041158-a1.mongolab.com:41158"] , "arbiters" : [ "ds041158-r0.mongolab.com:41158"] , "primary" : "ds041158-a0.mongolab.com:41158" , "me" : "ds041158-a0.mongolab.com:41158"} , "writeBacksQueued" : false , "mem" : { "bits" : 64 , "resident" : 637 , "virtual" : 10922 , "supported" : true , "mapped" : 5230 , "mappedWithJournal" : 10460} , "metrics" : { "document" : { "deleted" : 10579 , "inserted"
: 289100 , "returned" : 83213429 , "updated" : 12131403} , "getLastError" : { "wtime" : { "num" : 37 , "totalMillis" : 0} , "wtimeouts" : 0} , "operation" : { "fastmod" : 9336047 , "idhack" : 9313199 , "scanAndOrder" : 489} , "queryExecutor" : { "scanned" : 1184731541429} , "record" : { "moves" : 317856} , "repl" : { "apply" : { "batches" : { "num" : 0 , "totalMillis" : 0} , "ops" : 0} , "buffer" : { "count" : 0 , "maxSizeBytes" : 268435456 , "sizeBytes" : 0} , "network" : { "bytes" : 0 , "getmores" : { "num" : 0 , "totalMillis" : 0} , "ops" : 0 , "readersCreated" : 4} , "oplog" : { "insert" : { "num" : 9686892 , "totalMillis" : 38493} , "insertBytes" : 2075715158} , "preload" : { "docs" : { "num" : 0 , "totalMillis" : 0} , "indexes" : { "num" : 0 , "totalMillis" : 0}}} , "ttl" : { "deletedDocuments" : 0 , "passes" : 135660}} , "ok" : 1.0}
[2013-11-16 00:54:29,655][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] process: mongod
[2013-11-16 00:54:29,659][INFO ][org.elasticsearch.river.mongodb.Slurper] Authenticate admin with savvyadmin_prev_es
[2013-11-16 00:54:29,715][INFO ][cluster.metadata ] [savvy_es_chef_node_2] [_river] update_mapping savvy_products
[2013-11-16 00:54:29,769][DEBUG][river.mongodb.util ] setRiverStatus called with savvy_products - INITIAL_IMPORT_FAILED


Reply to this email directly or view it on GitHubhttps://github.com//issues/164#issuecomment-28615616
.

@ramv
Copy link
Author

ramv commented Nov 16, 2013

my apologies. In the first instance the log stopped after trying to authenticate. So I presumed that the authentication has failed

@ramv
Copy link
Author

ramv commented Nov 27, 2013

still having issues with mongodb servers hosted on MongoLab. We had an issue yesterday after one of the ElasticSearch nodes was restarted. The following query was causing a huge spike in the CPU load

{
            "opid" : 55243449,
            "active" : true,
            "secs_running" : 2400,
            "op" : "query",
            "ns" : "local.oplog.rs",
            "query" : {
                "$query" : {
                    "$and" : [
                        {
                            "$or" : [
                                {
                                    "ns" : "savvy.comments"
                                },
                                {
                                    "ns" : "savvy.$cmd"
                                }
                            ]
                        },
                        {
                            "ts" : {
                                "$gt" : Timestamp(1385145242, 3)
                            }
                        }
                    ]
                },
                "$orderby" : {
                    "$natural" : 1
                }
            },
            "client" : "10.76.227.130:25779",
            "desc" : "conn4463008",
            "threadId" : "0x7f2a15174700",
            "connectionId" : 4463008,
            "locks" : {
                "^" : "r",
                "^local" : "R"
            },
            "waitingForLock" : false,
            "numYields" : 7824,
            "lockStats" : {
                "timeLockedMicros" : {
                    "r" : NumberLong("4250384961"),
                    "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                    "r" : NumberLong("2400856653"),
                    "w" : NumberLong(0)
                }
            }
        }

MongoLab support says the following:

It looks like that same query was killing things:

Wed Nov 27 11:57:48.720 [conn81634] query local.oplog.rs query: 
{
    "$query": {
        "$and": [
            {
                "$or": [
                    {
                        "ns": "savvy.collections"
                    },
                    {
                        "ns": "savvy.$cmd"
                    }
                ]
            },
            {
                "ts": {
                    "$gt": "Timestamp1385115577000|2"
                }
            }
        ]
    },
    "$orderby": {
        "$natural": 1
    }
}
cursorid:206352073259044707 ntoreturn:0 ntoskip:0 nscanned:11427020 keyUpdates:0 numYields: 9292 locks(micros) r:3034952783 nreturned:101
reslen:50242 1674239ms

How much control do you have over these queries? Sorting by natural ordering on the oplog should be fast, but filtering on those fields ("ns" and "ts") is going to be very slow because there are no indexes available on the oplog, so it has to do a full collection scan every time.

Any pointers on fixing this?

@richardwilly98
Copy link
Owner

@ramv
I am surprised by the query issued. getOplogFilter has been modified in 1.7.2 [1] to replace the ugly $or by $in.

So you should see somethinkg like:

{
    "$query": {
        "$and": [
            {
                "ns": {
                        "$in": ["savvy.collections", "savvy.$cmd"]
                }
            },
            {
                "ts": {
                    "$gt": "Timestamp1385115577000|2"
                }
            }
        ]
    },
    "$orderby": {
        "$natural": 1
    }
}

Could you please confirm you are currently running river 1.7.2? It should be in ES log file when the river is started.

  • ts is required so the river does not tail the full oplog.rs collection.
  • Regarding ns this filter was included to try to reduce the amount of data between MongoDB and ES but it could optionally be removed.

[1] - https://github.com/richardwilly98/elasticsearch-river-mongodb/blob/elasticsearch-river-mongodb-1.7.2/src/main/java/org/elasticsearch/river/mongodb/Slurper.java#L353

richardwilly98 added a commit that referenced this issue Dec 2, 2013
- The filter will only use ts with OPLOG_REPLAY
- Other filtering will be handled within the river
@richardwilly98
Copy link
Owner

@ramv
oplog.rs filter has been cleaned-up again. It now uses only ts.
Can you please try release 1.7.3 and let me know how it goes?

@ramv
Copy link
Author

ramv commented Dec 6, 2013

will do . i will install the new version today. Thank you very much for
looking into this Richard!

On Fri, Dec 6, 2013 at 2:48 AM, Richard Louapre notifications@github.comwrote:

@ramv https://github.com/ramv
oplog.rs filter has been cleaned-up again. It now uses only ts.
Can you please try release 1.7.3 and let me know how it goes?


Reply to this email directly or view it on GitHubhttps://github.com//issues/164#issuecomment-29979182
.

Best Regards,

Ram Viswanadha

@richardwilly98
Copy link
Owner

@ramv
Could you please provide feedback with release 1.7.3?

@ramv
Copy link
Author

ramv commented Jan 14, 2014

currently testing 1.7.3 on production.

sudo tail -f /mnt/elasticsearch/logs/log.log
[2014-01-13 23:30:27,771][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Starting river comments
[2014-01-13 23:30:27,907][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoDB River Plugin - version[1.7.3] - hash[4ca377f] - time[2013-12-05T14:34:13Z]
[2014-01-13 23:30:27,907][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] starting mongodb stream. options: secondaryreadpreference [true], drop_collection [false], include_collection [], throttlesize [500], gridfs [false], filter [null], db [savvy], collection [comments], script [null], indexing to [comments]/[comment]
[2014-01-13 23:30:28,245][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoAdminUser: - {deleted} isAuthenticated: false
[2014-01-13 23:30:28,245][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Authenticate admin with {deleted}
[2014-01-13 23:30:29,874][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoDB version - 2.4.5

So far no issues faced.

@benmccann
Copy link
Collaborator

Sounds like this was fixed for you 1.7.3, so I'm going to close this issue

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants