Skip to Content.
Sympa Menu

rare-dev - Re: [rare-dev] bf_fwd issues

Subject: Rare project developers

List archive

Re: [rare-dev] bf_fwd issues


Chronological Thread 
    < Chronological >      < Thread >
  • From: Alexander Gall <>
  • To: <>
  • Cc: "" <>, Vágó Tibor <>, Frédéric LOUI <>
  • Subject: Re: [rare-dev] bf_fwd issues
  • Date: Fri, 6 May 2022 16:41:54 +0200
On Fri, 6 May 2022 10:41:48 +0200, mc36 <> said:

> okkk,
> with these changes we got the profiler functionality:
> https://github.com/rare-freertr/freeRtr/commit/128c4b08055fc9a62d4196e2e1956d334efc2950
> https://github.com/rare-freertr/freeRtr/commit/3bcf10d0785cb2069ca97a84f0f5696681889b6c
> alex, we'll need https://packages.debian.org/search?keywords=python3-yappi

Is this only for debugging or do you want to have the profiler added
permanently? Also, you seem to have it working on your test setup. Do
you actually still need me to do anything?

--
Alex

> br,
> cs


> On 5/5/22 23:04, mc36 wrote:
>> hi,
>> as you maybe already know, we're piloting to the 4k mpls lns use case
>> heavily...
>> at this point rare had no issues picking up them, and performing the
>> forwarding,
>> but today we performed some stress tests on the setup, especially flapping
>> the
>> cpes heavily, and we realized that this setup completely ruined the cpe
>> connectivity.
>> the bgp-lu with the lns came up as expected but the cpes had forwarding
>> issues...
>> after a bit later, even the interface counters frozen on the lns... at
>> this point
>> i unbinded the l2tp server from the vrf basically stopping the flap and
>> the box
>> slowly stabilized... finally those who were in, successfully brought up
>> the bgp-vpns
>> session through the lns... but it took a hour or so... :) looking at top
>> showed quickly
>> the bottleneck, bf_fwd ate 100% whereas bffwd was around 15% and i saw
>> nothing in the
>> "debug server p4 tx".. so here is my idea: some unknown series of events
>> rendered bffwd
>> to process the updates extremely slow... below you can see on (1), it was
>> barely able
>> to process 1.5mb of updates in 10 minutes... this box also holds about
>> ~5000 v4/v6 routes
>> from the nren core, and sending those after a killall -9 python3 took some
>> seconds (2)....
>> so we need a tool to be have some insight in such a case... java have
>> visualvm which can
>> attached any time, but, is there such a tool for python?
>> thanks,
>> cs
>>
>>
>>
>> 1)
>>
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:10:21 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1920400 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (5.96/0/0)
>> tcp 72704 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:10:30 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1920801 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (6.43/0/0)
>> tcp 56320 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:10:40 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1921503 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (10.18/0/0)
>> tcp 39936 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:11:37 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1835248 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (8.96/0/0)
>> tcp 48640 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:11:52 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1836080 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (21.43/0/0)
>> tcp 24064 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:12:03 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1837105 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (10.57/0/0)
>> tcp 7680 0 127.0.0.1:48386
>> 127.0.0.1:9080 ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:12:11 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1743543 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (1.57/0/0)
>> tcp 85760 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:12:25 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1744323 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (11.84/0/0)
>> tcp 69376 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:12:30 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1744557 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (7.65/0/0)
>> tcp 61184 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:12:35 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1744880 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (2.15/0/0)
>> tcp 52992 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:12:40 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1745270 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (25.60/0/0)
>> tcp 44800 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:13:16 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1651566 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (2.36/0/0)
>> tcp 71552 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:13:38 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1652877 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (2.26/0/0)
>> tcp 30592 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:14:10 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1589068 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (13.92/0/0)
>> tcp 40960 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:14:29 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1524427 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (0.10/0/1)
>> tcp 65536 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:16:34 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1269061 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (19.48/0/0)
>> tcp 32768 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:16:37 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1269139 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (17.27/0/0)
>> tcp 32768 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:18:47 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1144975 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (0.00/0/0)
>> tcp 65536 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:18:56 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 1146015 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (11.47/0/0)
>> tcp 57344 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:20:07 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 822112 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (21.13/0/0)
>> tcp 16384 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:22:28 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 699144 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (25.84/0/0)
>> tcp 49152 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:23:11 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 701974 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (50.42/0/0)
>> tcp 16384 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:23:20 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 702416 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (42.17/0/0)
>> tcp 8192 0 127.0.0.1:48386
>> 127.0.0.1:9080 ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:24:11 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 0 640360 127.0.0.1:9080
>> 127.0.0.1:48386 ESTABLISHED probe (11.81/0/0)
>> tcp 32768 0 127.0.0.1:48386 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> mc36@stordis:~$
>>
>>
>>
>>
>> 2)
>>
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:57:16 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 19200 0 127.0.0.1:48416 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> tcp 0 181366 127.0.0.1:9080
>> 127.0.0.1:48416 ESTABLISHED probe (0.52/0/0)
>> tcp 0 0 127.0.0.1:48386
>> 127.0.0.1:9080 TIME_WAIT timewait (42.11/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:57:17 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 2816 0 127.0.0.1:48416
>> 127.0.0.1:9080 ESTABLISHED off (0.00/0/0)
>> tcp 0 181418 127.0.0.1:9080
>> 127.0.0.1:48416 ESTABLISHED probe (2.90/0/0)
>> tcp 0 0 127.0.0.1:48386
>> 127.0.0.1:9080 TIME_WAIT timewait (41.00/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:57:18 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 71040 0 127.0.0.1:48416 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> tcp 0 85854 127.0.0.1:9080
>> 127.0.0.1:48416 ESTABLISHED probe (0.11/0/0)
>> tcp 0 0 127.0.0.1:48386
>> 127.0.0.1:9080 TIME_WAIT timewait (39.94/0/0)
>> mc36@stordis:~$ date ; netstat -ano | grep 9080
>> Thu 05 May 2022 10:57:20 PM CEST
>> tcp 0 0 0.0.0.0:9080
>> 0.0.0.0:* LISTEN off (0.00/0/0)
>> tcp 38272 0 127.0.0.1:48416 127.0.0.1:9080
>> ESTABLISHED off (0.00/0/0)
>> tcp 0 85906 127.0.0.1:9080
>> 127.0.0.1:48416 ESTABLISHED probe (1.53/0/0)
>> tcp 0 0 127.0.0.1:48386
>> 127.0.0.1:9080 TIME_WAIT timewait (38.62/0/0)
>> mc36@stordis:~$

Archive powered by MHonArc 2.6.19.

Top of Page