3M context switches due to sched_yield

XMLWordPrintableJSON

    • Type: Bug
    • Resolution: Done
    • Priority: Major - P3
    • None
    • Affects Version/s: 3.6.3
    • Component/s: WiredTiger
    • None
    • ALL
    • None
    • 3
    • None
    • None
    • None
    • None
    • None
    • None
    • None

      First, excuse me for non informative description Issue happens not often, so I didn't collect more information.

      During some dumb testing following weird behaviour were observed:

      • test configuration:
        • aws i3.2xlarge (2TB NVMe), ubuntu 14.04, mongodb 3.6.3
        • table with 3 fields:
           {_id: <blob>, touch: <timestamp>, kv: <map<string,blob>>} 

          with tts index on touch with expireAfterSeconds: 12hours .

        • "Upsertion" with
           db.ctx.update({_id: <id>}, {$set: {"kv.<key>": <value>, "touch": <now>}}) 

          , <value> blobs are near 512bytes (msgpack coded structure), <id> is near 40 bytes and highly random.

          • Upsertion are in two streams: first is ingesting huge set of records, so it is at high speed (~12k per second), and second is replicating commands (~2k per second)
        • At the same time, documents are randomly requested by _id (from same stream of replicated commands, with rate ~10k per second)
      • weird behaviour:
        • At some rare case mongo starts to consume a lot of System CPU (instead of User). strace showed a lot of call to '__sched_yield' system call. Number of context switches jumps to 3 millions per second instead of 80 thousands in usual.
        • First time it happend when on-disk database size reaches 64GB.
        • Currently, after couple of days, on-disk size is 234GB, and ingestion finished. Size of data starts to decrease (because of expiring), and this behavior occurs more often.
          (Picture with process stat are from time when ingestion stops. "perf top" screenshot from time when I first encounter behaviour).

        1. 3.6.4_eviction_checkpoint_target=0.png
          3.6.4_eviction_checkpoint_target=0.png
          381 kB
        2. 3.6.4.png
          3.6.4.png
          409 kB
        3. checkpoint-scrub.png
          checkpoint-scrub.png
          211 kB
        4. diagnostic_data.tar.gz
          106.45 MB
        5. diagnostic-2018-04-20.tar.gz
          2.15 MB
        6. last_diagnostic.tar.gz
          4.03 MB
        7. Monto_sched_yield.png
          Monto_sched_yield.png
          627 kB
        8. perf.out.tar.gz
          8.82 MB
        9. stacks.tar.gz
          212 kB
        10. SwitchesHigh.png
          SwitchesHigh.png
          481 kB
        11. SystemStat-2018-03-21-long.png
          SystemStat-2018-03-21-long.png
          492 kB
        12. SystemStat-2018-04-20_18-41-47.png
          SystemStat-2018-04-20_18-41-47.png
          187 kB
        13. SystemStat-2018-04-20_19-40-40.png
          SystemStat-2018-04-20_19-40-40.png
          183 kB
        14. SystemStat-2018-04-20_23-10-24.png
          SystemStat-2018-04-20_23-10-24.png
          207 kB

            Assignee:
            Dmitry Agranat
            Reporter:
            Юрий Соколов
            Votes:
            0 Vote for this issue
            Watchers:
            8 Start watching this issue

              Created:
              Updated:
              Resolved: