what may trigger a mongodb yield?

[Andy Fan]

recently we are getting a lot of complains from user about performance.   Here are some sample query.

3.0.8:

2016-10-24T11:39:57.520-0700 I QUERY [conn678684] query xxx.CollectionEntry query: { $orderby: { _id: 1 }, $query: { collectionId: { $in: [ "305254839016", "272225127016", "112138984016", "208145573016", "73356257016", "202169692016", "265342940016", "131798667016", "119998271016", "60863288016", "297410402016", "173247546016", "214939765016", "118168993016", "288889204016", "110426393016", "313041680016", "207198790016", "341585606016", "91598576016", "263319914016", "270097757016", "122159833016", "112696536016", "203057160016", "123247241016", "94612215016", "62677936016", "113371656016", "85136434016", "58813027016", "289430571016", "75306270016", "153305463016", "79437312016", "181365456016", "206035166016", "116939005016", "308323621016", "134461130016", "106420537016", "308321417016", "210970307016", "58824080016", "128613606016", "101336150016", "87097880016", "96781249016", "79660042016", "187205615016", "197407485016", "136547006016", "148607336016", "331938518016", "60116115016", "199529251016", "288906244016", "206000561016", "193613748016", "182299489016", "87087263016", "115124282016", "114583259016", "93009598016", "222301517016", "58930158016", "125507514016", "297706085016", "115123676016", "114903104016", "98140546016", "95786782016", "269060195016", "70891452016", "261565673016", "109003945016", "193777756016", "240671314016", "233934611016", "267373332016", "88401663016", "132589195016", "268640691016", "291038698016", "270072461016", "316406946016", "304760908016", "197988183016", "284124995016", "306240345016", "292102460016", "225432116016", "61037987016", "107580799016", "194560672016", "214279935016", "207217561016", "216450766016", "60705083016", "95035193016", "58931451016", "233278654016", "270102005016", "119549856016", "298826718016", "222116420016", "107602556016", "220241998016", "342258951016", "132857925016", "193675418016", "106980406016", "273014363016", "134689395016", "197308200016", "144813208016", "117100777016", "156259446016", "124005428016", "112720786016", "58932469016", "110283360016", "289449588016", "264287486016", "118307482016", "264417365016", "184517045016", "131901669016", "58871460016", "111566177016", "190192469016", "110201147016", "297278716016", "298416205016", "112160595016", "59245201016", "128927821016", "122748624016", "59139116016", "303791051016", "95031876016", "128945707016", "209767255016", "177370406016", "54365643016", "174738552016", "198416616016", "155729330016", "191156422016", "124539104016", "59414748016", "98831752016", "301002536016", "192191202016", "235672119016", "192072507016", "196765750016", "155294770016", "199525391016", "56470231016", "201484901016", "186080208016", "290143765016", "207198997016", "91238436016", "61711306016", "112325476016", "260476670016", "151948226016", "260098478016", "263390991016", "282732447016", "292449628016", "309863189016", "163556624016", "121177776016", "84942986016", "199533611016", "81018193016", "306138681016", "220886113016", "298826541016", "117879877016", "112065682016", "265881006016", "269956810016", "193796920016", "193335682016", "226287435016", "193805717016", "71903732016", "141435031016", "111537154016", "123002827016", "59956082016", "310052115016", "257335586016", "177642380016", "265341812016", "62878446016", "58552854016", "181899404016", "170069051016", "84302277016", "323741022016", "85132540016", "110129575016", "71044279016", "287974913016", "199604439016", "138018819016", "94849689016", "81588248016", "289429906016", "308322408016", "87155420016", "198949809016", "73370331016", "110663724016", "266182896016", "225193232016", "59641071016", "296785511016", "204796751016", "304687319016", "222416629016", "296602976016", "284062244016", "244713628016", "216878107016", "112154810016", "182692031016", "102028237016", "211652462016", "211041057016", "69536441016", "290130270016", "195818297016", "128781950016", "135389284016", "291587627016", "205821276016", "127446722016", "215685956016", "259170932016", "291609453016", "191736371016", "61712752016", "309529547016", "192485023016" ] }, _id: { $gt: ObjectId('576d7151b6e228049dc9c198') } } } planSummary: IXSCAN { collectionId: 1.0 }, IXSCAN { collectionId: 1.0 } ntoreturn:250 ntoskip:0 nscanned:28934 nscannedObjects:28436 scanAndOrder:1 keyUpdates:0 writeConflicts:0 numYields:2294 nreturned:218 reslen:46676 locks:{ Global: { acquireCount: { r: 4590 }, acquireWaitCount: { r: 650 }, timeAcquiringMicros: { r: 99350417 } }, Database: { acquireCount: { r: 2295 } }, Collection: { acquireCount: { r: 2295 } } } 363176ms

2.6.9:

2016-10-24T09:28:18.049-0700 [conn2574582] remove emailalertrs.UserItemEmailData query: { ItemId: 131971504004, UserId: 91062406 } ndeleted:1 keyUpdates:0 numYields:626 locks(micros) w:294276 14927ms

and we do have index {itemId + UserId}

so for the first case,  it scans  and order 28k rows, it take 363 second, with 2294 yield! 

for the second case,  it scans 1 row but it take 14 seconds. 

the first thing I am thinking about is it is caused by too many yields.

my questions are:

1).   what can trigger so many yield?

2).   what is the main place to check in source code for these logic?  

thanks