Operating System: All
Platform: All

Attachment karaf.rar has been added with description: follower node1 karaf logs

Isn't this duplicate of this one? https://bugs.opendaylight.org/show_bug.cgi?id=6552

I do not think there is regression here, the failures are in the cluster performance test that we have to separate in its own job and adjust so that it passes.

Reducing severity and change title to describe exactly what is going on.

The test is sporadically failing with just 32 switches and 2K flows/switch (64K flows):

https://jenkins.opendaylight.org/releng/view/openflowplugin/job/openflowplugin-csit-3node-periodic-bulkomatic-clustering-perf-daily-only-carbon/

Therefore rising to critical for now.

I am adding more memory to see if it helps:

https://git.opendaylight.org/gerrit/#/c/46644/

Luis,

Did adding more memory to the test (as per your last comment) help?

Abhijit

No it did not

For this particular bug I have action point of collecting cluster releated ERRORs in karaf log and open bugs to cluster project.

It seems that Boron is passing fine but not Carbon. For the latest I opened this bug in controller project to better understand the ERRORs:

https://bugs.opendaylight.org/show_bug.cgi?id=7901

Anil Vishnoi looking at this. The patch for this is failing netvirt test cases - and was reverted by https://git.opendaylight.org/gerrit/#/c/53532/.

My current observation is that stats collection for 100K flows work most of the times in Boron:

https://jenkins.opendaylight.org/releng/view/openflowplugin/job/openflowplugin-csit-3node-periodic-bulkomatic-clustering-daily-only-boron

But never works in Carbon:

https://jenkins.opendaylight.org/releng/view/openflowplugin/job/openflowplugin-csit-3node-periodic-bulkomatic-clustering-daily-only-carbon/

So we may be facing a perf regression in Carbon.

BR/Luis

Luis, the test are showing

Variable '${temp_json_config_get}' not found.

It is some issue in test itself ?

I actually posted the wrong links, these are the goods:

Boron:

https://jenkins.opendaylight.org/releng/view/openflowplugin/job/openflowplugin-csit-3node-periodic-bulkomatic-clustering-perf-daily-only-boron

Carbon:

https://jenkins.opendaylight.org/releng/view/openflowplugin/job/openflowplugin-csit-3node-periodic-bulkomatic-clustering-perf-daily-only-carbon/

BR/Luis

Hi Luis,

When I tried to reproduce this locally, I have received following warning:
(after all flows added to the config)

15159:2017-05-29 14:40:34,956 | WARN | entLoopGroup-5-2 | OperationLimiter | 207 - org.opendaylight.controller.sal-distributed-datastore - 1.5.1.SNAPSHOT | Failed to acquire operation permit for transaction member-1-datastore-operational-fe-0-chn-12-txn-734-0

It does not appear in Jenkins logs. Have you seen it already somewhere?

It is happening already when I try to add 1000 flows on 10 switches.

Flows are getting to the config and also to the switch.

But then mentioned WARN appear and later some switches are disconnected.

I have connected only one controller based on Jenkins test (one of the Followers), and it was timed out.

The Master was lost. And since no other controller was connected, we are finished...

I am wondering, if this can happen on Jenkins also, since logs don't seem to be same.

Thanks,
Miro

This is because in scalability/perf tests we use log:set ERROR. I will file a patch to set WARN on this test.

https://git.opendaylight.org/gerrit/#/c/58016

Hi Luis,

Great. Thanks a lot.

One run was completed already, but there are no logs.

https://jenkins.opendaylight.org/releng/view/openflowplugin/job/openflowplugin-csit-3node-periodic-bulkomatic-clustering-perf-daily-only-carbon/259/

I believe it happen just occasionally, since there are also other builds without logs. Right?

Hope next run logs should be there.

Thanks,
Miro

Right, next build worked: https://jenkins.opendaylight.org/releng/view/openflowplugin/job/openflowplugin-csit-3node-periodic-bulkomatic-clustering-perf-daily-only-carbon/260/

Hello Luis,

We need to check results of this test:

https://jenkins.opendaylight.org/releng/view/openflowplugin/job/openflowplugin-csit-3node-periodic-bulkomatic-clustering-perf-daily-only-nitrogen/

But it looks like it is not working properly. In the graph it is showing pass green, tests are red and logs are not there.

Could you please check what can be wrong?

Thanks a lot,
Miro

There is already a thread on this, the issue is impacting more projects (not just ofp):

https://lists.opendaylight.org/pipermail/integration-dev/2017-June/009906.html

I will let you know when it gets fixed.

Hi Miroslav, Nitrogen pass some times now:

https://jenkins.opendaylight.org/releng/view/openflowplugin/job/openflowplugin-csit-3node-periodic-bulkomatic-clustering-perf-daily-only-nitrogen/

But Carbon fails all the time:

https://jenkins.opendaylight.org/releng/view/openflowplugin/job/openflowplugin-csit-3node-periodic-bulkomatic-clustering-perf-daily-only-carbon/

Issue sems to be flow stats collection.

So it looks like on nitrogen this is already working, and on carbon it will be working after this cherry-pick will be merged: https://git.opendaylight.org/gerrit/#/c/60196/

Cherry-pick was merged and looks like it is working on carbon too now (https://jenkins.opendaylight.org/releng/job/openflowplugin-csit-3node-periodic-gate-bulkomatic-clustering-perf-daily-only-carbon/98/) so closing this bug.

Yes that is fine, we have all branches behaving the same, but do we want to leave this open to track the issue of sporadic failure in this test? also looking at karaf.log when it fails, it looks like we are hitting cluster issues:

2017-07-17 18:04:34,185 | WARN | tp1066220241-427 | BrokerFacade | 276 - org.opendaylight.netconf.sal-rest-connector - 1.5.2.SNAPSHOT | Error reading /(urn:opendaylight:inventory?revision=2013-08-19)nodes from datastore OPERATIONAL
ReadFailedException

Just realized there is a regression if we compare to Boron:

https://jenkins.opendaylight.org/releng/job/openflowplugin-csit-3node-periodic-bulkomatic-clustering-perf-daily-only-boron/

Or even nitrogen:

https://jenkins.opendaylight.org/releng/job/openflowplugin-csit-3node-periodic-bulkomatic-clustering-perf-daily-only-nitrogen/

So reopening the bug for this:

https://jenkins.opendaylight.org/releng/job/openflowplugin-csit-3node-periodic-bulkomatic-clustering-perf-daily-only-carbon/

Luis

Looking at a failed job log, I think this is cluster issue so moving bug to the right project:

2017-09-17 15:53:44,930 | WARN | tp1225015068-434 | BrokerFacade | 276 - org.opendaylight.netconf.sal-rest-connector - 1.5.2.SNAPSHOT | Error reading /(urn:opendaylight:inventory?revision=2013-08-19)nodes from datastore OPERATIONAL
ReadFailedException

at org.opendaylight.controller.cluster.datastore.RemoteTransactionContext$1.onComplete(RemoteTransactionContext.java:184)[196:org.opendaylight.controller.sal-distributed-datastore:1.5.2.SNAPSHOT]
at akka.dispatch.OnComplete.internal(Future.scala:258)[170:com.typesafe.akka.actor:2.4.18]
at akka.dispatch.OnComplete.internal(Future.scala:256)[170:com.typesafe.akka.actor:2.4.18]
at akka.dispatch.japi$CallbackBridge.apply(Future.scala:186)[170:com.typesafe.akka.actor:2.4.18]
at akka.dispatch.japi$CallbackBridge.apply(Future.scala:183)[170:com.typesafe.akka.actor:2.4.18]
at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:36)[166:org.scala-lang.scala-library:2.11.11.v20170413-090219-8a413ba7cc]
at akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:55)[170:com.typesafe.akka.actor:2.4.18]
at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run$1.apply$mcV$sp(BatchingExecutor.scala:91)[170:com.typesafe.akka.actor:2.4.18]
at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run$1.apply(BatchingExecutor.scala:91)[170:com.typesafe.akka.actor:2.4.18]
at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run$1.apply(BatchingExecutor.scala:91)[170:com.typesafe.akka.actor:2.4.18]
at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:72)[166:org.scala-lang.scala-library:2.11.11.v20170413-090219-8a413ba7cc]
at akka.dispatch.BatchingExecutor$BlockableBatch.run(BatchingExecutor.scala:90)[170:com.typesafe.akka.actor:2.4.18]
at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:39)[170:com.typesafe.akka.actor:2.4.18]
at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:415)[170:com.typesafe.akka.actor:2.4.18]
at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)[166:org.scala-lang.scala-library:2.11.11.v20170413-090219-8a413ba7cc]
at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)[166:org.scala-lang.scala-library:2.11.11.v20170413-090219-8a413ba7cc]
at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)[166:org.scala-lang.scala-library:2.11.11.v20170413-090219-8a413ba7cc]
at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)[166:org.scala-lang.scala-library:2.11.11.v20170413-090219-8a413ba7cc]
Caused by: akka.pattern.AskTimeoutException: Ask timed out on [ActorSelection[Anchor(akka.tcp://opendaylight-cluster-data@10.29.14.94:2550/), Path(/user/shardmanager-operational/member-3-shard-inventory-operational/shard-inventory-member-2:datastore-operational@0:6_870#-1165819976)]] after [5000 ms]. Sender[null] sent message of type "org.opendaylight.controller.cluster.datastore.messages.ReadData".
at akka.pattern.PromiseActorRef$$anonfun$1.apply$mcV$sp(AskSupport.scala:604)[170:com.typesafe.akka.actor:2.4.18]
at akka.actor.Scheduler$$anon$4.run(Scheduler.scala:126)[170:com.typesafe.akka.actor:2.4.18]
at scala.concurrent.Future$InternalCallbackExecutor$.unbatchedExecute(Future.scala:601)[166:org.scala-lang.scala-library:2.11.11.v20170413-090219-8a413ba7cc]
at scala.concurrent.BatchingExecutor$class.execute(BatchingExecutor.scala:109)[166:org.scala-lang.scala-library:2.11.11.v20170413-090219-8a413ba7cc]
at scala.concurrent.Future$InternalCallbackExecutor$.execute(Future.scala:599)[166:org.scala-lang.scala-library:2.11.11.v20170413-090219-8a413ba7cc]
at akka.actor.LightArrayRevolverScheduler$TaskHolder.executeTask(LightArrayRevolverScheduler.scala:329)[170:com.typesafe.akka.actor:2.4.18]
at akka.actor.LightArrayRevolverScheduler$$anon$4.executeBucket$1(LightArrayRevolverScheduler.scala:280)[170:com.typesafe.akka.actor:2.4.18]
at akka.actor.LightArrayRevolverScheduler$$anon$4.nextTick(LightArrayRevolverScheduler.scala:284)[170:com.typesafe.akka.actor:2.4.18]
at akka.actor.LightArrayRevolverScheduler$$anon$4.run(LightArrayRevolverScheduler.scala:236)[170:com.typesafe.akka.actor:2.4.18]
at java.lang.Thread.run(Thread.java:748)[:1.8.0_141]
2017-09-17 15:53:47,162 | WARN | lt-dispatcher-47 | ClusterCoreDaemon | 171 - com.typesafe.akka.slf4j - 2.4.18 | Cluster Node [akka.tcp://opendaylight-cluster-data@10.29.14.161:2550] - Marking node(s) as UNREACHABLE [Member(address = akka.tcp://opendaylight-cluster-data@10.29.14.94:2550, status = Up)]. Node roles [member-2]

Forgot the link to the failing job:

https://jenkins.opendaylight.org/releng/view/CSIT-3node/job/openflowplugin-csit-3node-periodic-bulkomatic-clustering-perf-daily-only-carbon/365/

> AskTimeoutException

Let me guess. Ongoing transactions (read by Restconf in this case) while isolation (or JVM kill) happens?
That is expected to fail while using ask-based protocol. Try using tell-based protocol (by prepending integration/test/csit/suites/controller/dom_data_broker/restart_odl_with_tell_based_true.robot in the testplan).

TODO: Add a link to an official documentation on tell-based protocol here.

This test does not take down any cluster instance, it just pushes a bunch of flows in config DS in a member that is not leader or switch master (worst case).

Changing to tell-based protocol seems to help in carbon but not in nitrogen, not sure why. I will prepare a patch to change the test anyway.

https://git.opendaylight.org/gerrit/#/c/63592/

Luis, moving this to you for now since Sanjib is no longer active. 

I am not sure we can do much here: same perf 100K flows test works for single node but obviously performance takes a hit when cluster is used due to the backend data replication.

I lower priority of this and I will adjust the test to pass with less flows. After that I will close the ticket.

Test passes with 80K flows. We will leave like this for now.