Hi Felix,
Are there any documents on OVN troubleshooting the way you explain? LIke
what logs to look at, what tools to use to dump perf data and tech support
style data to drill down the issue before we report to developers. I
heard in the past related ovn-controller CPU usage 100% etc. But there is
no better way to find out what causes those spikes and errors.
On Thu, Jan 2, 2025 at 9:48 AM Felix Huettner via discuss <
ovs-discuss@openvswitch.org> wrote:
> On Thu, Jan 02, 2025 at 08:47:34AM -0300, Tiago Pires via discuss wrote:
> > Hi all,
> >
> > While creating ovn interconnect logical flows (Transit switch, LRPs
> > and LSPs) for a Logical Router in an AZ, there is load spike in all
> > chassis's ovn-controllers to 100%.
> > This remains for 1 minute and half and returns to normal after the
> > logical flows are installed.
> > Since this behavior only manifests itself while creating ovn
> > interconnect logical flows, enabling the debug logs shows that the
> > ovn-controller receives from SB the following change:
> >
> >
> 2024-12-26T17:38:15.023Z|10562646|inc_proc_eng|DBG|lib/inc-proc-eng.c:379:
> > node: SB_encap, old_state Unchanged, new_state Stale
> >
> 2024-12-26T17:38:15.023Z|10562647|inc_proc_eng|DBG|lib/inc-proc-eng.c:379:
> > node: mff_ovn_geneve, old_state Unchanged, new_state Stale
> >
> 2024-12-26T17:38:15.023Z|10562648|inc_proc_eng|DBG|lib/inc-proc-eng.c:379:
> > node: physical_flow_output, old_state Unchanged, new_state Stale
> >
> 2024-12-26T17:38:15.023Z|10562649|inc_proc_eng|DBG|lib/inc-proc-eng.c:379:
> > node: flow_output, old_state Unchanged, new_state Stale
> > 2024-12-26T17:38:15.032Z|10562650|jsonrpc|DBG|ssl:1XX.XX.XX.X16:6642:
> > received notification, method="update3",
> >
> params=[["monid","OVN_Southbound"],"9c54ec46-83a4-4deb-877d-3089a99ae482",{"SB_Global
> >
> ":{"019c4225-e637-4881-b382-36fdfcb9e0c9":{"modify":{"nb_cfg":34448}}},"Port_Binding":{"4230d38a-75cd-4f1c-9fde-62e753958656":{"insert":{"up":false,"tunnel_key":7,"mac":"16:00:01:f4:03:cb
> > 169.254 .30.3/24
> >
> fe80:30::3/64","datapath":["uuid","e84addb8-efdd-48bc-8454-8dd76a4a5a19"],"logical_port":"bd7bae47-2482-41cc-9486-e66f9d7b25bf-lrp-793b8","type":"patch"}},"f4d71615-88b8-4274-87ab-448cf8
> > c6a6ee":{"insert":{"up":false,"tunnel_key":6,"mac":"16:00:01:75:f8:87
> > 169.254.10.1/24
> >
> fe80:10::1/64","datapath":["uuid","e84addb8-efdd-48bc-8454-8dd76a4a5a19"],"logical_port":"bd7bae47-2482-41cc-
> >
> 9486-e66f9d7b25bf-lrp-ba453","type":"patch"}},"3eac57dd-386c-43b0-bf5b-8225941b52cb":{"insert":{"up":false,"tunnel_key":5,"mac":"16:00:01:9a:30:fa
> > 169.254.40.4/24 fe80:40::4/64","datapath":["uuid
> >
> ","e84addb8-efdd-48bc-8454-8dd76a4a5a19"],"logical_port":"bd7bae47-2482-41cc-9486-e66f9d7b25bf-lrp-36ac0","type":"patch"}},"7295d5c6-ff8d-4f4f-b1a5-eb1ca87fcb7d":{"insert":{"up":false,"tunnel_key
> > ":8,"mac":"16:00:01:de:df:b5 169.254.20.2/24
> >
> fe80:20::2/64","datapath":["uuid","e84addb8-efdd-48bc-8454-8dd76a4a5a19"],"logical_port":"bd7bae47-2482-41cc-9486-e66f9d7b25bf-lrp-c21c6","type":"patc
> >
> h"}}},"Logical_Flow":{"224852f2-9a46-4569-b51d-5d340ed6f4b4":{"modify":{"logical_dp_group":["uuid","bd825723-9a0e-451c-b5ad-b7d6f9cc75e4"]}},"05f5d515-bccf-47c1-9d55-8a4dfce88822":{"insert":{"pip
> > eline":"ingress","match":"inport ==
> > \"bd7bae47-2482-41cc-9486-e66f9d7b25bf-lrp-36ac0\" && ip6.dst ==
> >
> fe80::/64","priority":194,"logical_datapath":["uuid","e84addb8-efdd-48bc-8454-8dd76a4a5a19"],"
> > table_id":13,"actions":"ip.ttl--; reg8[0..15] = 0; xxreg0 = ip6.dst;
> > xxreg1 = fe80::1400:1ff:fe9a:30fa; eth.src = 16:00:01:9a:30:fa;
> > outport = \"bd7bae47-2482-41cc-9486-e66f9d7b25bf-lrp-36ac0\";
> > flags.loopback = 1;
> >
> next;"}},"c67ec1ee-bfc1-47e0-b35c-95fcc2adc13b":{"modify":{"logical_dp_group":
> >
> > The addresses from the above change (16:00:01:75:f8:87 169.254.10.1/24
> > fe80:10::1/64) are configured into the LRP connected to the transit
> > switch.
> >
> > After while another incremental processing is started:
> >
> > 2024-12-26T17:38:18.035Z|11190795|coverage|INFO|Skipping details of
> > duplicate event coverage for hash=db09e857
> > 2024-12-26T17:38:18.035Z|11190796|poll_loop|DBG|wakeup due to [POLLIN]
> > on fd 3 (1XX.XX.XX.X99:47382<->1XX.XX.XX.X16:6642) at
> > lib/stream-ssl.c:842 (100% CPU usage)
> > 2024-12-26T17:38:18.035Z|11190797|inc_proc_eng|DBG|Initializing new
> > run
> 2024-12-26T17:38:18.035Z|11190798|inc_proc_eng|DBG|lib/inc-proc-eng.c:379:
> > node: SB_sb_global, old_state Updated, new_state Stale
> >
> 2024-12-26T17:38:18.035Z|11190799|inc_proc_eng|DBG|lib/inc-proc-eng.c:379:
> > node: northd_options, old_state Unchanged, new_state Stale
> >
> 2024-12-26T17:38:18.035Z|11190800|inc_proc_eng|DBG|lib/inc-proc-eng.c:379:
> > node: SB_dhcp_options, old_state Unchanged, new_state Stale
> >
> 2024-12-26T17:38:18.035Z|11190801|inc_proc_eng|DBG|lib/inc-proc-eng.c:379:
> > node: SB_dhcpv6_options, old_state Unchanged, new_state Stale
> >
> 2024-12-26T17:38:18.035Z|11190802|inc_proc_eng|DBG|lib/inc-proc-eng.c:379:
> > node: dhcp_options, old_state Unchanged, new_state Stale
> >
> 2024-12-26T17:38:18.035Z|11190803|inc_proc_eng|DBG|lib/inc-proc-eng.c:379:
> > node: SB_address_set, old_state Unchanged, new_state Stale
> >
> > In other chassis we observerd the recompute time increasing to 18secs:
> >
> > 2024-12-26T17:38:46.463Z|40096697|poll_loop|INFO|Dropped 72 log
> > messages in last 6 seconds (most recently, 0 seconds ago) due to
> > excessive rate 2024-12-26T17:38:46.463Z|40096698|poll_loop|INFO|wakeup
> > due to [POLLIN] on fd 26 (1XX.XX.XX.6:56350<->1XX.XX.XX.X16:6642) at
> > lib/stream-ssl.c:842 (99% CPU usage)
> > 2024-12-26T17:38:52.442Z|40096699|poll_loop|INFO|Dropped 72 log
> > messages in last 6 seconds (most recently, 0 seconds ago) due to
> > excessive rate 2024-12-26T17:38:52.442Z|40096700|poll_loop|INFO|wakeup
> > due to [POLLIN] on fd 26 (1XX.XX.XX.6:56350<->1XX.XX.XX.X16:6642) at
> > lib/stream-ssl.c:842 (102% CPU usage)
> > 2024-12-26T17:38:58.409Z|40096701|poll_loop|INFO|Dropped 72 log
> > messages in last 6 seconds (most recently, 0 seconds ago) due to
> > excessive rate 2024-12-26T17:38:58.409Z|40096702|poll_loop|INFO|wakeup
> > due to [POLLIN] on fd 26 (1XX.XX.XX.6:56350<->1XX.XX.XX.X16:6642) at
> > lib/stream-ssl.c:842 (101% CPU usage)
> > 2024-12-26T17:39:04.477Z|40096703|poll_loop|INFO|Dropped 72 log
> > messages in last 6 seconds (most recently, 0 seconds ago) due to
> > excessive rate 2024-12-26T17:39:04.477Z|40096704|poll_loop|INFO|wakeup
> > due to [POLLIN] on fd 26 (1XX.XX.XX.6:56350<->1XX.XX.XX.X16:6642) at
> > lib/stream-ssl.c:842 (98% CPU usage)
> > 2024-12-26T17:39:27.896Z|40096705|inc_proc_eng|INFO|node:
> > logical_flow_output, recompute (forced) took 18932ms
> > 2024-12-26T17:39:28.612Z|40096706|inc_proc_eng|INFO|node:
> > physical_flow_output, recompute (forced) took 670ms
> > 2024-12-26T17:39:30.614Z|40096707|timeval|WARN|Unreasonably long
> > 22134ms poll interval (19780ms user, 2315ms system)
> > 2024-12-26T17:39:30.614Z|40096708|timeval|WARN|faults: 2634558 minor,
> > 0 major 2024-12-26T17:39:30.614Z|40096709|timeval|WARN|disk: 0 reads,
> > 8 writes 2024-12-26T17:39:30.614Z|40096710|timeval|WARN|context
> > switches: 0 voluntary, 2688 involuntary
> >
> > This behavior only happens with ovn interconnect logical flows, do you
> > know any known issue regarding it?
>
> Hi Tiago,
>
> from the log above it seems like some part of the previous incremental
> processing run failed and caused a recompute afterwards. So the last
> logs are no longer incrementally processed.
>
> There should be some log line in between similar to "...forcing recompute
> next time...". That might help you find the cause of the recompute.
>
> Additionally you should be able to trigger a recompute manually with
> "ovn-appctl inc-engine/recompute". Then you will probably observe
> similar logs.
> You could then attach a perf to the ovn-controller for one or more
> recomputes and use "perf record" and "perf report" with call graphs to
> figure out what exactly takes long. That might be helpful information
> for further optimizations.
>
> Also ovn got significant improvements in incremental processing since
> 23.03, so an upgrade might help as well.
>
> Hope that helps
> Felix
>
>
> >
> > #Versions in use
> >
> > $ ovn-nbctl -V
> > ovn-nbctl 23.03.1
> > Open vSwitch Library 3.1.3
> > DB Schema 7.0.0
> >
> > $ ovs-vsctl -V
> > ovs-vsctl (Open vSwitch) 3.1.3
> > DB Schema 8.3.1
> >
> > external_ids: ovn-monitor-all="true",
> > ovn-ofctrl-wait-before-clear="10000", ovn-openflow-probe-interval="0",
> > ovn-remote-probe-interval="180000"
> >
> > Regards,
> >
> > Tiago Pires
> >
> > --
> >
> >
> >
> >
> > _‘Esta mensagem é direcionada apenas para os endereços constantes no
> > cabeçalho inicial. Se você não está listado nos endereços constantes no
> > cabeçalho, pedimos-lhe que desconsidere completamente o conteúdo dessa
> > mensagem e cuja cópia, encaminhamento e/ou execução das ações citadas
> estão
> > imediatamente anuladas e proibidas’._
> >
> >
> > * **‘Apesar do Magazine Luiza tomar
> > todas as precauções razoáveis para assegurar que nenhum vírus esteja
> > presente nesse e-mail, a empresa não poderá aceitar a responsabilidade
> por
> > quaisquer perdas ou danos causados por esse e-mail ou por seus anexos’.*
> >
> >
> >
> > _______________________________________________
> > discuss mailing list
> > disc...@openvswitch.org
> > https://mail.openvswitch.org/mailman/listinfo/ovs-discuss
> _______________________________________________
> discuss mailing list
> disc...@openvswitch.org
> https://mail.openvswitch.org/mailman/listinfo/ovs-discuss
>
_______________________________________________
discuss mailing list
disc...@openvswitch.org
https://mail.openvswitch.org/mailman/listinfo/ovs-discuss
