|
some additional info ... the test where the controller just announces routes to BGP peer is there ... aproximatelly 32k routes in 1 min (see the total_received_update_message_counter) ... a scheduler on the controller side?
https://jenkins.opendaylight.org/sandbox/job/bgpcep-csit-1node-periodic-bgp-ingest-only-stable-lithium/26/robot/report/log.html#s1-s4-t16-k4-k2
2015-11-30 09:40:01,828 INFO: No message received in 9.94529294968s
2015-11-30 09:40:01,830 INFO: total_received_update_message_counter: 0
2015-11-30 09:40:01,830 INFO: total_received_nlri_prefix_counter: 0
2015-11-30 09:40:01,830 INFO: total_received_withdrawn_prefix_counter: 0
2015-11-30 09:40:01,830 INFO: total_rx_idle_time_counter: 60.006s
2015-11-30 09:40:01,830 INFO: KEEP ALIVE is sent.
2015-11-30 09:40:02,668 INFO: KEEP ALIVE message received: 0xffffffffffffffffffffffffffffffff001304
2015-11-30 09:40:12,678 INFO: No message received in 10s
2015-11-30 09:40:12,678 INFO: total_received_update_message_counter: 9113
2015-11-30 09:40:12,679 INFO: total_received_nlri_prefix_counter: 0
2015-11-30 09:40:12,679 INFO: total_received_withdrawn_prefix_counter: 0
2015-11-30 09:40:12,679 INFO: total_rx_idle_time_counter: 70.199s
2015-11-30 09:40:22,689 INFO: No message received in 10s
2015-11-30 09:40:22,690 INFO: total_received_update_message_counter: 9113
2015-11-30 09:40:22,690 INFO: total_received_nlri_prefix_counter: 0
2015-11-30 09:40:22,690 INFO: total_received_withdrawn_prefix_counter: 0
2015-11-30 09:40:22,690 INFO: total_rx_idle_time_counter: 80.209s
2015-11-30 09:40:32,700 INFO: No message received in 10s
2015-11-30 09:40:32,701 INFO: total_received_update_message_counter: 9113
2015-11-30 09:40:32,701 INFO: total_received_nlri_prefix_counter: 0
2015-11-30 09:40:32,701 INFO: total_received_withdrawn_prefix_counter: 0
2015-11-30 09:40:32,701 INFO: total_rx_idle_time_counter: 90.220s
2015-11-30 09:40:42,711 INFO: No message received in 10s
2015-11-30 09:40:42,712 INFO: total_received_update_message_counter: 9113
2015-11-30 09:40:42,712 INFO: total_received_nlri_prefix_counter: 0
2015-11-30 09:40:42,712 INFO: total_received_withdrawn_prefix_counter: 0
2015-11-30 09:40:42,712 INFO: total_rx_idle_time_counter: 100.230s
2015-11-30 09:40:52,722 INFO: No message received in 10s
2015-11-30 09:40:52,723 INFO: total_received_update_message_counter: 9113
2015-11-30 09:40:52,723 INFO: total_received_nlri_prefix_counter: 0
2015-11-30 09:40:52,723 INFO: total_received_withdrawn_prefix_counter: 0
2015-11-30 09:40:52,723 INFO: total_rx_idle_time_counter: 110.240s
2015-11-30 09:41:01,840 INFO: No message received in 9.10711407661s
2015-11-30 09:41:01,840 INFO: total_received_update_message_counter: 9113
2015-11-30 09:41:01,840 INFO: total_received_nlri_prefix_counter: 0
2015-11-30 09:41:01,840 INFO: total_received_withdrawn_prefix_counter: 0
2015-11-30 09:41:01,840 INFO: total_rx_idle_time_counter: 119.356s
2015-11-30 09:41:01,841 INFO: KEEP ALIVE is sent.
2015-11-30 09:41:02,666 INFO: KEEP ALIVE message received: 0xffffffffffffffffffffffffffffffff001304
2015-11-30 09:41:14,920 INFO: No message received in 10s
2015-11-30 09:41:14,921 INFO: total_received_update_message_counter: 32391
2015-11-30 09:41:14,921 INFO: total_received_nlri_prefix_counter: 0
2015-11-30 09:41:14,921 INFO: total_received_withdrawn_prefix_counter: 0
2015-11-30 09:41:14,921 INFO: total_rx_idle_time_counter: 130.787s
2015-11-30 09:41:24,931 INFO: No message received in 10s
2015-11-30 09:41:24,932 INFO: total_received_update_message_counter: 32391
2015-11-30 09:41:24,932 INFO: total_received_nlri_prefix_counter: 0
2015-11-30 09:41:24,932 INFO: total_received_withdrawn_prefix_counter: 0
2015-11-30 09:41:24,932 INFO: total_rx_idle_time_counter: 140.797s
2015-11-30 09:41:34,942 INFO: No message received in 10s
... about the restconf performance ... based on https://wiki.opendaylight.org/view/BGP_LS_PCEP:Programmer_Guide#BGP test tool uses a single POST request for addition of single route (anyway gauges will be introduced to the test tool to measure total response time). Performance could be increased using single request for all routes. Is it the target to announce 1M routes in a single POST request? Does controller support routes announcement via restconf in batches?
|
|
... similar behavior for deleting all routes (waiting for updates failed - timeout for this TC set 10x longer than other bgp performance suites have, ROBOT OPTIONS: --suite *ready --suite *bgp_app_peer_prefixcount -v COUNT:50000 -v PREFILL:25000 -v TEST_DURATION_MULTIPLIER:10):
Karaf log:
=========
https://jenkins.opendaylight.org/sandbox/job/bgpcep-csit-1node-periodic-bgp-ingest-only-stable-lithium/22/artifact/karaf.log
2015-12-08 10:15:13,551 | INFO | h for user karaf | command | 255 - org.apache.karaf.log.command - 3.0.3 | ROBOT MESSAGE: Starting test Reconnect_BGP_Peer
2015-12-08 10:15:13,670 | INFO | oupCloseable-6-3 | StrictBGPPeerRegistry | 238 - org.opendaylight.bgpcep.bgp-rib-impl - 0.4.4.SNAPSHOT | BGP Open message session parameters differ, session still accepted.
2015-12-08 10:15:13,670 | INFO | oupCloseable-6-3 | BGPSessionImpl | 238 - org.opendaylight.bgpcep.bgp-rib-impl - 0.4.4.SNAPSHOT | BGP HoldTimer new value: 180
2015-12-08 10:15:13,671 | INFO | oupCloseable-6-3 | BGPPeer | 238 - org.opendaylight.bgpcep.bgp-rib-impl - 0.4.4.SNAPSHOT | Session with peer 10.30.32.55 went up with tables: [BgpTableTypeImpl [getAfi()=class org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.types.rev130919.Ipv4AddressFamily, getSafi()=class org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.types.rev130919.UnicastSubsequentAddressFamily]]
2015-12-08 10:15:13,673 | INFO | oupCloseable-6-3 | AbstractBGPSessionNegotiator | 238 - org.opendaylight.bgpcep.bgp-rib-impl - 0.4.4.SNAPSHOT | BGP Session with peer [id: 0x4249a7c0, /10.30.32.55:17900 => /10.30.32.60:1790] established successfully.
2015-12-08 10:15:23,691 | INFO | h for user karaf | command | 255 - org.apache.karaf.log.command - 3.0.3 | ROBOT MESSAGE: Starting test Check_Bgp_Peer_Updates_For_Reintroduced_Routes
2015-12-08 10:15:34,272 | INFO | h for user karaf | command | 255 - org.apache.karaf.log.command - 3.0.3 | ROBOT MESSAGE: Starting test BGP_Application_Peer_Delete_All_Routes
2015-12-08 10:15:34,572 | INFO | h for user karaf | command | 255 - org.apache.karaf.log.command - 3.0.3 | ROBOT MESSAGE: Starting test Wait_For_Stable_Topology_After_Deletion
2015-12-08 10:15:36,229 | INFO | oupCloseable-6-2 | BGPSessionImpl | 238 - org.opendaylight.bgpcep.bgp-rib-impl - 0.4.4.SNAPSHOT | Failed to send message Update [_attributes=Attributes [_asPath=AsPath{augmentations={}}, _clusterId=ClusterId{getCluster=[Ipv4Address [_value=40.40.40.40]], augmentations={}}, _localPref=LocalPref{getPref=100, augmentations={}}, _multiExitDisc=MultiExitDisc{getMed=0, augmentations={}}, _origin=Origin{getValue=Igp, augmentations={}}, _originatorId=OriginatorId{getOriginator=Ipv4Address [_value=41.41.41.41], augmentations={}}, augmentation=[Attributes2 [_mpUnreachNlri=MpUnreachNlri [_afi=class org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.types.rev130919.Ipv4AddressFamily, _safi=class org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.types.rev130919.UnicastSubsequentAddressFamily, _withdrawnRoutes=WithdrawnRoutes [_destinationType=DestinationIpv4Case [_destinationIpv4=DestinationIpv4 [_ipv4Prefixes=[Ipv4Prefixes [_prefix=Ipv4Prefix [_value=8.2.134.192/28], augmentation=[]]], augmentation=[]], augmentation=[]], augmentation=[]], augmentation=[]]]]], augmentation=[]] to socket java.nio.channels.ClosedChannelException
2015-12-08 10:15:36,230 | INFO | oupCloseable-6-2 | BGPSessionImpl | 238 - org.opendaylight.bgpcep.bgp-rib-impl - 0.4.4.SNAPSHOT | Failed to send message Update [_attributes=Attributes [_asPath=AsPath{augmentations={}}, _clusterId=ClusterId{getCluster=[Ipv4Address [_value=40.40.40.40]], augmentations={}}, _localPref=LocalPref{getPref=100, augmentations={}}, _multiExitDisc=MultiExitDisc{getMed=0, augmentations={}}, _origin=Origin{getValue=Igp, augmentations={}}, _originatorId=OriginatorId{getOriginator=Ipv4Address [_value=41.41.41.41], augmentations={}}, augmentation=[Attributes2 [_mpUnreachNlri=MpUnreachNlri [_afi=class org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.types.rev130919.Ipv4AddressFamily, _safi=class org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.types.rev130919.UnicastSubsequentAddressFamily, _withdrawnRoutes=WithdrawnRoutes [_destinationType=DestinationIpv4Case [_destinationIpv4=DestinationIpv4 [_ipv4Prefixes=[Ipv4Prefixes [_prefix=Ipv4Prefix [_value=12.0.43.160/28], augmentation=[]]], augmentation=[]], augmentation=[]], augmentation=[]], augmentation=[]]]]], augmentation=[]] to socket java.nio.channels.ClosedChannelException
BGP peer simulator log (play.py):
=================================
please see the total_received_withdrawn_prefix_counter: 35229 frozen for long time
https://jenkins.opendaylight.org/sandbox/job/bgpcep-csit-1node-periodic-bgp-ingest-only-stable-lithium/22/robot/report/log.html#s1-s2-t17-k4-k2
2015-12-08 10:15:14,039 INFO: Connecting in the talking mode.
2015-12-08 10:15:14,042 INFO: Connected to ODL.
2015-12-08 10:15:14,052 INFO: Open message received.
2015-12-08 10:15:14,053 INFO: Generator initialisation
2015-12-08 10:15:14,053 INFO: Target total number of prefixes to be introduced: 0
2015-12-08 10:15:14,053 INFO: Prefix base: 8.0.1.0/28
2015-12-08 10:15:14,053 INFO: My Autonomous System number: 64496
2015-12-08 10:15:14,053 INFO: My Hold Time: 180
2015-12-08 10:15:14,053 INFO: My BGP Identifier: 169746487
2015-12-08 10:15:14,053 INFO: Next Hop: 192.0.2.1
2015-12-08 10:15:14,053 INFO: Prefix count to be inserted at once: 1
2015-12-08 10:15:14,053 INFO: Prefix count to be withdrawn at once: 0
2015-12-08 10:15:14,054 INFO: Fast pre-fill up to 0 prefixes
2015-12-08 10:15:14,054 INFO: Remaining number of prefixes to be processed in parallel with withdrawals: 0
2015-12-08 10:15:14,054 INFO: Two separate UPDATEs will be generated for each NLRI & WITHDRAWN lists
2015-12-08 10:15:14,054 INFO: Let's go ...
2015-12-08 10:15:14,055 INFO: total_received_update_message_counter: 0
2015-12-08 10:15:14,055 INFO: total_received_nlri_prefix_counter: 0
2015-12-08 10:15:14,056 INFO: total_received_withdrawn_prefix_counter: 0
2015-12-08 10:15:15,763 INFO: ... idle for 1.707s
2015-12-08 10:15:15,763 INFO: total_rx_idle_time_counter: 1.707s
2015-12-08 10:15:24,023 INFO: total_received_update_message_counter: 50000
2015-12-08 10:15:24,024 INFO: total_received_nlri_prefix_counter: 50000
2015-12-08 10:15:24,024 INFO: total_received_withdrawn_prefix_counter: 0
2015-12-08 10:15:34,034 INFO: ... idle for 10.010s
2015-12-08 10:15:34,034 INFO: total_rx_idle_time_counter: 11.717s
2015-12-08 10:15:34,035 INFO: total_received_update_message_counter: 50000
2015-12-08 10:15:34,035 INFO: total_received_nlri_prefix_counter: 50000
2015-12-08 10:15:34,035 INFO: total_received_withdrawn_prefix_counter: 0
2015-12-08 10:15:44,045 INFO: ... idle for 10.010s
2015-12-08 10:15:44,045 INFO: total_rx_idle_time_counter: 21.727s
2015-12-08 10:15:44,046 INFO: total_received_update_message_counter: 50000
2015-12-08 10:15:44,046 INFO: total_received_nlri_prefix_counter: 50000
2015-12-08 10:15:44,046 INFO: total_received_withdrawn_prefix_counter: 0
2015-12-08 10:15:54,056 INFO: ... idle for 10.010s
2015-12-08 10:15:54,057 INFO: total_rx_idle_time_counter: 31.737s
2015-12-08 10:15:54,057 INFO: total_received_update_message_counter: 50000
2015-12-08 10:15:54,057 INFO: total_received_nlri_prefix_counter: 50000
2015-12-08 10:15:54,057 INFO: total_received_withdrawn_prefix_counter: 0
2015-12-08 10:16:04,067 INFO: ... idle for 10.010s
2015-12-08 10:16:04,068 INFO: total_rx_idle_time_counter: 41.748s
2015-12-08 10:16:04,068 INFO: total_received_update_message_counter: 50000
2015-12-08 10:16:04,068 INFO: total_received_nlri_prefix_counter: 50000
2015-12-08 10:16:04,068 INFO: total_received_withdrawn_prefix_counter: 0
2015-12-08 10:16:14,066 INFO: ... idle for 9.997s
2015-12-08 10:16:14,066 INFO: total_rx_idle_time_counter: 51.745s
2015-12-08 10:16:14,066 INFO: KEEP ALIVE is sent.
2015-12-08 10:16:14,066 INFO: total_received_update_message_counter: 50000
2015-12-08 10:16:14,066 INFO: total_received_nlri_prefix_counter: 50000
2015-12-08 10:16:14,066 INFO: total_received_withdrawn_prefix_counter: 0
2015-12-08 10:16:24,077 INFO: ... idle for 10.010s
2015-12-08 10:16:24,077 INFO: total_rx_idle_time_counter: 61.755s
2015-12-08 10:16:24,077 INFO: total_received_update_message_counter: 50000
2015-12-08 10:16:24,077 INFO: total_received_nlri_prefix_counter: 50000
2015-12-08 10:16:24,078 INFO: total_received_withdrawn_prefix_counter: 0
2015-12-08 10:16:34,088 INFO: ... idle for 10.010s
2015-12-08 10:16:34,088 INFO: total_rx_idle_time_counter: 71.765s
2015-12-08 10:16:34,088 INFO: total_received_update_message_counter: 50000
2015-12-08 10:16:34,089 INFO: total_received_nlri_prefix_counter: 50000
2015-12-08 10:16:34,089 INFO: total_received_withdrawn_prefix_counter: 0
2015-12-08 10:16:36,946 INFO: ... idle for 2.857s
2015-12-08 10:16:36,946 INFO: total_rx_idle_time_counter: 74.622s
2015-12-08 10:16:42,443 INFO: KEEP ALIVE message received: 0xffffffffffffffffffffffffffffffff001304
2015-12-08 10:16:42,444 INFO: total_received_update_message_counter: 85229
2015-12-08 10:16:42,444 INFO: total_received_nlri_prefix_counter: 50000
2015-12-08 10:16:42,444 INFO: total_received_withdrawn_prefix_counter: 35229
2015-12-08 10:16:52,454 INFO: ... idle for 10.010s
2015-12-08 10:16:52,455 INFO: total_rx_idle_time_counter: 84.632s
2015-12-08 10:16:52,455 INFO: total_received_update_message_counter: 85229
2015-12-08 10:16:52,455 INFO: total_received_nlri_prefix_counter: 50000
2015-12-08 10:16:52,455 INFO: total_received_withdrawn_prefix_counter: 35229
2015-12-08 10:17:02,465 INFO: ... idle for 10.010s
2015-12-08 10:17:02,466 INFO: total_rx_idle_time_counter: 94.643s
2015-12-08 10:17:02,466 INFO: total_received_update_message_counter: 85229
2015-12-08 10:17:02,466 INFO: total_received_nlri_prefix_counter: 50000
2015-12-08 10:17:02,466 INFO: total_received_withdrawn_prefix_counter: 35229
2015-12-08 10:17:12,476 INFO: ... idle for 10.009s
2015-12-08 10:17:12,476 INFO: total_rx_idle_time_counter: 104.652s
2015-12-08 10:17:12,476 INFO: total_received_update_message_counter: 85229
2015-12-08 10:17:12,476 INFO: total_received_nlri_prefix_counter: 50000
2015-12-08 10:17:12,476 INFO: total_received_withdrawn_prefix_counter: 35229
2015-12-08 10:17:14,068 INFO: ... idle for 1.592s
2015-12-08 10:17:14,069 INFO: total_rx_idle_time_counter: 106.244s
2015-12-08 10:17:14,069 INFO: KEEP ALIVE is sent.
2015-12-08 10:17:14,069 INFO: total_received_update_message_counter: 85229
2015-12-08 10:17:14,069 INFO: total_received_nlri_prefix_counter: 50000
2015-12-08 10:17:14,069 INFO: total_received_withdrawn_prefix_counter: 35229
2015-12-08 10:17:24,080 INFO: ... idle for 10.010s
2015-12-08 10:17:24,080 INFO: total_rx_idle_time_counter: 116.254s
2015-12-08 10:17:24,080 INFO: total_received_update_message_counter: 85229
2015-12-08 10:17:24,080 INFO: total_received_nlri_prefix_counter: 50000
2015-12-08 10:17:24,080 INFO: total_received_withdrawn_prefix_counter: 35229
2015-12-08 10:17:34,091 INFO: ... idle for 10.010s
2015-12-08 10:17:34,091 INFO: total_rx_idle_time_counter: 126.264s
2015-12-08 10:17:34,091 INFO: total_received_update_message_counter: 85229
2015-12-08 10:17:34,091 INFO: total_received_nlri_prefix_counter: 50000
2015-12-08 10:17:34,091 INFO: total_received_withdrawn_prefix_counter: 35229
2015-12-08 10:17:42,135 INFO: ... idle for 8.044s
2015-12-08 10:17:42,135 INFO: total_rx_idle_time_counter: 134.308s
2015-12-08 10:17:43,683 INFO: KEEP ALIVE message received: 0xffffffffffffffffffffffffffffffff001304
2015-12-08 10:17:43,683 INFO: total_received_update_message_counter: 95214
2015-12-08 10:17:43,683 INFO: total_received_nlri_prefix_counter: 50000
2015-12-08 10:17:43,684 INFO: total_received_withdrawn_prefix_counter: 45214
Traceback (most recent call last):
File "play.py", line 1580, in <module>
state.perform_one_loop_iteration()
File "play.py", line 1522, in perform_one_loop_iteration
self.reader.wait_for_read()
File "play.py", line 1355, in wait_for_read
select.select([self.socket], [], [self.socket], wait_timedelta)
KeyboardInterrupt
|