Uploaded image for project: 'Couchbase Python Client Library'
  1. Couchbase Python Client Library
  2. PYCBC-507

overhead too high with tracing enabled

    XMLWordPrintable

Details

    • Bug
    • Status: Resolved
    • Major
    • Resolution: Fixed
    • 2.4.0-beta2, 2.4.0
    • 2.4.1
    • None
    • None
    • 1

    Description

      2.4.0-beta2-9-gf8683a6/lcb 2.9.2: $ python bench.py -U couchbase:/
      /centos7lx-55a.home.ingenthron.org/ -p benchbench -t 64 -N 10 -D 60 
      Total run took an absolute time of 60.00 seconds
      Did a total of 1711190 operations
      Total wait time of 3825.66 seconds
      [WAIT] 447.29 ops/second
      [ABS] 28519.37 ops/second
       
       
      2.4.0-beta2-9-gf8683a6/lcb 2.9.2: $ python bench.py -U couchbase:/
      /centos7lx-55a.home.ingenthron.org/?compression=off -p benchbench -t 64 -N 10 -
      D 60 
      Total run took an absolute time of 60.00 seconds
      Did a total of 1775190 operations
      Total wait time of 3825.85 seconds
      [WAIT] 464.00 ops/second
      [ABS] 29586.28 ops/second
       
      2.4.0-beta2-9-gf8683a6/lcb 2.9.2: $ python bench.py -U couchbase:/
      /centos7lx-55a.home.ingenthron.org/?compression=off\&enable_tracing=false -p be
      nchbench -t 64 -N 10 -D 60 
      Total run took an absolute time of 60.00 seconds
      Did a total of 5490230 operations
      Total wait time of 3810.18 seconds
      [WAIT] 1440.94 ops/second
      [ABS] 91503.77 ops/second
       
       
      2.4.0-beta2-9-gf8683a6+PYCBC_DISABLE_TRACING=TRUE/lcb 2.9.2: 
      $ python bench.py -U couchbase:/
      /centos7lx-55a.home.ingenthron.org/?compression=off -p benchbench -t 64 -N 10 -
      D 60 
      Total run took an absolute time of 60.00 seconds
      Did a total of 3399530 operations
      Total wait time of 3801.27 seconds
      [WAIT] 894.31 ops/second
      [ABS] 56658.32 ops/second
       
       
       
      2.4.0-beta2-9-gf8683a6+PYCBC_DISABLE_TRACING=TRUE/lcb 2.9.2:
      $ python bench.py -U couchbase:/
      /centos7lx-55a.home.ingenthron.org/?compression=off\&enable_tracing=false -p be
      nchbench -t 64 -N 10 -D 60 
      Total run took an absolute time of 60.00 seconds
      Did a total of 5464230 operations
      Total wait time of 3808.89 seconds
      [WAIT] 1434.60 ops/second
      [ABS] 91070.30 ops/second
       
       
      2.4.0-beta2-9-gf8683a6+PYCBC_DISABLE_TRACING=TRUE/lcb 2.9.2:
      $ python bench.py -U couchbase:/
      /centos7lx-55a.home.ingenthron.org/?enable_tracing=false -p benchbench -t 64 -N
       10 -D 60 
      Total run took an absolute time of 60.00 seconds
      Did a total of 5268310 operations
      Total wait time of 3809.77 seconds
      [WAIT] 1382.84 ops/second
      [ABS] 87805.05 ops/second
       
       
      2.3.4/2.8.4: 
      $ python bench.py -U couchbase://centos7lx-55
      a.home.ingenthron.org/ -p benchbench -t 64 -N 10 -D 60 
      Total run took an absolute time of 60.00 seconds
      Did a total of 5206430 operations
      Total wait time of 3807.84 seconds
      [WAIT] 1367.29 ops/second
      [ABS] 86773.52 ops/second
       
      2nd run:
      $ python bench.py -U couchbase://centos7lx-55
      a.home.ingenthron.org/ -p benchbench -t 64 -N 10 -D 60 
      Total run took an absolute time of 60.00 seconds
      Did a total of 4470660 operations
      Total wait time of 3807.64 seconds
      [WAIT] 1174.13 ops/second
      [ABS] 74510.35 ops/second
       
      without compression for kicks:
      $ python bench.py -U couchbase://centos7lx-55
      a.home.ingenthron.org/?compression=off -p benchbench -t 64 -N 10 -D 60 
      Total run took an absolute time of 60.00 seconds
      Did a total of 5064410 operations
      Total wait time of 3808.28 seconds
      [WAIT] 1329.84 ops/second
      [ABS] 84405.39 ops/second
      
      

      Attachments

        1. 2.4.0-3-ga281b40 4 thread 2 run comparison off then on.trace.zip
          81.70 MB
        2. bench.py
          4 kB
        3. image-2018-07-20-15-42-15-083.png
          image-2018-07-20-15-42-15-083.png
          135 kB
        4. image-2018-08-08-15-03-10-903.png
          image-2018-08-08-15-03-10-903.png
          211 kB
        5. image-2018-08-08-15-04-05-986.png
          image-2018-08-08-15-04-05-986.png
          316 kB
        6. image-2018-08-08-15-25-13-419.png
          image-2018-08-08-15-25-13-419.png
          107 kB
        7. image-2018-08-08-15-25-13-419.png
          image-2018-08-08-15-25-13-419.png
          107 kB
        8. image-2018-08-08-15-28-52-112.png
          image-2018-08-08-15-28-52-112.png
          355 kB
        9. image-2018-08-08-15-48-39-872.png
          image-2018-08-08-15-48-39-872.png
          185 kB
        10. image-2018-08-08-15-49-28-796.png
          image-2018-08-08-15-49-28-796.png
          356 kB
        11. image-2018-08-08-15-49-36-361.png
          image-2018-08-08-15-49-36-361.png
          356 kB
        12. image-2018-08-08-15-49-55-570.png
          image-2018-08-08-15-49-55-570.png
          263 kB
        13. image-2018-08-13-18-23-43-542.png
          image-2018-08-13-18-23-43-542.png
          526 kB
        14. image-2018-08-13-18-25-58-279.png
          image-2018-08-13-18-25-58-279.png
          165 kB
        15. image-2018-08-13-18-40-38-526.png
          image-2018-08-13-18-40-38-526.png
          438 kB
        16. image-2018-08-13-18-44-19-367.png
          image-2018-08-13-18-44-19-367.png
          155 kB
        17. image-2018-08-13-19-30-02-926.png
          image-2018-08-13-19-30-02-926.png
          505 kB
        18. image-2018-08-14-12-53-01-033.png
          image-2018-08-14-12-53-01-033.png
          1.04 MB
        19. image-2018-08-14-12-54-17-591.png
          image-2018-08-14-12-54-17-591.png
          1.04 MB
        20. image-2018-08-14-13-06-32-768.png
          image-2018-08-14-13-06-32-768.png
          1.01 MB
        21. image-2018-08-14-17-32-00-782.png
          image-2018-08-14-17-32-00-782.png
          1.08 MB
        22. Picture1.png
          Picture1.png
          148 kB
        23. Picture12.png
          Picture12.png
          234 kB
        24. Picture3.png
          Picture3.png
          139 kB

        Issue Links

          No reviews matched the request. Check your Options in the drop-down menu of this sections header.

          Activity

            Ellis.Breen Ellis Breen added a comment -

            No major advance in performance since this - still 75% with bench.py:

            ./txbench_64_priorityqueue_unshared_tracing_pq3_lcb_debug_tracing_on_mk3.txt
            :0: UserWarning: You do not have a working installation of the service_identity module: 'No module named 'service_identity''. Please install it from <https://pypi.python.org/pypi/service_identity> and make sure all of its dependencies are satisfied. Without the service_identity module, Twisted can perform only rudimentary TLS client hostname verification. Many valid certificate/hostname mappings may be rejected.
            Total run took an absolute time of 60.02 seconds
            Did a total of 2264200 operations
            [ABS] 37722.02 ops/second
            ./bench_priorityqueue_unshared_tracing_pq3_lcb_nodebug_tracing_off_mk3.txt
            Exception in thread Thread-28:
            Traceback (most recent call last):
            File "/usr/local/Cellar/python3/3.6.2/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py", line 916, in _bootstrap_inner
            self.run()
            File "examples/bench.py", line 92, in run
            rv = cb.upsert_multi(self.kv, format=FMT_BYTES)
            File "/Users/ellis_breen/root/virtualenvs/3.6/default/lib/python3.6/site-packages/couchbase-2.4.0.dev5+g816b433-py3.6-macosx-10.12-x86_64.egg/couchbase/bucket.py", line 1162, in upsert_multi
            replicate_to=replicate_to)
            couchbase.exceptions._TimeoutError_0x17 (generated, catch TimeoutError): <Key='KKKKKKKKKKKK0', RC=0x17[Client-Side timeout exceeded for operation. Inspect network conditions or increase the timeout], Operational Error, Results=100, C Source=(src/multiresult.c,316), Tracing Output={"KKKKKKKKKKKK0": null, "KKKKKKKKKKKK1": null, "KKKKKKKKKKKK2": null, "KKKKKKKKKKKK3": null, "KKKKKKKKKKKK4": null, "KKKKKKKKKKKK5": null, "KKKKKKKKKKKK6": null, "KKKKKKKKKKKK7": null, "KKKKKKKKKKKK8": null, "KKKKKKKKKKKK9": null, "KKKKKKKKKKKK10": null, "KKKKKKKKKKKK11": null, "KKKKKKKKKKKK12": null, "KKKKKKKKKKKK13": null, "KKKKKKKKKKKK14": null, "KKKKKKKKKKKK15": null, "KKKKKKKKKKKK16": null, "KKKKKKKKKKKK17": null, "KKKKKKKKKKKK18": null, "KKKKKKKKKKKK19": null, "KKKKKKKKKKKK20": null, "KKKKKKKKKKKK21": null, "KKKKKKKKKKKK22": null, "KKKKKKKKKKKK23": null, "KKKKKKKKKKKK24": null, "KKKKKKKKKKKK25": null, "KKKKKKKKKKKK26": null, "KKKKKKKKKKKK27": null, "KKKKKKKKKKKK28": null, "KKKKKKKKKKKK29": null, "KKKKKKKKKKKK30": null, "KKKKKKKKKKKK31": null, "KKKKKKKKKKKK32": null, "KKKKKKKKKKKK33": null, "KKKKKKKKKKKK34": null, "KKKKKKKKKKKK35": null, "KKKKKKKKKKKK36": null, "KKKKKKKKKKKK37": null, "KKKKKKKKKKKK38": null, "KKKKKKKKKKKK39": null, "KKKKKKKKKKKK40": null, "KKKKKKKKKKKK41": null, "KKKKKKKKKKKK42": null, "KKKKKKKKKKKK43": null, "KKKKKKKKKKKK44": null, "KKKKKKKKKKKK45": null, "KKKKKKKKKKKK46": null, "KKKKKKKKKKKK47": null, "KKKKKKKKKKKK48": null, "KKKKKKKKKKKK49": null, "KKKKKKKKKKKK50": null, "KKKKKKKKKKKK51": null, "KKKKKKKKKKKK52": null, "KKKKKKKKKKKK53": null, "KKKKKKKKKKKK54": null, "KKKKKKKKKKKK55": null, "KKKKKKKKKKKK56": null, "KKKKKKKKKKKK57": null, "KKKKKKKKKKKK58": null, "KKKKKKKKKKKK59": null, "KKKKKKKKKKKK60": null, "KKKKKKKKKKKK61": null, "KKKKKKKKKKKK62": null, "KKKKKKKKKKKK63": null, "KKKKKKKKKKKK64": null, "KKKKKKKKKKKK65": null, "KKKKKKKKKKKK66": null, "KKKKKKKKKKKK67": null, "KKKKKKKKKKKK68": null, "KKKKKKKKKKKK69": null, "KKKKKKKKKKKK70": null, "KKKKKKKKKKKK71": null, "KKKKKKKKKKKK72": null, "KKKKKKKKKKKK73": null, "KKKKKKKKKKKK74": null, "KKKKKKKKKKKK75": null, "KKKKKKKKKKKK76": null, "KKKKKKKKKKKK77": null, "KKKKKKKKKKKK78": null, "KKKKKKKKKKKK79": null, "KKKKKKKKKKKK80": null, "KKKKKKKKKKKK81": null, "KKKKKKKKKKKK82": null, "KKKKKKKKKKKK83": null, "KKKKKKKKKKKK84": null, "KKKKKKKKKKKK85": null, "KKKKKKKKKKKK86": null, "KKKKKKKKKKKK87": null, "KKKKKKKKKKKK88": null, "KKKKKKKKKKKK89": null, "KKKKKKKKKKKK90": null, "KKKKKKKKKKKK91": null, "KKKKKKKKKKKK92": null, "KKKKKKKKKKKK93": null, "KKKKKKKKKKKK94": null, "KKKKKKKKKKKK95": null, "KKKKKKKKKKKK96": null, "KKKKKKKKKKKK97": null, "KKKKKKKKKKKK98": null, "KKKKKKKKKKKK99": null}>
             
            Total run took an absolute time of 60.00 seconds
            Did a total of 2546500 operations
            Total wait time of 2832.93 seconds
            [WAIT] 898.89 ops/second
            [ABS] 42440.83 ops/second
            ./bench_priorityqueue_unshared_tracing_pq3_lcb_nodebug_tracing_on_mk3.txt
            Total run took an absolute time of 60.00 seconds
            Did a total of 1917200 operations
            Total wait time of 3119.02 seconds
            [WAIT] 614.68 ops/second
            [ABS] 31952.94 ops/second
            ./bench_32_priorityqueue_unshared_tracing_pq3_lcb_nodebug_tracing_off_mk3.txt
            Total run took an absolute time of 60.00 seconds
            Did a total of 2820400 operations
            Total wait time of 1860.29 seconds
            [WAIT] 1516.11 ops/second
            [ABS] 47005.51 ops/second
            ./txbench_64_priorityqueue_unshared_tracing_pq3_lcb_debug_py_nodebug_tracing_on_mk8.txt
            :0: UserWarning: You do not have a working installation of the service_identity module: 'No module named 'service_identity''. Please install it from <https://pypi.python.org/pypi/service_identity> and make sure all of its dependencies are satisfied. Without the service_identity module, Twisted can perform only rudimentary TLS client hostname verification. Many valid certificate/hostname mappings may be rejected.
            Total run took an absolute time of 60.05 seconds
            Did a total of 2102200 operations
            [ABS] 35009.42 ops/second
            ./bench_32_priorityqueue_unshared_tracing_pq3_lcb_debug_tracing_on_mk6.txt
            Total run took an absolute time of 60.00 seconds
            Did a total of 1767600 operations
            Total wait time of 1808.60 seconds
            [WAIT] 977.33 ops/second
            [ABS] 29459.54 ops/second
            ./bench_32_priorityqueue_unshared_tracing_pq3_lcb_debug_tracing_on_mk5.txt
            Total run took an absolute time of 60.00 seconds
            Did a total of 1625200 operations
            Total wait time of 3775.83 seconds
            [WAIT] 430.42 ops/second
            [ABS] 27084.82 ops/second
            ./bench_32_priorityqueue_unshared_tracing_pq3_lcb_debug_tracing_on_mk4.txt
            Total run took an absolute time of 60.01 seconds
            Did a total of 1758600 operations
            Total wait time of 1906.28 seconds
            [WAIT] 922.53 ops/second
            [ABS] 29307.53 ops/second
            ./bench_32_priorityqueue_unshared_tracing_pq3_lcb_debug_tracing_off.txt
            Total run took an absolute time of 60.00 seconds
            Did a total of 2852900 operations
            Total wait time of 1902.15 seconds
            [WAIT] 1499.83 ops/second
            [ABS] 47547.47 ops/second
            ./bench_64_priorityqueue_unshared_tracing_pq3_lcb_debug_tracing_on_mk6.txt
            Total run took an absolute time of 60.00 seconds
            Did a total of 1847300 operations
            Total wait time of 3203.91 seconds
            [WAIT] 576.58 ops/second
            [ABS] 30786.16 ops/second
            ./txbench_64_priorityqueue_unshared_tracing_pq3_lcb_debug_py_nodebug_tracing_on_mk4.txt
            :0: UserWarning: You do not have a working installation of the service_identity module: 'No module named 'service_identity''. Please install it from <https://pypi.python.org/pypi/service_identity> and make sure all of its dependencies are satisfied. Without the service_identity module, Twisted can perform only rudimentary TLS client hostname verification. Many valid certificate/hostname mappings may be rejected.
            Total run took an absolute time of 60.03 seconds
            Did a total of 2152800 operations
            [ABS] 35861.90 ops/second
            ./bench_64_priorityqueue_unshared_tracing_pq3_lcb_debug_tracing_off.txt
            Total run took an absolute time of 60.00 seconds
            Did a total of 2654200 operations
            Total wait time of 3767.25 seconds
            [WAIT] 704.55 ops/second
            [ABS] 44234.06 ops/second
            ./txbench_64_priorityqueue_unshared_tracing_pq3_lcb_debug_py_nodebug_tracing_on_mk5.txt
            :0: UserWarning: You do not have a working installation of the service_identity module: 'No module named 'service_identity''. Please install it from <https://pypi.python.org/pypi/service_identity> and make sure all of its dependencies are satisfied. Without the service_identity module, Twisted can perform only rudimentary TLS client hostname verification. Many valid certificate/hostname mappings may be rejected.
            Total run took an absolute time of 60.05 seconds
            Did a total of 2008300 operations
            [ABS] 33445.07 ops/second
            ./txbench_64_priorityqueue_unshared_tracing_pq3_lcb_debug_py_nodebug_tracing_on_mk7.txt
            :0: UserWarning: You do not have a working installation of the service_identity module: 'No module named 'service_identity''. Please install it from <https://pypi.python.org/pypi/service_identity> and make sure all of its dependencies are satisfied. Without the service_identity module, Twisted can perform only rudimentary TLS client hostname verification. Many valid certificate/hostname mappings may be rejected.
            Total run took an absolute time of 60.04 seconds
            Did a total of 2176700 operations
            [ABS] 36254.19 ops/second
            ./bench_32_priorityqueue_unshared_tracing_pq3_lcb_nodebug_tracing_on_mk3.txt
            Total run took an absolute time of 60.00 seconds
            Did a total of 2611400 operations
            Total wait time of 1904.79 seconds
            [WAIT] 1370.96 ops/second
            [ABS] 43520.78 ops/second
            ./txbench_64_priorityqueue_unshared_tracing_pq3_lcb_debug_py_nodebug_tracing_on_mk6.txt
            :0: UserWarning: You do not have a working installation of the service_identity module: 'No module named 'service_identity''. Please install it from <https://pypi.python.org/pypi/service_identity> and make sure all of its dependencies are satisfied. Without the service_identity module, Twisted can perform only rudimentary TLS client hostname verification. Many valid certificate/hostname mappings may be rejected.
            Total run took an absolute time of 60.04 seconds
            Did a total of 2355800 operations
            [ABS] 39237.71 ops/second
            ./bench_32_priorityqueue_unshared_tracing_pq3_lcb_debug_tracing_on_mk5_nogilunlock.txt
            Total run took an absolute time of 60.00 seconds
            Did a total of 1688000 operations
            Total wait time of 2690.51 seconds
            [WAIT] 627.39 ops/second
            [ABS] 28131.76 ops/second
            

            Ellis.Breen Ellis Breen added a comment - No major advance in performance since this - still 75% with bench.py: ./txbench_64_priorityqueue_unshared_tracing_pq3_lcb_debug_tracing_on_mk3.txt : 0 : UserWarning: You do not have a working installation of the service_identity module: 'No module named ' service_identity '' . Please install it from <https: //pypi.python.org/pypi/service_identity> and make sure all of its dependencies are satisfied. Without the service_identity module, Twisted can perform only rudimentary TLS client hostname verification. Many valid certificate/hostname mappings may be rejected. Total run took an absolute time of 60.02 seconds Did a total of 2264200 operations [ABS] 37722.02 ops/second ./bench_priorityqueue_unshared_tracing_pq3_lcb_nodebug_tracing_off_mk3.txt Exception in thread Thread- 28 : Traceback (most recent call last): File "/usr/local/Cellar/python3/3.6.2/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py" , line 916 , in _bootstrap_inner self.run() File "examples/bench.py" , line 92 , in run rv = cb.upsert_multi(self.kv, format=FMT_BYTES) File "/Users/ellis_breen/root/virtualenvs/3.6/default/lib/python3.6/site-packages/couchbase-2.4.0.dev5+g816b433-py3.6-macosx-10.12-x86_64.egg/couchbase/bucket.py" , line 1162 , in upsert_multi replicate_to=replicate_to) couchbase.exceptions._TimeoutError_0x17 (generated, catch TimeoutError): <Key= 'KKKKKKKKKKKK0' , RC= 0x17 [Client-Side timeout exceeded for operation. Inspect network conditions or increase the timeout], Operational Error, Results= 100 , C Source=(src/multiresult.c, 316 ), Tracing Output={ "KKKKKKKKKKKK0" : null , "KKKKKKKKKKKK1" : null , "KKKKKKKKKKKK2" : null , "KKKKKKKKKKKK3" : null , "KKKKKKKKKKKK4" : null , "KKKKKKKKKKKK5" : null , "KKKKKKKKKKKK6" : null , "KKKKKKKKKKKK7" : null , "KKKKKKKKKKKK8" : null , "KKKKKKKKKKKK9" : null , "KKKKKKKKKKKK10" : null , "KKKKKKKKKKKK11" : null , "KKKKKKKKKKKK12" : null , "KKKKKKKKKKKK13" : null , "KKKKKKKKKKKK14" : null , "KKKKKKKKKKKK15" : null , "KKKKKKKKKKKK16" : null , "KKKKKKKKKKKK17" : null , "KKKKKKKKKKKK18" : null , "KKKKKKKKKKKK19" : null , "KKKKKKKKKKKK20" : null , "KKKKKKKKKKKK21" : null , "KKKKKKKKKKKK22" : null , "KKKKKKKKKKKK23" : null , "KKKKKKKKKKKK24" : null , "KKKKKKKKKKKK25" : null , "KKKKKKKKKKKK26" : null , "KKKKKKKKKKKK27" : null , "KKKKKKKKKKKK28" : null , "KKKKKKKKKKKK29" : null , "KKKKKKKKKKKK30" : null , "KKKKKKKKKKKK31" : null , "KKKKKKKKKKKK32" : null , "KKKKKKKKKKKK33" : null , "KKKKKKKKKKKK34" : null , "KKKKKKKKKKKK35" : null , "KKKKKKKKKKKK36" : null , "KKKKKKKKKKKK37" : null , "KKKKKKKKKKKK38" : null , "KKKKKKKKKKKK39" : null , "KKKKKKKKKKKK40" : null , "KKKKKKKKKKKK41" : null , "KKKKKKKKKKKK42" : null , "KKKKKKKKKKKK43" : null , "KKKKKKKKKKKK44" : null , "KKKKKKKKKKKK45" : null , "KKKKKKKKKKKK46" : null , "KKKKKKKKKKKK47" : null , "KKKKKKKKKKKK48" : null , "KKKKKKKKKKKK49" : null , "KKKKKKKKKKKK50" : null , "KKKKKKKKKKKK51" : null , "KKKKKKKKKKKK52" : null , "KKKKKKKKKKKK53" : null , "KKKKKKKKKKKK54" : null , "KKKKKKKKKKKK55" : null , "KKKKKKKKKKKK56" : null , "KKKKKKKKKKKK57" : null , "KKKKKKKKKKKK58" : null , "KKKKKKKKKKKK59" : null , "KKKKKKKKKKKK60" : null , "KKKKKKKKKKKK61" : null , "KKKKKKKKKKKK62" : null , "KKKKKKKKKKKK63" : null , "KKKKKKKKKKKK64" : null , "KKKKKKKKKKKK65" : null , "KKKKKKKKKKKK66" : null , "KKKKKKKKKKKK67" : null , "KKKKKKKKKKKK68" : null , "KKKKKKKKKKKK69" : null , "KKKKKKKKKKKK70" : null , "KKKKKKKKKKKK71" : null , "KKKKKKKKKKKK72" : null , "KKKKKKKKKKKK73" : null , "KKKKKKKKKKKK74" : null , "KKKKKKKKKKKK75" : null , "KKKKKKKKKKKK76" : null , "KKKKKKKKKKKK77" : null , "KKKKKKKKKKKK78" : null , "KKKKKKKKKKKK79" : null , "KKKKKKKKKKKK80" : null , "KKKKKKKKKKKK81" : null , "KKKKKKKKKKKK82" : null , "KKKKKKKKKKKK83" : null , "KKKKKKKKKKKK84" : null , "KKKKKKKKKKKK85" : null , "KKKKKKKKKKKK86" : null , "KKKKKKKKKKKK87" : null , "KKKKKKKKKKKK88" : null , "KKKKKKKKKKKK89" : null , "KKKKKKKKKKKK90" : null , "KKKKKKKKKKKK91" : null , "KKKKKKKKKKKK92" : null , "KKKKKKKKKKKK93" : null , "KKKKKKKKKKKK94" : null , "KKKKKKKKKKKK95" : null , "KKKKKKKKKKKK96" : null , "KKKKKKKKKKKK97" : null , "KKKKKKKKKKKK98" : null , "KKKKKKKKKKKK99" : null }>   Total run took an absolute time of 60.00 seconds Did a total of 2546500 operations Total wait time of 2832.93 seconds [WAIT] 898.89 ops/second [ABS] 42440.83 ops/second ./bench_priorityqueue_unshared_tracing_pq3_lcb_nodebug_tracing_on_mk3.txt Total run took an absolute time of 60.00 seconds Did a total of 1917200 operations Total wait time of 3119.02 seconds [WAIT] 614.68 ops/second [ABS] 31952.94 ops/second ./bench_32_priorityqueue_unshared_tracing_pq3_lcb_nodebug_tracing_off_mk3.txt Total run took an absolute time of 60.00 seconds Did a total of 2820400 operations Total wait time of 1860.29 seconds [WAIT] 1516.11 ops/second [ABS] 47005.51 ops/second ./txbench_64_priorityqueue_unshared_tracing_pq3_lcb_debug_py_nodebug_tracing_on_mk8.txt : 0 : UserWarning: You do not have a working installation of the service_identity module: 'No module named ' service_identity '' . Please install it from <https: //pypi.python.org/pypi/service_identity> and make sure all of its dependencies are satisfied. Without the service_identity module, Twisted can perform only rudimentary TLS client hostname verification. Many valid certificate/hostname mappings may be rejected. Total run took an absolute time of 60.05 seconds Did a total of 2102200 operations [ABS] 35009.42 ops/second ./bench_32_priorityqueue_unshared_tracing_pq3_lcb_debug_tracing_on_mk6.txt Total run took an absolute time of 60.00 seconds Did a total of 1767600 operations Total wait time of 1808.60 seconds [WAIT] 977.33 ops/second [ABS] 29459.54 ops/second ./bench_32_priorityqueue_unshared_tracing_pq3_lcb_debug_tracing_on_mk5.txt Total run took an absolute time of 60.00 seconds Did a total of 1625200 operations Total wait time of 3775.83 seconds [WAIT] 430.42 ops/second [ABS] 27084.82 ops/second ./bench_32_priorityqueue_unshared_tracing_pq3_lcb_debug_tracing_on_mk4.txt Total run took an absolute time of 60.01 seconds Did a total of 1758600 operations Total wait time of 1906.28 seconds [WAIT] 922.53 ops/second [ABS] 29307.53 ops/second ./bench_32_priorityqueue_unshared_tracing_pq3_lcb_debug_tracing_off.txt Total run took an absolute time of 60.00 seconds Did a total of 2852900 operations Total wait time of 1902.15 seconds [WAIT] 1499.83 ops/second [ABS] 47547.47 ops/second ./bench_64_priorityqueue_unshared_tracing_pq3_lcb_debug_tracing_on_mk6.txt Total run took an absolute time of 60.00 seconds Did a total of 1847300 operations Total wait time of 3203.91 seconds [WAIT] 576.58 ops/second [ABS] 30786.16 ops/second ./txbench_64_priorityqueue_unshared_tracing_pq3_lcb_debug_py_nodebug_tracing_on_mk4.txt : 0 : UserWarning: You do not have a working installation of the service_identity module: 'No module named ' service_identity '' . Please install it from <https: //pypi.python.org/pypi/service_identity> and make sure all of its dependencies are satisfied. Without the service_identity module, Twisted can perform only rudimentary TLS client hostname verification. Many valid certificate/hostname mappings may be rejected. Total run took an absolute time of 60.03 seconds Did a total of 2152800 operations [ABS] 35861.90 ops/second ./bench_64_priorityqueue_unshared_tracing_pq3_lcb_debug_tracing_off.txt Total run took an absolute time of 60.00 seconds Did a total of 2654200 operations Total wait time of 3767.25 seconds [WAIT] 704.55 ops/second [ABS] 44234.06 ops/second ./txbench_64_priorityqueue_unshared_tracing_pq3_lcb_debug_py_nodebug_tracing_on_mk5.txt : 0 : UserWarning: You do not have a working installation of the service_identity module: 'No module named ' service_identity '' . Please install it from <https: //pypi.python.org/pypi/service_identity> and make sure all of its dependencies are satisfied. Without the service_identity module, Twisted can perform only rudimentary TLS client hostname verification. Many valid certificate/hostname mappings may be rejected. Total run took an absolute time of 60.05 seconds Did a total of 2008300 operations [ABS] 33445.07 ops/second ./txbench_64_priorityqueue_unshared_tracing_pq3_lcb_debug_py_nodebug_tracing_on_mk7.txt : 0 : UserWarning: You do not have a working installation of the service_identity module: 'No module named ' service_identity '' . Please install it from <https: //pypi.python.org/pypi/service_identity> and make sure all of its dependencies are satisfied. Without the service_identity module, Twisted can perform only rudimentary TLS client hostname verification. Many valid certificate/hostname mappings may be rejected. Total run took an absolute time of 60.04 seconds Did a total of 2176700 operations [ABS] 36254.19 ops/second ./bench_32_priorityqueue_unshared_tracing_pq3_lcb_nodebug_tracing_on_mk3.txt Total run took an absolute time of 60.00 seconds Did a total of 2611400 operations Total wait time of 1904.79 seconds [WAIT] 1370.96 ops/second [ABS] 43520.78 ops/second ./txbench_64_priorityqueue_unshared_tracing_pq3_lcb_debug_py_nodebug_tracing_on_mk6.txt : 0 : UserWarning: You do not have a working installation of the service_identity module: 'No module named ' service_identity '' . Please install it from <https: //pypi.python.org/pypi/service_identity> and make sure all of its dependencies are satisfied. Without the service_identity module, Twisted can perform only rudimentary TLS client hostname verification. Many valid certificate/hostname mappings may be rejected. Total run took an absolute time of 60.04 seconds Did a total of 2355800 operations [ABS] 39237.71 ops/second ./bench_32_priorityqueue_unshared_tracing_pq3_lcb_debug_tracing_on_mk5_nogilunlock.txt Total run took an absolute time of 60.00 seconds Did a total of 1688000 operations Total wait time of 2690.51 seconds [WAIT] 627.39 ops/second [ABS] 28131.76 ops/second
            Ellis.Breen Ellis Breen added a comment -

            With bench.py, a lot of time is spent waiting on the GIL. There appears to be plenty of spare CPU but this is causing lots of contention. This appears to be happening in the callbacks, e.g. get_common_objects, and is currently necessary because we are writing to the mres dictionary. More time is spent with the GIL locked during get_common_objects, because it is initiating new contexts. I will see if I can reduce the time spent in this critical section tomorrow.

            Ellis.Breen Ellis Breen added a comment - With bench.py, a lot of time is spent waiting on the GIL. There appears to be plenty of spare CPU but this is causing lots of contention. This appears to be happening in the callbacks, e.g. get_common_objects, and is currently necessary because we are writing to the mres dictionary. More time is spent with the GIL locked during get_common_objects, because it is initiating new contexts. I will see if I can reduce the time spent in this critical section tomorrow.

            If the profile or another test proves it's contention in the GIL (and by the way, one thing I disabled/skipped in my modified bench.py was the GIL unlocking) then I'd not worry about it. One way to test this would be to run 32 processes compared to concurrency 32. If 32 processes with tracing on is similar to 32 threads with tracing off, then we're probably done here, but could use a better test going into the future.

            Another thought occurs (which we may want Michael Goldsmith to think about), maybe we need more granular tracing disabling to reduce overhead in a future sdk-rfc?

            ingenthr Matt Ingenthron added a comment - If the profile or another test proves it's contention in the GIL (and by the way, one thing I disabled/skipped in my modified bench.py was the GIL unlocking) then I'd not worry about it. One way to test this would be to run 32 processes compared to concurrency 32. If 32 processes with tracing on is similar to 32 threads with tracing off, then we're probably done here, but could use a better test going into the future. Another thought occurs (which we may want Michael Goldsmith to think about), maybe we need more granular tracing disabling to reduce overhead in a future sdk-rfc?

            Matt Ingenthron - yes, I think that's a good idea. Independent per-service tracing switches would be good. You may care about KV but not the others.

            I've added it to a RTO RFC enhancement notes.

            mike.goldsmith Michael Goldsmith added a comment - Matt Ingenthron - yes, I think that's a good idea. Independent per-service tracing switches would be good. You may care about KV but not the others. I've added it to a RTO RFC enhancement notes.
            Ellis.Breen Ellis Breen added a comment -

            GIL unlocking only works for single-threaded operation - if you try it in multithreaded mode you will (quite rightly) get assertions thrown about multiple threads being run without the GIL on. Having revisited the tests looks like we're in the ballpark of your suggested performance targets with tracing on (hitting 90% of performance with 32 threads, just missing 80% with 64 threads)

            Ellis.Breen Ellis Breen added a comment - GIL unlocking only works for single-threaded operation - if you try it in multithreaded mode you will (quite rightly) get assertions thrown about multiple threads being run without the GIL on. Having revisited the tests looks like we're in the ballpark of your suggested performance targets with tracing on (hitting 90% of performance with 32 threads, just missing 80% with 64 threads)

            People

              Ellis.Breen Ellis Breen
              ingenthr Matt Ingenthron
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Gerrit Reviews

                  There are no open Gerrit changes

                  PagerDuty