Uploaded image for project: 'Couchbase Server'
  1. Couchbase Server
  2. MB-41899

cbexport ~50% performance degradation compared to earlier GA(mad-hatter) build

    XMLWordPrintable

Details

    • Bug
    • Status: Resolved
    • Major
    • Resolution: Won't Fix
    • 6.6.1
    • None
    • tools
    • Untriaged
    • 1
    • Unknown

    Description

       

      Attachments

        Issue Links

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

          Activity

            James Lee 

            7.0.0-3004 build throughput is 293  MB/sec . Not sure if above reasoning holds good in this case .

            http://perf.jenkins.couchbase.com/job/leto/15348/

             

             

            sharath.sulochana Sharath Sulochana (Inactive) added a comment - James Lee   7.0.0-3004 build throughput is 293  MB/sec . Not sure if above reasoning holds good in this case . http://perf.jenkins.couchbase.com/job/leto/15348/    
            james.lee James Lee added a comment - - edited

            Hi Sharath Sulochana,

            Thanks for running that build, that's very strange. I've re-bisected and I seem to be able to reliably attribute the increase in throughput to a commit from MB-41214 (obviously I'm not running in the same conditions as Leto, however, I'm trying my best to ensure "reliable" benchmark conditions). Looking at the code change from MH-CC for the lines/list exporters we see:

            $ git diff --stat mad-hatter..master jsondata/lines_exporter.go
            jsondata/lines_exporter.go | 8 +++-----
            1 file changed, 3 insertions(+), 5 deletions(-)
             
            $ git diff --stat mad-hatter..master jsondata/list_exporter.go
            jsondata/list_exporter.go | 18 +++++++++---------
            1 file changed, 9 insertions(+), 9 deletions(-)
             
            $ git diff --stat mad-hatter..master jsondata/sink.go
            jsondata/sink.go | 7 ++++---
            1 file changed, 4 insertions(+), 3 deletions(-)
            

            obviously this is a really minor change compared to the rest of the code base which is why I'm curious to wonder whether it's a change to a library that we depend on i.e json-iterator/gocbcore. I've spoken to the SDK team, and they don't recall having made any changes which would have notable effects on DCP throughput (there is the "chatty" buffer acknowledgement fix, however, it looks like we have a build indicating the throughput increase wasn't due to that change). Please could you set off a few additional runs for increasingly older builds to attempt to "smoke test" where we're initially seeing this increase in throughput.

            Thanks in advance,
            James

            EDIT: It looks like the buffer ack fix was introduced in gocbcore v9.0.4 (which is the version 6.6.0 is using), therefore, we can rule that out as a source for the increase in throughput.

            james.lee James Lee added a comment - - edited Hi Sharath Sulochana , Thanks for running that build, that's very strange. I've re-bisected and I seem to be able to reliably attribute the increase in throughput to a commit from MB-41214 (obviously I'm not running in the same conditions as Leto, however, I'm trying my best to ensure "reliable" benchmark conditions). Looking at the code change from MH-CC for the lines/list exporters we see: $ git diff --stat mad-hatter..master jsondata/lines_exporter.go jsondata/lines_exporter.go | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-)   $ git diff --stat mad-hatter..master jsondata/list_exporter.go jsondata/list_exporter.go | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-)   $ git diff --stat mad-hatter..master jsondata/sink.go jsondata/sink.go | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) obviously this is a really minor change compared to the rest of the code base which is why I'm curious to wonder whether it's a change to a library that we depend on i.e json-iterator/gocbcore. I've spoken to the SDK team, and they don't recall having made any changes which would have notable effects on DCP throughput (there is the "chatty" buffer acknowledgement fix, however, it looks like we have a build indicating the throughput increase wasn't due to that change). Please could you set off a few additional runs for increasingly older builds to attempt to "smoke test" where we're initially seeing this increase in throughput. Thanks in advance, James EDIT: It looks like the buffer ack fix was introduced in gocbcore v9.0.4 (which is the version 6.6.0 is using), therefore, we can rule that out as a source for the increase in throughput.

            Without CBPS-750 and CBPS-791, it's really hard to debug the issue. Every time we are force to reproduce the issue on out own hardware. Can we please get someone to look at this issues?

            pvarley Patrick Varley added a comment - Without CBPS-750 and CBPS-791, it's really hard to debug the issue. Every time we are force to reproduce the issue on out own hardware. Can we please get someone to look at this issues?

            Patrick Varley both CBPS-750 and CBPS-791 are fixed. If needed please rerun jenkins jobs (it should collect cbbackupmgr logs).

            sharath.sulochana Sharath Sulochana (Inactive) added a comment - Patrick Varley  both CBPS-750 and CBPS-791 are fixed. If needed please rerun jenkins jobs (it should collect cbbackupmgr logs).
            james.lee James Lee added a comment - - edited

            Hi Sharath Sulochana,

            I'm going to close this as a won't fix for now because the root cause of the drop in throughput has already been discussed in MB-38140 (in which we attribute the drop in throughput to the collections work). Note that prior to the release of 6.6.0 our master branch became our mad-hatter branch to pick up the S3 feature. So this drop in throughput is the same one discussed in MB-38140 (although the versions differ).

            I think the more interesting thing about this MB is the somewhat inexplicable increase in throughput from 6.6.0 to 7.0.0. As I showed in a previous comment, the code change for 'cbexport' is very minor. The starting point here, is checking that the output produced by each version is the same i.e. is the same job is being performed. For this I performed multiple exports using either version and compared the output; which both looked good. This means we're functionally performing the same job.

            The next thing to take into account is that although we've only had minor changes in cbexport, we've updated up dependencies a few times. I am able to reproduce this increase in throughput on my local machine and can attribute it to us having updated one of our dependencies ('gocbcore' ). Below is a small scale example of what I'm seeing, note that I'm reducing the amount of variables by using the same version of Go and Couchbase Server for each test case and I'm flushing the caches before each test.

            6.6.0 - Go 1.15 - CB Server 6.6.0   
            $ command time -v cbexport json -c 172.20.1.1 -u admin -p password -b default -f lines -o lines.json
            Json exported to `lines.json` successfully
            Documents exported: 10000000 Documents skipped: 0
                    Command being timed: "cbexport json -c 172.20.1.1 -u admin -p password -b default -f lines -o lines.json"
                    User time (seconds): 134.84
                    System time (seconds): 39.39
                    Percent of CPU this job got: 145%
                    Elapsed (wall clock) time (h:mm:ss or m:ss): 1:59.98
                    Average shared text size (kbytes): 0
                    Average unshared data size (kbytes): 0
                    Average stack size (kbytes): 0
                    Average total size (kbytes): 0
                    Maximum resident set size (kbytes): 167640
                    Average resident set size (kbytes): 0
                    Major (requiring I/O) page faults: 88
                    Minor (reclaiming a frame) page faults: 8342
                    Voluntary context switches: 7096904
                    Involuntary context switches: 24579
                    Swaps: 0
                    File system inputs: 23281
                    File system outputs: 1210944
                    Socket messages sent: 0
                    Socket messages received: 0
                    Signals delivered: 0
                    Page size (bytes): 4096
                    Exit status: 0
             
            7.0.0 - Go 1.15 - CB Server 6.6.0    
            $ command time -v cbexport json -c 172.20.1.1 -u admin -p password -b default -f lines -o lines.json
            JSON exported to `lines.json` successfully
            Documents exported: 10000000 Documents skipped: 0
                    Command being timed: "cbexport json -c 172.20.1.1 -u admin -p password -b default -f lines -o lines.json"
                    User time (seconds): 101.30
                    System time (seconds): 46.33
                    Percent of CPU this job got: 182%
                    Elapsed (wall clock) time (h:mm:ss or m:ss): 1:20.77
                    Average shared text size (kbytes): 0
                    Average unshared data size (kbytes): 0
                    Average stack size (kbytes): 0
                    Average total size (kbytes): 0
                    Maximum resident set size (kbytes): 175568
                    Average resident set size (kbytes): 0
                    Major (requiring I/O) page faults: 99
                    Minor (reclaiming a frame) page faults: 8940
                    Voluntary context switches: 4204728
                    Involuntary context switches: 33513
                    Swaps: 0
                    File system inputs: 26777
                    File system outputs: 1210944
                    Socket messages sent: 0
                    Socket messages received: 0
                    Signals delivered: 0
                    Page size (bytes): 4096
                    Exit status: 0                 
             
            6.6.0 - Go 1.15 - CB Server 6.6.0 (bumped gocbcore)
            $ command time -v cbexport json -c 172.20.1.1 -u admin -p password -b default -f lines -o lines.json
            Json exported to `lines.json` successfully
            Documents exported: 10000000 Documents skipped: 0
                    Command being timed: "cbexport json -c 172.20.1.1 -u admin -p password -b default -f lines -o lines.json"
                    User time (seconds): 106.07
                    System time (seconds): 47.43
                    Percent of CPU this job got: 187%
                    Elapsed (wall clock) time (h:mm:ss or m:ss): 1:21.77
                    Average shared text size (kbytes): 0
                    Average unshared data size (kbytes): 0
                    Average stack size (kbytes): 0
                    Average total size (kbytes): 0
                    Maximum resident set size (kbytes): 178300
                    Average resident set size (kbytes): 0
                    Major (requiring I/O) page faults: 92
                    Minor (reclaiming a frame) page faults: 8961
                    Voluntary context switches: 4310512
                    Involuntary context switches: 38417
                    Swaps: 0
                    File system inputs: 23473
                    File system outputs: 1210944
                    Socket messages sent: 0
                    Socket messages received: 0
                    Signals delivered: 0
                    Page size (bytes): 4096
                    Exit status: 0
            

            As we can see above, we see a similar increase in throughput for 6.6.0 when we bump the underlying 'gocbcore' library.

            TLDR; mad-hatter sees a similar increase in throughput if we bump the gocbcore version to the same that's used in master.

            james.lee James Lee added a comment - - edited Hi Sharath Sulochana , I'm going to close this as a won't fix for now because the root cause of the drop in throughput has already been discussed in MB-38140 (in which we attribute the drop in throughput to the collections work). Note that prior to the release of 6.6.0 our master branch became our mad-hatter branch to pick up the S3 feature. So this drop in throughput is the same one discussed in MB-38140 (although the versions differ). I think the more interesting thing about this MB is the somewhat inexplicable increase in throughput from 6.6.0 to 7.0.0. As I showed in a previous comment, the code change for ' cbexport ' is very minor. The starting point here, is checking that the output produced by each version is the same i.e. is the same job is being performed. For this I performed multiple exports using either version and compared the output; which both looked good. This means we're functionally performing the same job. The next thing to take into account is that although we've only had minor changes in cbexport, we've updated up dependencies a few times. I am able to reproduce this increase in throughput on my local machine and can attribute it to us having updated one of our dependencies (' gocbcore ' ). Below is a small scale example of what I'm seeing, note that I'm reducing the amount of variables by using the same version of Go and Couchbase Server for each test case and I'm flushing the caches before each test. 6.6.0 - Go 1.15 - CB Server 6.6.0 $ command time -v cbexport json -c 172.20.1.1 -u admin -p password -b default -f lines -o lines.json Json exported to `lines.json` successfully Documents exported: 10000000 Documents skipped: 0 Command being timed: "cbexport json -c 172.20.1.1 -u admin -p password -b default -f lines -o lines.json" User time (seconds): 134.84 System time (seconds): 39.39 Percent of CPU this job got: 145% Elapsed (wall clock) time (h:mm:ss or m:ss): 1:59.98 Average shared text size (kbytes): 0 Average unshared data size (kbytes): 0 Average stack size (kbytes): 0 Average total size (kbytes): 0 Maximum resident set size (kbytes): 167640 Average resident set size (kbytes): 0 Major (requiring I/O) page faults: 88 Minor (reclaiming a frame) page faults: 8342 Voluntary context switches: 7096904 Involuntary context switches: 24579 Swaps: 0 File system inputs: 23281 File system outputs: 1210944 Socket messages sent: 0 Socket messages received: 0 Signals delivered: 0 Page size (bytes): 4096 Exit status: 0   7.0.0 - Go 1.15 - CB Server 6.6.0 $ command time -v cbexport json -c 172.20.1.1 -u admin -p password -b default -f lines -o lines.json JSON exported to `lines.json` successfully Documents exported: 10000000 Documents skipped: 0 Command being timed: "cbexport json -c 172.20.1.1 -u admin -p password -b default -f lines -o lines.json" User time (seconds): 101.30 System time (seconds): 46.33 Percent of CPU this job got: 182% Elapsed (wall clock) time (h:mm:ss or m:ss): 1:20.77 Average shared text size (kbytes): 0 Average unshared data size (kbytes): 0 Average stack size (kbytes): 0 Average total size (kbytes): 0 Maximum resident set size (kbytes): 175568 Average resident set size (kbytes): 0 Major (requiring I/O) page faults: 99 Minor (reclaiming a frame) page faults: 8940 Voluntary context switches: 4204728 Involuntary context switches: 33513 Swaps: 0 File system inputs: 26777 File system outputs: 1210944 Socket messages sent: 0 Socket messages received: 0 Signals delivered: 0 Page size (bytes): 4096 Exit status: 0   6.6.0 - Go 1.15 - CB Server 6.6.0 (bumped gocbcore) $ command time -v cbexport json -c 172.20.1.1 -u admin -p password -b default -f lines -o lines.json Json exported to `lines.json` successfully Documents exported: 10000000 Documents skipped: 0 Command being timed: "cbexport json -c 172.20.1.1 -u admin -p password -b default -f lines -o lines.json" User time (seconds): 106.07 System time (seconds): 47.43 Percent of CPU this job got: 187% Elapsed (wall clock) time (h:mm:ss or m:ss): 1:21.77 Average shared text size (kbytes): 0 Average unshared data size (kbytes): 0 Average stack size (kbytes): 0 Average total size (kbytes): 0 Maximum resident set size (kbytes): 178300 Average resident set size (kbytes): 0 Major (requiring I/O) page faults: 92 Minor (reclaiming a frame) page faults: 8961 Voluntary context switches: 4310512 Involuntary context switches: 38417 Swaps: 0 File system inputs: 23473 File system outputs: 1210944 Socket messages sent: 0 Socket messages received: 0 Signals delivered: 0 Page size (bytes): 4096 Exit status: 0 As we can see above, we see a similar increase in throughput for 6.6.0 when we bump the underlying ' gocbcore ' library. TLDR; mad-hatter sees a similar increase in throughput if we bump the gocbcore version to the same that's used in master.

            People

              sharath.sulochana Sharath Sulochana (Inactive)
              sharath.sulochana Sharath Sulochana (Inactive)
              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