Uploaded image for project: 'Qpid Proton'
  1. Qpid Proton
  2. PROTON-1764

Slow performance seen when running Go client

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Duplicate
    • Affects Version/s: proton-c-0.18.1
    • Fix Version/s: None
    • Component/s: go-binding
    • Labels:

      Description

      Slower than expected message deliver rate seen while running simple benchmarking test.  Setup:

        Client(Go) Sender -> QPID Router -> Client Receiver(Go)

      Profiling of reveals that a large percentage of time is spent in wrapper call from Go to c.

      Not sure if the call to C from Go is the issue.

       

      Here's the pointer for sender/receiver (both uses qpid go-binding).

      Sender (with '-limit' option, it sends AMQP messages in 10sec for benchmarking):
      https://github.com/redhat-nfvpe/service-assurance-poc/tree/master/tools/sa-bench

      Receiver (based on electron sample):
      http://kagaribi.s1061123.net/receive.go

      Here are the results:

      [root@nfvha-comp-01 sa-bench]# ./sa-bench -mode limit amqp://127.0.0.1:5672/collectd/telemetry
      sending AMQP in 10 seconds...Done!
      Total: 171908 sent (duration:10.000103521s, mesg/sec: 17190.62204096157)
      
      [root@nfvha-comp-01 electron_sample]# ./receive -prefetch 12 amqp://127.0.0.1:5672/collectd/telemetry
      Listening on 1 connections
      ^C2018/02/15 01:44:51 Total: 171908 received.
      2018/02/15 01:44:51 captured interrupt, stopping profiler and exiting...
      

      Both program can collect profile data using '-pprofile' option as following:

      [root@nfvha-comp-01 sa-bench]# ./sa-bench -mode limit -pprofile profile.out amqp://127.0.0.1:5672/collectd/telemetry
      sending AMQP in 10 seconds...Done!
      Total: 189305 sent (duration:10.000111611s, mesg/sec: 18930.2887171546)
      [root@nfvha-comp-01 sa-bench]# go tool pprof sa-bench profile.out 
      File: sa-bench
      Build ID: 7ffec7b98a532892d7b9932b70b7451866cd4e5e
      Type: cpu
      Time: Feb 15, 2018 at 1:49am (EST)
      Duration: 10.11s, Total samples = 15.75s (155.79%)
      Entering interactive mode (type "help" for commands, "o" for options)
      (pprof) top5
      Showing nodes accounting for 9990ms, 63.43% of 15750ms total
      Dropped 200 nodes (cum <= 78.75ms)
      Showing top 5 nodes out of 144
            flat  flat%   sum%        cum   cum%
          6750ms 42.86% 42.86%     7080ms 44.95%  runtime.cgocall /usr/local/go/src/runtime/cgocall.go
          1570ms  9.97% 52.83%     1590ms 10.10%  syscall.Syscall /usr/local/go/src/syscall/asm_linux_amd64.s
           800ms  5.08% 57.90%      800ms  5.08%  runtime.futex /usr/local/go/src/runtime/sys_linux_amd64.s
           440ms  2.79% 60.70%      770ms  4.89%  runtime.runqgrab /usr/local/go/src/runtime/proc.go
           430ms  2.73% 63.43%     1070ms  6.79%  runtime.selectgo /usr/local/go/src/runtime/select.go
      
      [root@nfvha-comp-01 electron_sample]# ./receive -prefetch 12 -pprofile profile.out amqp://127.0.0.1:5672/collectd/telemetry
      Listening on 1 connections
      ^C2018/02/15 01:49:25 Total: 181422 received.
      2018/02/15 01:49:25 captured interrupt, stopping profiler and exiting...
      [root@nfvha-comp-01 electron_sample]# go tool pprof receive profile.out 
      File: receive
      Build ID: 66addd89d429ca678cbd6e336872bc604406f83e
      Type: cpu
      Time: Feb 15, 2018 at 1:49am (EST)
      Duration: 14.78s, Total samples = 16.60s (112.31%)
      Entering interactive mode (type "help" for commands, "o" for options)
      (pprof) top 5
      Showing nodes accounting for 10620ms, 63.98% of 16600ms total
      Dropped 160 nodes (cum <= 83ms)
      Showing top 5 nodes out of 124
            flat  flat%   sum%        cum   cum%
          5730ms 34.52% 34.52%     5960ms 35.90%  runtime.cgocall /usr/local/go/src/runtime/cgocall.go
          2190ms 13.19% 47.71%     2220ms 13.37%  syscall.Syscall /usr/local/go/src/syscall/asm_linux_amd64.s
          1070ms  6.45% 54.16%     1070ms  6.45%  runtime.epollwait /usr/local/go/src/runtime/sys_linux_amd64.s
           860ms  5.18% 59.34%     4430ms 26.69%  runtime.findrunnable /usr/local/go/src/runtime/proc.go
           770ms  4.64% 63.98%     1130ms  6.81%  runtime.runqgrab /usr/local/go/src/runtime/proc.go
      (pprof) 

       

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                aconway Alan Conway
                Reporter:
                atyronesmith Aaron Smith
              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: