[#BGPCEP-385] 10 iBGP rrc scenario failed for 1M prefixes in ipv4 topology target

[BGPCEP-385] 10 iBGP rrc scenario failed for 1M prefixes in ipv4 topology target Created: 02/Feb/16 Updated: 03/Mar/19 Resolved: 18/Oct/16
Status:	Resolved
Project:	bgpcep
Component/s:	BGP
Affects Version/s:	Bugzilla Migration
Fix Version/s:	Bugzilla Migration

Type:

Bug

Reporter:

Radovan Sajben

Assignee:

Milos Fabian

Resolution:

Won't Do

Votes:

Labels:

None

Remaining Estimate:

Not Specified

Time Spent:

Not Specified

Original Estimate:

Not Specified

Environment:

Operating System: All
Platform: All

Attachments:

karaf.txt

External issue ID:

5185

Description

10 iBGP rrc scenario failed for 1M prefixes in ipv4 topology target (Lithium)

please have a look at karaf.log

BGP Synchronization finished for table TablesKey ... and
Failed to acquire operation permit for transaction member ...

Note: prefixes successfully introduced to topology and announced to iBGP rrc peers for low numbers like 10k-100k prefixes

peers
=====

peers logs contain

10x: Target total number of prefixes to be introduced: 100000
10x: All update messages generated
many times: Input and output both blocked for ... seconds
none of: total_received_update_message_counter: 900000

console
=======

bgpcep-bgp-ingest.txt.Manypeers Peercount :: BGP performance of ingesting f...
==============================================================================
Check_That_Ipv4_Topology_Is_Empty :: Wait and check that the examp... waiting 120s
2016-02-01 17:27:27: actual (expected) prefix count is 0 (0)

PASS

------------------------------------------------------------------------------
Reconfigure_ODL_To_Accept_Connections :: Configure BGP peer module... | PASS |
------------------------------------------------------------------------------
Start_Talking_BGP_Manager :: Start Python manager to connect speak... | PASS |
------------------------------------------------------------------------------
Wait_For_Ipv4_Topology :: Wait until example-ipv4-topology reaches... waiting 3220.0
2016-02-01 17:27:33: actual (expected) prefix count is 0 (1000000)
2016-02-01 17:27:44: actual (expected) prefix count is 6490 (1000000)
2016-02-01 17:27:54: actual (expected) prefix count is 23318 (1000000)
2016-02-01 17:28:05: actual (expected) prefix count is 23318 (1000000)
2016-02-01 17:28:15: actual (expected) prefix count is 23318 (1000000)
2016-02-01 17:28:25: actual (expected) prefix count is 23318 (1000000)
2016-02-01 17:28:35: actual (expected) prefix count is 23960 (1000000)
2016-02-01 17:28:45: actual (expected) prefix count is 30177 (1000000)
2016-02-01 17:28:56: actual (expected) prefix count is 36561 (1000000)
2016-02-01 17:29:06: actual (expected) prefix count is 43822 (1000000)
2016-02-01 17:29:16: actual (expected) prefix count is 50556 (1000000)
2016-02-01 17:29:27: actual (expected) prefix count is 57659 (1000000)
2016-02-01 17:29:37: actual (expected) prefix count is 62079 (1000000)
2016-02-01 17:29:47: actual (expected) prefix count is 75352 (1000000)
2016-02-01 17:29:58: actual (expected) prefix count is 82623 (1000000)
2016-02-01 17:30:12: actual (expected) prefix count is 94136 (1000000)
2016-02-01 17:30:24: actual (expected) prefix count is 107114 (1000000)
2016-02-01 17:30:39: actual (expected) prefix count is 116712 (1000000)
2016-02-01 17:30:55: actual (expected) prefix count is 118980 (1000000)
2016-02-01 17:31:06: actual (expected) prefix count is 118980 (1000000)
2016-02-01 17:31:17: actual (expected) prefix count is 118980 (1000000)
2016-02-01 17:31:28: actual (expected) prefix count is 122804 (1000000)
2016-02-01 17:31:39: actual (expected) prefix count is 126627 (1000000)
2016-02-01 17:31:49: actual (expected) prefix count is 126627 (1000000)
2016-02-01 17:32:00: actual (expected) prefix count is 126627 (1000000)
2016-02-01 17:32:11: actual (expected) prefix count is 126627 (1000000)
2016-02-01 17:32:22: actual (expected) prefix count is 126627 (1000000)
2016-02-01 17:32:33: actual (expected) prefix count is 126627 (1000000)
2016-02-01 17:32:44: actual (expected) prefix count is 126627 (1000000)
2016-02-01 17:32:55: actual (expected) prefix count is 126627 (1000000)
2016-02-01 17:33:06: actual (expected) prefix count is 126627 (1000000)
2016-02-01 17:33:16: actual (expected) prefix count is 126627 (1000000)
2016-02-01 17:33:27: actual (expected) prefix count is 131606 (1000000)
2016-02-01 17:33:38: actual (expected) prefix count is 137537 (1000000)
2016-02-01 17:33:49: actual (expected) prefix count is 144321 (1000000)
2016-02-01 17:34:00: actual (expected) prefix count is 149499 (1000000)
2016-02-01 17:34:12: actual (expected) prefix count is 154614 (1000000)
2016-02-01 17:34:23: actual (expected) prefix count is 160054 (1000000)
2016-02-01 17:34:34: actual (expected) prefix count is 167039 (1000000)
2016-02-01 17:34:51: actual (expected) prefix count is 185780 (1000000)
2016-02-01 17:35:10: actual (expected) prefix count is 196039 (1000000)
2016-02-01 17:35:22: actual (expected) prefix count is 200480 (1000000)
2016-02-01 17:35:33: actual (expected) prefix count is 209110 (1000000)
2016-02-01 17:35:45: actual (expected) prefix count is 214540 (1000000)
2016-02-01 17:36:04: actual (expected) prefix count is 216054 (1000000)
2016-02-01 17:36:16: actual (expected) prefix count is 216054 (1000000)
2016-02-01 17:36:27: actual (expected) prefix count is 216054 (1000000)
2016-02-01 17:36:38: actual (expected) prefix count is 216054 (1000000)
2016-02-01 17:36:50: actual (expected) prefix count is 216054 (1000000)
2016-02-01 17:37:01: actual (expected) prefix count is 216054 (1000000)
2016-02-01 17:37:13: actual (expected) prefix count is 216054 (1000000)
2016-02-01 17:37:24: actual (expected) prefix count is 216054 (1000000)
2016-02-01 17:37:35: actual (expected) prefix count is 216054 (1000000)
2016-02-01 17:37:47: actual (expected) prefix count is 216054 (1000000)
2016-02-01 17:37:58: actual (expected) prefix count is 216054 (1000000)
2016-02-01 17:38:10: actual (expected) prefix count is 216197 (1000000)
2016-02-01 17:38:21: actual (expected) prefix count is 221796 (1000000)
2016-02-01 17:38:33: actual (expected) prefix count is 227779 (1000000)
2016-02-01 17:38:44: actual (expected) prefix count is 233735 (1000000)
2016-02-01 17:38:56: actual (expected) prefix count is 240232 (1000000)
2016-02-01 17:39:08: actual (expected) prefix count is 245768 (1000000)
2016-02-01 17:39:20: actual (expected) prefix count is 252202 (1000000)
2016-02-01 17:39:37: actual (expected) prefix count is 264713 (1000000)
2016-02-01 17:39:49: actual (expected) prefix count is 271351 (1000000)
2016-02-01 17:40:09: actual (expected) prefix count is 290581 (1000000)
2016-02-01 17:40:21: actual (expected) prefix count is 292937 (1000000)
2016-02-01 17:40:35: actual (expected) prefix count is 305671 (1000000)
2016-02-01 17:40:51: actual (expected) prefix count is 318981 (1000000)
2016-02-01 17:41:18: actual (expected) prefix count is 326555 (1000000)
2016-02-01 17:41:31: actual (expected) prefix count is 326555 (1000000)
2016-02-01 17:41:43: actual (expected) prefix count is 326555 (1000000)
2016-02-01 17:42:02: actual (expected) prefix count is 326555 (1000000)
2016-02-01 17:42:14: actual (expected) prefix count is 326555 (1000000)
2016-02-01 17:42:26: actual (expected) prefix count is 326555 (1000000)
2016-02-01 17:42:38: actual (expected) prefix count is 326555 (1000000)
2016-02-01 17:42:50: actual (expected) prefix count is 326555 (1000000)
2016-02-01 17:43:02: actual (expected) prefix count is 326555 (1000000)
2016-02-01 17:43:15: actual (expected) prefix count is 326555 (1000000)
2016-02-01 17:43:27: actual (expected) prefix count is 326555 (1000000)
2016-02-01 17:43:39: actual (expected) prefix count is 326555 (1000000)
2016-02-01 17:43:51: actual (expected) prefix count is 327944 (1000000)
2016-02-01 17:44:03: actual (expected) prefix count is 328264 (1000000)
2016-02-01 17:44:15: actual (expected) prefix count is 334875 (1000000)
2016-02-01 17:44:27: actual (expected) prefix count is 341499 (1000000)
2016-02-01 17:44:40: actual (expected) prefix count is 348160 (1000000)
2016-02-01 17:44:52: actual (expected) prefix count is 355702 (1000000)
2016-02-01 17:45:05: actual (expected) prefix count is 362327 (1000000)
2016-02-01 17:45:17: actual (expected) prefix count is 370097 (1000000)
2016-02-01 17:45:30: actual (expected) prefix count is 380722 (1000000)
2016-02-01 17:45:50: actual (expected) prefix count is 397260 (1000000)
2016-02-01 17:46:12: actual (expected) prefix count is 417419 (1000000)
2016-02-01 17:46:42: actual (expected) prefix count is 423856 (1000000)
2016-02-01 17:46:55: actual (expected) prefix count is 423856 (1000000)
2016-02-01 17:47:07: actual (expected) prefix count is 425929 (1000000)
2016-02-01 17:47:21: actual (expected) prefix count is 432227 (1000000)
2016-02-01 17:47:33: actual (expected) prefix count is 432227 (1000000)
2016-02-01 17:47:46: actual (expected) prefix count is 432227 (1000000)
2016-02-01 17:47:59: actual (expected) prefix count is 432227 (1000000)
2016-02-01 17:48:12: actual (expected) prefix count is 432227 (1000000)
2016-02-01 17:48:25: actual (expected) prefix count is 432227 (1000000)
2016-02-01 17:48:38: actual (expected) prefix count is 432227 (1000000)
2016-02-01 17:48:51: actual (expected) prefix count is 432227 (1000000)
2016-02-01 17:49:03: actual (expected) prefix count is 432227 (1000000)
2016-02-01 17:49:16: actual (expected) prefix count is 436931 (1000000)
2016-02-01 17:49:29: actual (expected) prefix count is 443489 (1000000)
2016-02-01 17:49:42: actual (expected) prefix count is 450601 (1000000)
2016-02-01 17:49:55: actual (expected) prefix count is 458153 (1000000)
2016-02-01 17:50:09: actual (expected) prefix count is 465288 (1000000)
2016-02-01 17:50:22: actual (expected) prefix count is 474002 (1000000)
2016-02-01 17:50:36: actual (expected) prefix count is 481159 (1000000)
2016-02-01 17:50:55: actual (expected) prefix count is 492945 (1000000)
2016-02-01 17:51:09: actual (expected) prefix count is 505630 (1000000)
2016-02-01 17:51:50: actual (expected) prefix count is 521927 (1000000)
2016-02-01 17:52:10: actual (expected) prefix count is 521927 (1000000)
2016-02-01 17:52:24: actual (expected) prefix count is 521927 (1000000)
2016-02-01 17:52:37: actual (expected) prefix count is 521927 (1000000)
2016-02-01 17:52:50: actual (expected) prefix count is 521927 (1000000)
2016-02-01 17:53:04: actual (expected) prefix count is 521927 (1000000)
2016-02-01 17:53:17: actual (expected) prefix count is 527548 (1000000)
2016-02-01 17:53:30: actual (expected) prefix count is 535550 (1000000)
2016-02-01 17:53:44: actual (expected) prefix count is 543942 (1000000)
2016-02-01 17:53:58: actual (expected) prefix count is 550884 (1000000)
2016-02-01 17:54:19: actual (expected) prefix count is 570927 (1000000)
2016-02-01 17:54:33: actual (expected) prefix count is 575054 (1000000)
2016-02-01 17:55:23: actual (expected) prefix count is 583938 (1000000)
2016-02-01 17:57:43: actual (expected) prefix count is 590214 (1000000)
2016-02-01 18:04:32: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:04:46: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:05:00: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:05:14: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:05:28: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:05:41: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:05:55: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:06:09: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:06:22: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:06:36: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:06:50: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:07:03: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:07:17: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:07:31: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:07:44: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:07:58: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:08:12: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:08:26: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:08:39: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:08:53: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:09:07: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:09:20: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:09:34: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:09:48: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:10:01: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:10:15: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:10:29: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:10:43: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:10:57: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:11:11: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:11:24: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:11:38: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:11:52: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:12:05: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:12:19: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:12:33: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:12:46: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:13:00: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:13:14: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:13:28: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:13:41: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:13:55: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:14:09: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:14:23: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:14:36: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:14:50: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:15:04: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:15:18: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:15:31: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:15:45: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:15:59: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:16:13: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:16:26: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:16:40: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:16:54: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:17:08: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:17:22: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:17:36: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:17:49: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:18:03: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:18:17: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:18:31: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:18:45: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:18:58: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:19:12: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:19:26: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:19:40: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:19:54: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:20:08: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:20:21: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:20:35: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:20:49: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:21:03: actual (expected) prefix count is 591817 (1000000)
2016-02-01 18:21:17: actual (expected) prefix count is 591817 (1000000)

FAIL

Comments

Comment by Radovan Sajben [ 02/Feb/16 ]

Attachment karaf.txt has been added with description: karaf log

Comment by Radovan Sajben [ 02/Feb/16 ]

please see the beryllium result for 10x100 prefixes: https://jenkins.opendaylight.org/sandbox/job/bgpcep-csit-1node-periodic-bgp-ingest-only-beryllium/2/artifact/karaf.log/*view*/

2016-02-02 11:30:37,947 | WARN | lt-dispatcher-20 | SimpleShardDataTreeCohort | 143 - org.opendaylight.controller.sal-distributed-datastore - 1.3.0.SNAPSHOT | Store Tx member-1-chn-39-txn-53: Data validation failed for path /(urn:opendaylight:params:xml:ns:yang:bgp-rib?revision=2013-09-25)bgp-rib/rib/rib[

{(urn:opendaylight:params:xml:ns:yang:bgp-rib?revision=2013-09-25)id=example-bgp-rib}

]/peer/peer[

{(urn:opendaylight:params:xml:ns:yang:bgp-rib?revision=2013-09-25)peer-id=bgp://127.0.0.4}

].
org.opendaylight.yangtools.yang.data.api.schema.tree.ModifiedNodeDoesNotExistException: Node /(urn:opendaylight:params:xml:ns:yang:bgp-rib?revision=2013-09-25)bgp-rib/rib/rib[

{(urn:opendaylight:params:xml:ns:yang:bgp-rib?revision=2013-09-25)id=example-bgp-rib}

]/peer/peer[

{(urn:opendaylight:params:xml:ns:yang:bgp-rib?revision=2013-09-25)peer-id=bgp://127.0.0.4}

] does not exist. Cannot apply modification to its children.

2016-02-02 11:30:38,105 | WARN | oupCloseable-6-6 | DefaultChannelPipeline | 102 - io.netty.common - 4.0.33.Final | An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
java.lang.IllegalStateException: Transaction chain has failed
at com.google.common.base.Preconditions.checkState(Preconditions.java:173)[39:com.google.guava:18.0.0]
at org.opendaylight.controller.cluster.databroker.DOMBrokerTransactionChain.checkNotFailed(DOMBrokerTransactionChain.java:73)[143:org.opendaylight.controller.sal-distributed-datastore:1.3.0.SNAPSHOT]
at org.opendaylight.controller.cluster.databroker.DOMBrokerTransactionChain.submit(DOMBrokerTransactionChain.java:84)[143:org.opendaylight.controller.sal-distributed-datastore:1.3.0.SNAPSHOT]
at org.opendaylight.controller.cluster.databroker.AbstractDOMBrokerWriteTransaction.submit(AbstractDOMBrokerWriteTransaction.java:137)[143:org.opendaylight.controller.sal-distributed-datastore:1.3.0.SNAPSHOT]

Test suite console:
===================

bgpcep-bgp-ingest.txt.Manypeers Peercount :: BGP performance of ingesting f...
==============================================================================
Check_For_Empty_Ipv4_Topology_Before_Talking :: Wait for example-i... | PASS |
------------------------------------------------------------------------------
Reconfigure_ODL_To_Accept_Connections :: Configure BGP peer module... | PASS |
------------------------------------------------------------------------------
Start_Talking_BGP_Manager :: Start Python manager to connect speak... | PASS |
------------------------------------------------------------------------------
Wait_For_Ipv4_Topology :: Wait until example-ipv4-topology reaches... 226.0s
2016-02-02 11:30:36: actual (expected) prefix count is 0 (1000)
2016-02-02 11:30:46: actual (expected) prefix count is 14 (1000)
2016-02-02 11:30:56: actual (expected) prefix count is 14 (1000)
2016-02-02 11:31:06: actual (expected) prefix count is 14 (1000)
2016-02-02 11:31:16: actual (expected) prefix count is 14 (1000)
2016-02-02 11:31:26: actual (expected) prefix count is 14 (1000)
2016-02-02 11:31:36: actual (expected) prefix count is 14 (1000)
2016-02-02 11:31:46: actual (expected) prefix count is 14 (1000)
2016-02-02 11:31:56: actual (expected) prefix count is 14 (1000)
2016-02-02 11:32:06: actual (expected) prefix count is 14 (1000)
2016-02-02 11:32:16: actual (expected) prefix count is 14 (1000)
2016-02-02 11:32:27: actual (expected) prefix count is 14 (1000)
2016-02-02 11:32:37: actual (expected) prefix count is 14 (1000)
2016-02-02 11:32:47: actual (expected) prefix count is 14 (1000)
2016-02-02 11:32:57: actual (expected) prefix count is 14 (1000)
2016-02-02 11:33:07: actual (expected) prefix count is 14 (1000)
2016-02-02 11:33:17: actual (expected) prefix count is 14 (1000)
2016-02-02 11:33:27: actual (expected) prefix count is 14 (1000)
2016-02-02 11:33:37: actual (expected) prefix count is 14 (1000)
2016-02-02 11:33:47: actual (expected) prefix count is 14 (1000)
2016-02-02 11:33:57: actual (expected) prefix count is 14 (1000)
2016-02-02 11:34:07: actual (expected) prefix count is 14 (1000)
2016-02-02 11:34:17: actual (expected) prefix count is 14 (1000)
2016-02-02 11:34:27: actual (expected) prefix count is 14 (1000)

FAIL

This test fails due to https://bugs.opendaylight.org/show_bug.cgi?id=5185

Keyword 'Check_Ipv4_Topology' failed after retrying for 3 minutes 46 seconds. The last error was: 14 != 1000

Comment by Milos Fabian [ 08/Feb/16 ]

What is the maximum Java heap size?
What garbage collector is used?

Comment by Radovan Sajben [ 08/Feb/16 ]

+ source /w/workspace/bgpcep-csit-1node-periodic-bgp-ingest-only-beryllium/test/csit/scripts/controllermem_6g.sh
++ CONTROLLERMEM=6144m

garbage collector - no info in logs anyway this suite is just a part of the whole BGP performance suite = the same as for the rest ...

... current sandbox result passed the topology check: https://jenkins.opendaylight.org/sandbox/job/bgpcep-csit-1node-periodic-bgp-ingest-only-beryllium/1/console

Wait_For_Ipv4_Topology :: Wait until example-ipv4-topology reaches... 49620.0s
2016-02-08 08:29:08: actual (expected) prefix count is 0 (1000000)
2016-02-08 08:29:18: actual (expected) prefix count is 4210 (1000000)
...
2016-02-08 09:20:05: actual (expected) prefix count is 1000000 (1000000)

PASS

------------------------------------------------------------------------------
Check_Logs_For_Updates :: Check BGP peer logs for received updates. | FAIL |
Keyword 'Check_File_For_Occurence' failed after retrying for 20 seconds. The last error was: '0 >= 2' should be true.

and failed on one of bgp peer update count ...

Comment by Vratko Polak [ 23/Feb/16 ]

On top of possible (still not verified) memory pressure on ODL_SYSTEM, there seem to be problems on robot slave too [0]:
Output: /w/workspace/bgpcep-csit-1node-periodic-bgp-ingest-only-stable-lithium/output.xml
Traceback (most recent call last):
File "/tmp/tmp.UyJmSZoTFJrobot_venv/bin/pybot", line 6, in <module>
run_cli(sys.argv[1:])
File "/tmp/tmp.UyJmSZoTFJrobot_venv/lib/python2.7/site-packages/robot/run.py", line 466, in run_cli
RobotFramework().execute_cli(arguments)
File "/tmp/tmp.UyJmSZoTFJrobot_venv/lib/python2.7/site-packages/robot/utils/application.py", line 45, in execute_cli
rc = self._execute(arguments, options)
File "/tmp/tmp.UyJmSZoTFJrobot_venv/lib/python2.7/site-packages/robot/utils/application.py", line 87, in _execute
error, details = get_error_details(exclude_robot_traces=False)
File "/tmp/tmp.UyJmSZoTFJrobot_venv/lib/python2.7/site-packages/robot/utils/error.py", line 46, in get_error_details
details = ErrorDetails(exclude_robot_traces=exclude_robot_traces)
File "/tmp/tmp.UyJmSZoTFJrobot_venv/lib/python2.7/site-packages/robot/utils/error.py", line 59, in ErrorDetails
raise exc_value
MemoryError

Robot VM now uses only 2GB RAM, so scaling suite should be reviewed for memory inefficiencies.

[0] https://jenkins.opendaylight.org/releng/view/bgpcep/job/bgpcep-csit-1node-periodic-bgp-ingest-only-stable-lithium/116/console

Comment by Milos Fabian [ 29/Apr/16 ]

Testing locally with Beryllium SR2 and latest - 10 rr-clients, each advertise 10k prefixes.
The log contain a lot of "Failed to acquire operation permit for transaction" and " Generation of DataTreeCandidateNode events took longer than expected. Elapsed time"

After some time, ODL runs out of memory:

2016-04-29 11:26:20,980 | WARN | oupCloseable-2-6 | BGPSessionImpl | 185 - org.opendaylight.bgpcep.bgp-rib-impl - 0.5.2.SNAPSHOT | Failed to send message Update [_attributes=Attributes [_asPath=AsPath{getSegments=[], augmentations={}}, _clusterId=ClusterId{getCluster=[Ipv4Address [_value=127.0.0.1]], augmentations={}}, _localPref=LocalPref{getPref=100, augmentations={}}, _origin=Origin{getValue=Igp, augmentations={}}, _originatorId=OriginatorId{getOriginator=Ipv4Address [_value=127.0.0.1], augmentations={}}, _unrecognizedAttributes=[], augmentation=[Attributes1 [_mpReachNlri=MpReachNlri [_advertizedRoutes=AdvertizedRoutes [_destinationType=DestinationIpv4Case [_destinationIpv4=DestinationIpv4 [_ipv4Prefixes=[Ipv4Prefixes [_prefix=Ipv4Prefix [_value=2.0.210.48/28], augmentation=[]]], augmentation=[]], augmentation=[]], augmentation=[]], _afi=class org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.types.rev130919.Ipv4AddressFamily, _cNextHop=Ipv4NextHopCase{getIpv4NextHop=Ipv4NextHop{getGlobal=Ipv4Address [_value=192.0.2.1], augmentations={}}, augmentations={}}, _safi=class org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.types.rev130919.UnicastSubsequentAddressFamily, augmentation=[]]]]], augmentation=[]] to socket io.netty.handler.codec.EncoderException: java.lang.OutOfMemoryError: GC overhead limit exceeded
Uncaught error from thread [opendaylight-cluster-data-notification-dispatcher-56] shutting down JVM since 'akka.jvm-exit-on-fatal-error' is enabled for ActorSystem[opendaylight-cluster-data]
2016-04-29 11:26:29,548 | WARN | on-dispatcher-52 | OperationLimiter | 175 - org.opendaylight.controller.sal-distributed-datastore - 1.3.2.SNAPSHOT | Failed to acquire operation permit for transaction member-1-chn-5-txn-3699-1461921917380
java.lang.OutOfMemoryError: GC overhead limit exceeded
Uncaught error from thread [opendaylight-cluster-data-akka.actor.default-dispatcher-17] shutting down JVM since 'akka.jvm-exit-o2016-04-29 11:26:37,565 | WARN | on-dispatcher-52 | OperationLimiter | 175 - org.opendaylight.controller.sal-distributed-datastore - 1.3.2.SNAPSHOT | Failed to acquire operation permit for transaction member-1-chn-5-txn-3699-1461921917380
n-fatal-error' is enabled for ActorSystem[opendaylight-cluster-data]
at org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.multiprotocol.rev130919.Attributes1Builder.build(Attributes1Builder.java:38)
at org.opendaylight.protocol.bgp.rib.spi.AbstractRIBSupport.buildUpdate(AbstractRIBSupport.java:241)
2016-04-29 11:26:45,944 | WARN | on-dispatcher-52 | OperationLimiter | 175 - org.opendaylight.controller.sal-distributed-datastore - 1.3.2.SNAPSHOT | Failed to acquire operation permit for transaction member-1-chn-5-txn-3699-1461921917380
at org.opendaylight.protocol.bgp.rib.impl.AdjRibOutListener.advertise(AdjRibOutListener.java:143)
at org.opendaylight.protocol.bgp.rib.impl.AdjRibOutListener.processRouteChange(AdjRibOutListener.java:114)
at org.opendaylight.protocol.bgp.rib.impl.AdjRibOutListener.processSupportedFamilyRoutes(AdjRibOutListener.java:95)
at org.opendaylight.protocol.bgp.rib.impl.AdjRibOutListener.onDataTreeChanged(AdjRibOutListener.java:87)
at org.opendaylight.controller.cluster.datastore.DataTreeChangeListenerActor.dataChanged(DataTreeChangeListenerActor.java:53)
at org.opendaylight.controller.cluster.datastore.DataTreeChangeListenerActor.handleReceive(DataTreeChangeListenerActor.java:37)
at org.opendaylight.controller.cluster.common.actor.AbstractUntypedActor.onReceive(AbstractUntypedActor.java:34)
at akka.actor.UntypedActor$$anonfun$receive$1.applyOrElse(UntypedActor.scala:167)
at akka.actor.Actor$class.aroundReceive(Actor.scala:467)
at akka.actor.UntypedActor.aroundReceive(UntypedActor.scala:97)
at akka.actor.ActorCell.receiveMessage(ActorCell.scala:516)
at akka.actor.ActorCell.invoke(ActorCell.scala:487)
at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:238)
at akka.dispatch.Mailbox.run(Mailbox.scala:220)
at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:397)
at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)
java.lang.OutOfMemoryError: GC overhead limit exceeded

Initial try-outs shows that pressure can be lowered by narrowing LocRibWriter DCN listener scope to Effective-RIB-In tables only.

Comment by Milos Fabian [ 03/May/16 ]

stable/beryllium: https://git.opendaylight.org/gerrit/#/c/38286

Generated at Wed Feb 07 19:12:54 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.

[BGPCEP-385] 10 iBGP rrc scenario failed for 1M prefixes in ipv4 topology target Created: 02/Feb/16 Updated: 03/Mar/19 Resolved: 18/Oct/16