-
Type: Question
-
Resolution: Done
-
Priority: Major - P3
-
None
-
Affects Version/s: None
-
Component/s: MapReduce
-
Labels:None
Mongo-DB in spite of having adequate resources ( 4 - Core Box ) with single map-reduce operations seems to be chocking down other operations. In our simple tests , with simple collection having 400 records , a select takes more than 16 seconds. The map-reduce is running entirely on a different collection. Also we noticed node is unable to connect - resets the connection and on a new connection query is run which normally takes fraction of a second now takes nearly 16 seconds to comeback with a count of < 300 records.
Conn5865 - Command Count takes 16509 ms while map reduce is running. Under normal load conditions < 100 milliseconds.
, acquireWaitCount:
{ r: 3 }, timeAcquiringMicros:
{ r: 7055 }}, Collection: { acquireCount:
{ r: 11 } } } protocol:op_query 135ms
2016-03-31T14:58:11.322-0700 I COMMAND [conn6097] CMD: drop dim3.tmp.mr.whois.tech_postalcode_56cc44bbf2e5301119d51e37s_3924
2016-03-31T14:58:11.371-0700 I NETWORK [initandlisten] connection accepted from 172.31.32.189:37316 #6167 (363 connections now open)
2016-03-31T14:58:16.007-0700 I - [conn6097] M/R: (3/3) Final Reduce Progress: 50700/54200 93%
2016-03-31T14:58:19.030-0700 I - [conn6097] M/R Reduce Post Processing Progress: 8100/54200 14%
2016-03-31T14:58:22.045-0700 I - [conn6097] M/R Reduce Post Processing Progress: 16600/54200 30%
2016-03-31T14:58:25.028-0700 I - [conn6097] M/R Reduce Post Processing Progress: 24900/54200 45%
2016-03-31T14:58:26.190-0700 I NETWORK [initandlisten] connection accepted from 172.31.32.189:37317 #6168 (364 connections now open)
2016-03-31T14:58:26.191-0700 I NETWORK [conn6166] end connection 172.31.32.189:37315 (363 connections now open)
2016-03-31T14:58:28.004-0700 I - [conn6097] M/R Reduce Post Processing Progress: 32800/54200 60%
2016-03-31T14:58:31.015-0700 I - [conn6097] M/R Reduce Post Processing Progress: 41300/54200 76%
2016-03-31T14:58:34.011-0700 I - [conn6097] M/R Reduce Post Processing Progress: 50000/54200 92%
2016-03-31T14:58:35.490-0700 I COMMAND [conn6097] CMD: drop dim3.tmp.mr.whois.tech_postalcode_56cc44bbf2e5301119d51e37s_3924
2016-03-31T14:58:35.490-0700 I COMMAND [conn6167] command local.oplog.rs command: getMore { getMore: 116290011101, collection: "oplog.rs", maxTimeMS: 5000, term: 17, lastKnownCommittedOpTime:
} cursorid:116290011101 keyUpdates:0 writeConflicts:0 exception: operation exceeded time limit code:50 numYields:0 reslen:74 locks:{ Global: { acquireCount:
{ r: 2 }, acquireWaitCount:
{ r: 1 }, timeAcquiringMicros:
{ r: 19300914 }}, Database: { acquireCount:
{ r: 1 }}, oplog: { acquireCount:
{ r: 1 } } } protocol:op_command 19301ms
2016-03-31T14:58:35.490-0700 I NETWORK [conn6167] end connection 172.31.32.189:37316 (362 connections now open)
2016-03-31T14:58:35.492-0700 I NETWORK [conn6168] end connection 172.31.32.189:37317 (361 connections now open)
2016-03-31T14:58:35.493-0700 I NETWORK [initandlisten] connection accepted from 172.31.32.189:37318 #6169 (362 connections now open)
2016-03-31T14:58:35.496-0700 I COMMAND [conn5865] command dim3.scans command: count { count: "scans", query: { $and: [
] } } planSummary: COUNT_SCAN
{ scan_status: 1.0 }keyUpdates:0 writeConflicts:0 numYields:1 reslen:62 locks:{ Global: { acquireCount:
{ r: 4 }, acquireWaitCount:
{ r: 1 }, timeAcquiringMicros:
{ r: 16503711 }}, Database: { acquireCount:
{ r: 2 }, acquireWaitCount:
{ r: 1 }, timeAcquiringMicros:
{ r: 5971 }}, Collection: { acquireCount:
{ r: 2 } } } protocol:op_query 16509ms
2016-03-31T14:58:35.499-0700 I COMMAND [conn6097] CMD: drop dim3.tmp.mr.whois.tech_postalcode_56cc44bbf2e5301119d51e37s_3924
2016-03-31T14:58:35.530-0700 I COMMAND [conn6097] command dim3.domainstats command: mapReduce { mapreduce: "whois.tech_postalcode_56cc44bbf2e5301119d51e37s", map: "function () {
var key = this._id;
var value=
;
if(value.colors){
//coming from aggregate collections
va...", reduce: "function (key, values) {
//printjson(values)
var reduce ={colors:{whois:{}}};
values.forEach(function(value){
var properties = Ob...", verbose: true, out:
, jsMode: true, sort:
{ _id: 1 }, readPreference: "primary" } planSummary: COUNT keyUpdates:0 writeConflicts:0 numYields:850 reslen:218 locks:{ Global: { acquireCount:
{ r: 382226, w: 216813, W: 54201 }}, Database: { acquireCount:
{ r: 54635, w: 216807, R: 971, W: 8 }, acquireWaitCount:
{ W: 2 }, timeAcquiringMicros:
{ W: 24771 }}, Collection: { acquireCount:
{ r: 54635, w: 108406 }}, Metadata: { acquireCount:
{ w: 108403 }}, oplog: { acquireCount:
{ w: 108403 }} } protocol:op_query 24225ms