-
Type:
Bug
-
Resolution: Done
-
Priority:
Major - P3
-
Affects Version/s: 2.8.0-rc4
-
Component/s: Concurrency
-
Labels:
-
Fully Compatible
-
ALL
- tests run on Ubuntu, VMWare, 6 cores.
- heavy mixed workload (read, update, insert) with 100 clients
- using a recent pre-rc4 build from master (6105f06402fe1e7578d41f3e4e583a1476ef2455); subsequently reproduced under rc4.
Run with replica set of 1:
- Throughout the run mongod write queues (second line) sporadically build, indicating a write bottleneck in mongod. This may be the same issue as
SERVER-16651. - At a couple points during the run (A, B, C), mongod log reports isolated (single) write operations (updates or inserts) taking extreme times, up to 111891 ms in this test (you can read this off of the "max logged query" graph: vertical axis is longest operation, in ms, logged in each 0.1 second interval). Unknown if this is the same bottleneck or a different issue, so opening this issue to investigate.
- The pattern seen in the graph above of 3 or so such isolated extreme latencies of increasing size throughout the run is repeatable with this workload. The length of each one is roughly double the preceding one.
For comparison, here's the same workload standalone:
- Write queues do not build.
- We see pauses in WT (e.g. A, B; subject of
SERVER-16662). Those pauses are less evident in the replica set case above, probably because the mongod bottleneck in that case throttles the workload going into WT. - Associated with pauses are numerous long latency operations around 11 seconds, but no extreme long-latency operations as seen in the preceding test.
- Overall throughput is much higher in the standalone case, possibly because of the bottleneck in the replica set case.
Here are the specific queries, two updates and one insert, that showed extreme latencies:
2014-12-24T12:17:14.182-0500 I QUERY [conn95] command testsrv.$cmd command: update { update: "data", writeConcern: {}, ordered: true, updates: [ { q: { _id: { o: ObjectId('549af4f61d41c883ae5622d2'), t: "This is a string, not a small string either, it's in here to make the index larger", seq: -1729382253017956352 } }, u: { $set: { f0: -1097749151, f1: -1097691211, f2: "bkfiv Wfi vWfiv Wf ivW fivW fivW fiv Wfiv Wf i ", f3: "dsz szs zsz szs zs zszszs z szsz szszs z szs zs", f4: "xa jmH szsz sz sz sz sz szszs zszsz sz s zszszs z", f5: "szsz szs zsz szs zs zszszs z szsz szszs z szs zs", f6: "ivWfi vWfi vWf ivW fiv Wf i vW f ivW f ivWfiv W", f7: "yvWfiv Wfiv Wf iv Wf iv WfivW fivWf iv W fivWfi v", f8: "mH s zszs zsz szs zsz sz s zs z szs z szszsz s", f9: "rqjmH szs zszsz sz szs zszs zszs zsz szsz sz s ", fa: 47242, fb: 91501, fc: "ajmH s zszs zs zszsz sz szsz szsz szszs zszsz sz", fd: "mHszsz szsz sz sz sz sz szszs zszsz sz s zszszs z", fe: "uHsz szs zsz szs zs zszszs z szsz szszs z szs zs", ff: "zszsz szs zszsz sz szs zszs zszs zsz szsz sz s ", f10: "kfivW f i v Wf ivWfi vW fi v Wfiv WfivW f ivW fi", f11: "tkfiv Wfi v W f i vWfiv Wf iv WfivW fivWf ivWfi vW", f12: "zszs zszs zsz szs zsz sz s zs z szs z szszsz s", f13: "pKNkf ivW fivWf iv Wfi vWfi vWfi vWf ivWf iv W ", f14: 51733, f15: 90312, f16: "qjmHs zs zszs zsz s zsz szs zsz szs zszsz sz szsz ", f17: "yv W fivW fiv Wfi vWf iv W fi v Wfi v WfivWf i", f18: "bkf i vWfiv Wf ivWf ivW fiv W f iv Wfi v WfivW fi", f19: "ajmHs zs zszs zsz s zsz szs zsz szs zszsz sz szsz ", f1a: "bkfivW fivW fiv Wfi vWf iv W fi v Wfi v WfivWf i", f1b: "cnajmH szs zszsz sz szs zszs zszs zsz szsz sz s ", f1c: "cn a jmHs zsz szs zsz sz s zs z szs z szszsz s", f1d: "gt k fivW fiv Wfi vWf iv W fi v Wfi v WfivWf i" } }, multi: false, upsert: false } ] } ntoreturn:1 keyUpdates:0 reslen:95 24494ms
2014-12-24T12:18:06.958-0500 I QUERY [conn100] command testsrv.$cmd command: insert { insert: "data", writeConcern: {}, ordered: true, documents: [ { _id: { o: ObjectId('549af4f61d41c883a908b7c2'), t: "This is a string, not a small string either, it's in here to make the index larger", seq: 3819052484899373056 }, f0: 1826216753, f1: 1826277117, f2: "bkfivW fivW fiv Wfi vWf iv W fi v Wfi v WfivWf i", f3: "lKNkf iv W f ivW f ivWf ivWf ivWf ivWfiv WfivW fi", f4: "wNkfi vWfi vWf ivW fiv Wf i vW f ivW f ivWfiv W", f5: "qj m Hszs zsz szs zsz sz s zs z szs z szszsz s", f6: "xajmH szs zszsz sz szs zszs zszs zsz szsz sz s ", f7: "oHszs zs zszs zsz s zsz szs zsz szs zszsz sz szsz ", f8: "zsz szs zsz szs zs zszszs z szsz szszs z szs zs", f9: "sz s zszs zsz szs zsz sz s zs z szs z szszsz s", fa: 54913, fb: 94391, fc: "szsz szs zsz szs zs zszszs z szsz szszs z szs zs", fd: "ivWfi vW fivW fiv W fiv Wfi vWf ivW fivWf iv Wfiv ", fe: "jmHszs zszs zsz szs zsz sz s zs z szs z szszsz s", ff: "fivWf iv W f ivW f ivWf ivWf ivWf ivWfiv WfivW fi", f10: "rq jmH szsz sz sz sz sz szszs zszsz sz s zszszs z", f11: "wNkfi vW fivW fiv W fiv Wfi vWf ivW fivWf iv Wfiv ", f12: "lKN k fivWf iv Wfiv Wfi vWf i v Wf ivW f ivWfi vW", f13: "vWf i vWfiv Wf ivWf ivW fiv W f iv Wfi v WfivW fi", f14: 50071, f15: 107864, f16: "mHsz szs zszsz sz szs zszs zszs zsz szsz sz s ", f17: "ezszsz szsz sz sz sz sz szszs zszsz sz s zszszs z", f18: "yvWfiv Wfiv Wf iv Wf iv WfivW fivWf iv W fivWfi v", f19: "tkfiv Wf i v Wfi v Wfiv Wfiv Wfiv WfivWf ivWfi vW", f1a: "ivWfi vWfi vWf ivW fiv Wf i vW f ivW f ivWfiv W", f1b: "fivWf ivW fivWf iv Wfi vWfi vWfi vWf ivWf iv W ", f1c: "mHsz szs zszsz sz szs zszs zszs zsz szsz sz s ", f1d: "oHsz szs zszsz sz szs zszs zszs zsz szsz sz s " } ] } ntoreturn:1 keyUpdates:0 reslen:80 52917ms
2014-12-24T12:19:58.656-0500 I QUERY [conn39] command testsrv.$cmd command: update { update: "data", writeConcern: {}, ordered: true, updates: [ { q: { _id: { o: ObjectId('549af4f61d41c8837743de22'), t: "This is a string, not a small string either, it's in here to make the index larger", seq: 3602879702735257600 } }, u: { $set: { f0: -1097747785, f1: -1097704122, f2: "rqj m Hszsz sz szsz szs zsz s z sz szs z szszs zs", f3: "mHszs zszsz sz szsz szs zsz s z sz szs z szszs zs", f4: "bkfivW fivW fiv Wfi vWf iv W fi v Wfi v WfivWf i", f5: "vWfiv Wfi vWfiv Wf ivW fivW fivW fiv Wfiv Wf i ", f6: "fivW fivW fiv Wfi vWf iv W fi v Wfi v WfivWf i", f7: "xajmH sz s z szs z szsz szsz szsz szszsz szszs zs", f8: "jmH szs zsz szs zs zszszs z szsz szszs z szs zs", f9: "ajmH s zszs zs zszsz sz szsz szsz szszs zszsz sz", fa: 44944, fb: 82734, fc: "qjmHs zs zszs zsz s zsz szs zsz szs zszsz sz szsz ", fd: "uH s zszs zsz szs zsz sz s zs z szs z szszsz s", fe: "mHszsz szsz sz sz sz sz szszs zszsz sz s zszszs z", ff: "sz s zszs zsz szs zsz sz s zs z szs z szszsz s", f10: "dszszs zszs zs zszsz sz szsz szsz szszs zszsz sz", f11: "tkfiv Wfi vWfiv Wf ivW fivW fivW fiv Wfiv Wf i ", f12: "ezszs zszsz sz szsz szs zsz s z sz szs z szszs zs", f13: "ivWf ivW fiv Wfi vW fivWfi v Wfiv WfivW f ivW fi", f14: 40990, f15: 88315, f16: "oHsz szs zszsz sz szs zszs zszs zsz szsz sz s ", f17: "ivWfi vW fivW fiv W fiv Wfi vWf ivW fivWf iv Wfiv ", f18: "xa jmH szsz sz sz sz sz szszs zszsz sz s zszszs z", f19: "iv W fivW fiv Wfi vWf iv W fi v Wfi v WfivWf i", f1a: "fivW fivW fiv Wfi vWf iv W fi v Wfi v WfivWf i", f1b: "bk fiv Wfiv Wf iv Wf iv WfivW fivWf iv W fivWfi v", f1c: "kfivWf ivWf iv Wf iv Wf ivWfi vWfiv Wf i vWfivW f", f1d: "bkfi vWfi vWf ivW fiv Wf i vW f ivW f ivWfiv W" } }, multi: false, upsert: false } ] } ntoreturn:1 keyUpdates:0 reslen:95 111891ms
- is duplicated by
-
-
- Closed
-
- is related to
-
-
- Closed
-
-
SERVER-16640 Long running queries on the secondary with WT
-
- Closed
-