Operating System: All
Platform: All

Well, Verify_Cars fails, can they be related?

To quantify this a bit, we are seeing about 100% performance degradation observed from test duration.

> Verify_Cars fails

I do not see that in recent builds. Links without specific build number:
Be [3], B [4], C [5].

Note that those are single node tests, the suite runs also in three node setup [6], but the difference in performance is small.

[3] https://jenkins.opendaylight.org/releng/view/controller/job/controller-csit-1node-rest-cars-perf-only-beryllium/lastSuccessfulBuild/robot/controller-rest-cars-perf.txt/
[4] https://jenkins.opendaylight.org/releng/view/controller/job/controller-csit-1node-rest-cars-perf-only-boron/lastSuccessfulBuild/robot/controller-rest-cars-perf.txt/
[5] https://jenkins.opendaylight.org/releng/view/controller/job/controller-csit-1node-rest-cars-perf-only-carbon/lastSuccessfulBuild/robot/controller-rest-cars-perf.txt/010%20Crud%20Mdsal%20Perf/
[6] https://jenkins.opendaylight.org/releng/view/controller/job/controller-csit-3node-rest-clust-cars-perf-only-carbon/lastSuccessfulBuild/robot/controller-rest-clust-cars-perf.txt/010%20Crud%20Mdsal%20Perf/

Numeric values (for times when Beryllium jobs are removed) for Add_Cars:
Beryllium: 0:00:28.534
Boron: 0:01:24.138
Carbon: 0:01:36.001

Testing with distribution-karaf-0.6.0-20170418.121829-4936, it looks like the add case is doing an awful lot of reads.

I will profile this further to get to the bottom of this.

Add must check for existence (by read) but reads were also in beryllium,
by comparison of code there are exactly the same operations on transactions (merge, read, put) in master as were done in beryllium.

There are some modifications in master compare to beryllium (uri parameters) but in this simple case they are not applied.

When profiled beryllium and master and compared there were a lot of changes in Yangtools, maybe added some additional verifications for data.

Did you find more reads in recent versions?

Well, the reason for the regression is in RESTCONF. The regression was introduced in https://git.opendaylight.org/gerrit/#/c/30554/48/restconf/sal-rest-connector/src/main/java/org/opendaylight/netconf/sal/restconf/impl/BrokerFacade.java@320, as now BrokerFacade issues a read request for each individual item in the list.

So, the question is: what exactly is the reason for issuing the massive amounts of reads? I would prefer exact quotes from drafts, because the code sure as hell does not contain any sort of documentation about what is going on.

Attachment Main-2017-04-18-2.snapshot.xz has been added with description: YKP tracing snapshot

Snapshot shows BrokerFacade executing 10K read operations. Each of those is being waited synchronously, which is not something you can do while expecting reasonable performance.

Furthermore, these reads are executed as the target is being modified, which is forcing DataTree to apply operations so it can report accurate results.

easy data - POST empty container
complete data - POST list items into container

Attachment time results.tar.gz has been added with description: result of time measure between Be-4 and master running the same data

(In reply to Robert Varga from comment #7)
> Well, the reason for the regression is in RESTCONF. The regression was
> introduced in
> https://git.opendaylight.org/gerrit/#/c/30554/48/restconf/sal-rest-connector/
> src/main/java/org/opendaylight/netconf/sal/restconf/impl/BrokerFacade.
> java@320, as now BrokerFacade issues a read request for each individual item
> in the list.

-this code is for PACTH operation, we are dealing now with POST (postDataViaTransaction method)

when batch size for command is used wall time difference between master and be-4 arises

command:
/usr/bin/time -v python cluster_rest_script.py --host localhost --port 8181 --threads 1 --itemcount 10000 --ipr 10000 --debug add

Attachment compare has been added with description: compare be-4 and master when batch size is 10000

carbon: https://git.opendaylight.org/gerrit/55205
boron: https://git.opendaylight.org/gerrit/55211

This will need a proper follow-up to address overall code structure like:

• eliminate blocking checks in loops, so the checks are done in parallel
• make RestDocumentedException a checked exception
• audit all code to make sure checks are done before modifications
• ask controller/mdsal to add a create() method

will sit down with Ivan & Jakub to discuss follow-up notes

Boron looks fixed [7]:
Duration: 0:00:02.544 (-0:01:18.522)

Carbon merged, waiting for test run.
Nitrogen [8] not merged just yet.

[7] https://jenkins.opendaylight.org/releng/view/controller/job/controller-csit-1node-rest-cars-perf-only-boron/947/robot/controller-rest-cars-perf.txt/Add%20Cars/
[8] https://git.opendaylight.org/gerrit/55231

> Nitrogen [8]

merged now.

New Carbon performance [9] number: 0:00:02.314

[9] https://jenkins.opendaylight.org/releng/view/controller/job/controller-csit-1node-rest-cars-perf-all-carbon/245/robot/controller-rest-cars-perf.txt/010%20Crud%20Mdsal%20Perf/Add%20Cars/

Follow up bugs/improvements:

https://bugs.opendaylight.org/show_bug.cgi?id=8268
https://bugs.opendaylight.org/show_bug.cgi?id=8269
https://bugs.opendaylight.org/show_bug.cgi?id=8270
https://bugs.opendaylight.org/show_bug.cgi?id=8271
https://bugs.opendaylight.org/show_bug.cgi?id=8272

Also performance issue: https://bugs.opendaylight.org/show_bug.cgi?id=6412