Page MenuHomeVyOS Platform

Something is fishy with commit and boot times when more than a few hundred static routes are being used
Open, NormalPublicBUG

Description

Commit times during configuration mode but also during boot increases ALOT when more than a few hundred static routes are being used.

Using 1.4-rolling-202307200317 the commit times with 1024 static routes loaded took about 1 minute when changing "set firewall all-ping disable" (normally takes 3-4 seconds with only a handful of static routes).

Boot time increased from less than 1 minute to more than 5 minutes.

With a few static routes (timestamps as seen in console during boot):

  1. vyos-router[xxx]: Waiting for NICs to settle down: settled in 1secs…: 24.89 sec
  2. vyos-router[xxx]: Mounting VyOS Config…done.: 31.07 sec
  3. vyos-router[xxx]: Starting VyOS router: migrate configure.: 49.12 sec
  4. vyos-config[xxx]: Configuration success: 49.34 sec

With 1024 static routes added:

  1. vyos-router[xxx]: Waiting for NICs to settle down: settled in 1secs…: 29.85 sec
  2. vyos-router[xxx]: Mounting VyOS Config…done.: 36.06 sec
  3. vyos-router[xxx]: Starting VyOS router: migrate configure.: 306.76 sec
  4. vyos-config[xxx]: Configuration success: 306.77 sec

In this particular case the VyOS is being runned in Virtualbox on a Ubuntu host with 2 VCPU configured and 8GB of RAM.

Host CPU is: Intel(R) Core(TM) i5-4250U CPU.

The ones to blame seems to be a combo of:

root@vyos:/home/vyos# ps auxwww | grep -i union
root 3046 13.7 0.0 299624 2772 ? Ssl 04:04 0:31 unionfs-fuse -o cow -o allow_other /opt/vyatta/config/tmp/changes_only_3030=RW:/opt/vyatta/config/active=RO /opt/vyatta/config/tmp/new_config_3030

and /usr/lib/frr/staticd who both take alot of time both during injection and commit.

Script used to inject static routes:

#!/bin/vbash

# Include VyOS functions
source /opt/vyatta/etc/functions/script-template

# Script debugging
#set -x

# Set variables
GATEWAY=192.168.1.254
OCTET_A_START=0
OCTET_A_END=0
OCTET_B_START=0
OCTET_B_END=0
OCTET_C_START=0
OCTET_C_END=3
OCTET_D_START=0
OCTET_D_END=255

# Inject configuration
configure
for OCTET_A in `seq ${OCTET_A_START} ${OCTET_A_END}`
do
	for OCTET_B in `seq ${OCTET_B_START} ${OCTET_B_END}`
	do
		for OCTET_C in `seq ${OCTET_C_START} ${OCTET_C_END}`
		do
			for OCTET_D in `seq ${OCTET_D_START} ${OCTET_D_END}`
			do
				echo "set vrf name INTERNET protocols static route ${OCTET_A}.${OCTET_B}.${OCTET_C}.${OCTET_D}/32 next-hop ${GATEWAY} distance 1"
				set vrf name INTERNET protocols static route ${OCTET_A}.${OCTET_B}.${OCTET_C}.${OCTET_D}/32 next-hop ${GATEWAY} distance 1
			done
		done
	done
done
commit
exit

Forum thread available at: https://forum.vyos.io/t/very-long-time-commit/11596/

Details

Difficulty level
Unknown (require assessment)
Version
1.4-rolling-202307200317
Why the issue appeared?
Will be filled on close
Is it a breaking change?
Unspecified (possibly destroys the router)
Issue type
Bug (incorrect behavior)

Event Timeline

Long commit time does not depend on the number of static routes, but on a size of the configuration or number of lines in the configuration. If a router has a large configuration (not necessarily static routes), committing any changes takes several minutes.

But they shouldnt take several minutes and this alone can be a reason for why not putting VyOS into production.

"Large" amount of static routes is just a reproducable testcase that shows that commit of the VyOS config have methods and procedures that should be updated to better deal with larger commits.

For example why is unionfs-fuse (usermode) being used instead of overlayfs (kernelmode) during commits?

For the case of static routes are they injected as a batch (--tcli, transactional cli) to frr/staticd (or for that matter updating the configuration file of frr/staticd and then restart the staticd daemon) or one by one (which would also explain long commit times when static routes are involved)?

Doing some more digging it turned out that VyOS doesnt support nested routing so the gateway must be reachable (at least IP-address wise) through a physical interface - I have updated the script in the original post to adjust for that (added variable GATEWAY).

This way one can verify that whatever staticd is digesting do show up in the kernel (when in bash mode):

ip route show vrf INTERNET

I also verified that when altering /run/frr/config/frr.conf (NOTE: this will be recreated next time you commit config or reboot the device) and having staticd reloaded (couldnt figure out which systemctl command to use so I just did "kill -9 <pid>" on the staticd pid and watchfrr would then within a few seconds respawn the staticd process) staticd would digest all 1024 routes within a second or so.

So part of the long commit/boot times would be to change however static routes are being loaded so they instead will be loaded in a batch fashion.

That is generate the /run/frr/config/frr.conf file and then have frr reload all its processes and estimated 20% or so of the commit/boot times would be cut.

This still leaves us with what it is that takes the other +80% of the commit/boot times (that unionfs-fuse thingy seen through "ps auxwww").

Attempted some debugging on this issue.

Edited /usr/libexec/vyos/conf_mode/protocols_static.py by adding:

import timeit

...

def get_config(config=None):
    TIMEIT_START = timeit.default_timer()
    ...
    print("TIMEIT:protocols_static.py:get_config: ", timeit.default_timer() - TIMEIT_START)
    return static

def verify(static):
    TIMEIT_START = timeit.default_timer()
    ...
    print("TIMEIT:protocols_static.py:verify: ", timeit.default_timer() - TIMEIT_START)
    return None

def generate(static):
    TIMEIT_START = timeit.default_timer()
    ...
    print("TIMEIT:protocols_static.py:generate: ", timeit.default_timer() - TIMEIT_START)
    return None

def apply(static):
    TIMEIT_START = timeit.default_timer()
    ...
    print("TIMEIT:protocols_static.py:apply: ", timeit.default_timer() - TIMEIT_START)
    return None

Also edited /usr/libexec/vyos/services/vyos-configd by doing the similar as above but without the timing.

That is just added a print in each function to better trace which function is being called or not:

print("VYOS-CONFIGD:run_script")
...
print("VYOS-CONFIGD:initialization")
...
print("VYOS-CONFIGD:process_node_data")
...
print("VYOS-CONFIGD:while")
...
print("VYOS-CONFIGD:while:type_init")
...
print("VYOS-CONFIGD:while:type_node")
...
print("VYOS-CONFIGD:while:type_else")

Then restarted the vyos-configd service:

systemctl restart vyos-configd.service

Running inject.sh (with 50 static routes) gives following output:

root@vyos:~# time /config/custom/inject.sh
set vrf name INTERNET protocols static route 0.0.0.1/32 next-hop 192.168.1.254 distance 1
set vrf name INTERNET protocols static route 0.0.0.2/32 next-hop 192.168.1.254 distance 1
...
set vrf name INTERNET protocols static route 0.0.0.49/32 next-hop 192.168.1.254 distance 1
set vrf name INTERNET protocols static route 0.0.0.50/32 next-hop 192.168.1.254 distance 1
VYOS-CONFIGD:run_script
TIMEIT:protocols_static.py:get_config:  0.012246656999991501
TIMEIT:protocols_static.py:verify:  0.00019919900000786583
TIMEIT:protocols_static.py:generate:  0.0028339360000018132
TIMEIT:protocols_static.py:apply:  1.1426793219999922

real	0m19.519s
user	0m6.730s
sys	0m7.016s

Running deinject.sh (which removes the above 50 static routes) gives following output:

root@vyos:~# time /config/custom/deinject.sh
...
VYOS-CONFIGD:run_script
TIMEIT:protocols_static.py:get_config:  0.012219625000000178
TIMEIT:protocols_static.py:verify:  2.26129999987279e-05
TIMEIT:protocols_static.py:generate:  0.0010247849999984737
TIMEIT:protocols_static.py:apply:  0.8094521840000084

real	0m10.723s
user	0m3.599s
sys	0m3.540s

A regular boot on this testsystem completes in about 56 seconds.

With above 50 static routes added it took 62 seconds to complete the boot.

Output of /tmp/vyos-configd-script-stdout:

#cat /tmp/vyos-configd-script-stdout
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
Adapter does not support changing large-receive-offload settings!
VYOS-CONFIGD:run_script
Adapter does not support changing large-receive-offload settings!
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
Adapter does not support changing large-receive-offload settings!
VYOS-CONFIGD:run_script
Adapter does not support changing large-receive-offload settings!
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
TIMEIT:protocols_static.py:get_config:  0.009371553999997673
TIMEIT:protocols_static.py:verify:  0.00011678700000317122
TIMEIT:protocols_static.py:generate:  0.03998458599999566
TIMEIT:protocols_static.py:apply:  1.1233115180000013
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script
VYOS-CONFIGD:run_script

So it seems that the thing to blame is at least not protocols_static.py which is only being runned once and seem to behave as expected (could probably still be tweaked but its in the range of a few second(s)).

Which gives that whats going mayhem in terms of commit and boot times is located somewhere else.

Could it be /bin/cli-shell-api itself?

Continued debugging by also modifying /usr/libexec/vyos/services/vyos-configd by adding:

import timeit
TIMEIT_START = timeit.default_timer()
...
def run_script(script, config, args) -> int:
    print("VYOS-CONFIGD:run_script_begin: ", timeit.default_timer() - TIMEIT_START)
    ...
    try:
        print("VYOS-CONFIGD:run_script_try: ", script)
        ...
    except ConfigError as e:
        ...
    except Exception as e:
        ...
    print("VYOS-CONFIGD:run_script_end: ", timeit.default_timer() - TIMEIT_START)
    return R_SUCCESS

Output of /tmp/vyos-configd-script-stdout without static routes (well only the one default route), boot time approx 56 seconds:

#cat /tmp/vyos-configd-script-stdout
VYOS-CONFIGD:run_script_begin:  10.810446759999998                                                                     
VYOS-CONFIGD:run_script_try:  <module 'host_name' from '/usr/libexec/vyos//conf_mode/host_name.py'>                    
VYOS-CONFIGD:run_script_end:  10.879444450000001                                                                       
VYOS-CONFIGD:run_script_begin:  11.243645180000001                                                                     
VYOS-CONFIGD:run_script_try:  <module 'system_timezone' from '/usr/libexec/vyos//conf_mode/system-timezone.py'>        
VYOS-CONFIGD:run_script_end:  11.280752200999999                                                                       
VYOS-CONFIGD:run_script_begin:  11.306388470000002                                                                     
VYOS-CONFIGD:run_script_try:  <module 'system_console' from '/usr/libexec/vyos//conf_mode/system_console.py'>          
VYOS-CONFIGD:run_script_end:  11.810086982999998                                                                       
VYOS-CONFIGD:run_script_begin:  13.135635272000002                                                                     
VYOS-CONFIGD:run_script_begin:  14.367748921                                                                           
VYOS-CONFIGD:run_script_try:  <module 'conntrack' from '/usr/libexec/vyos//conf_mode/conntrack.py'>                    
VYOS-CONFIGD:run_script_end:  14.468633656999998                                                                       
VYOS-CONFIGD:run_script_begin:  14.489162141999998                                                                     
VYOS-CONFIGD:run_script_try:  <module 'system_ipv6' from '/usr/libexec/vyos//conf_mode/system-ipv6.py'>                
VYOS-CONFIGD:run_script_end:  14.971548028                                                                             
VYOS-CONFIGD:run_script_begin:  14.992493863                                                                           
VYOS-CONFIGD:run_script_try:  <module 'system_ip' from '/usr/libexec/vyos//conf_mode/system-ip.py'>                    
VYOS-CONFIGD:run_script_end:  15.408027343                                                                             
VYOS-CONFIGD:run_script_begin:  15.523509339999997                                                                     
VYOS-CONFIGD:run_script_try:  <module 'vrf' from '/usr/libexec/vyos//conf_mode/vrf.py'>                                
VYOS-CONFIGD:run_script_end:  16.303457398999996                                                                       
VYOS-CONFIGD:run_script_begin:  16.327718458                                                                           
VYOS-CONFIGD:run_script_try:  <module 'interfaces_loopback' from '/usr/libexec/vyos//conf_mode/interfaces-loopback.py'>
VYOS-CONFIGD:run_script_end:  16.476238926999997                                                                       
VYOS-CONFIGD:run_script_begin:  16.545494134000002                                                                     
VYOS-CONFIGD:run_script_try:  <module 'interfaces_ethernet' from '/usr/libexec/vyos//conf_mode/interfaces-ethernet.py'>
Adapter does not support changing large-receive-offload settings!                                                      
VYOS-CONFIGD:run_script_end:  16.790402178999997                                                                       
VYOS-CONFIGD:run_script_begin:  16.86466695                                                                            
VYOS-CONFIGD:run_script_try:  <module 'interfaces_ethernet' from '/usr/libexec/vyos//conf_mode/interfaces-ethernet.py'>
Adapter does not support changing large-receive-offload settings!                                                      
VYOS-CONFIGD:run_script_end:  17.065442570000002                                                                       
VYOS-CONFIGD:run_script_begin:  17.205136371000002                                                                     
VYOS-CONFIGD:run_script_try:  <module 'system_sysctl' from '/usr/libexec/vyos//conf_mode/system_sysctl.py'>            
VYOS-CONFIGD:run_script_end:  17.229681332                                                                             
VYOS-CONFIGD:run_script_begin:  17.303307959999998                                                                     
VYOS-CONFIGD:run_script_try:  <module 'interfaces_ethernet' from '/usr/libexec/vyos//conf_mode/interfaces-ethernet.py'>
Adapter does not support changing large-receive-offload settings!                                                      
VYOS-CONFIGD:run_script_end:  17.514118329                                                                                 
VYOS-CONFIGD:run_script_begin:  17.585613547                                                                               
VYOS-CONFIGD:run_script_try:  <module 'interfaces_ethernet' from '/usr/libexec/vyos//conf_mode/interfaces-ethernet.py'>    
Adapter does not support changing large-receive-offload settings!                                                          
VYOS-CONFIGD:run_script_end:  17.784969687                                                                             
VYOS-CONFIGD:run_script_begin:  18.442523168                                                                           
VYOS-CONFIGD:run_script_try:  <module 'system_syslog' from '/usr/libexec/vyos//conf_mode/system-syslog.py'>            
VYOS-CONFIGD:run_script_end:  18.920234189999995                                                                       
VYOS-CONFIGD:run_script_begin:  19.008130445999996                                                                     
VYOS-CONFIGD:run_script_try:  <module 'host_name' from '/usr/libexec/vyos//conf_mode/host_name.py'>                    
VYOS-CONFIGD:run_script_end:  19.076665276999996                                                                       
VYOS-CONFIGD:run_script_begin:  19.093803856                                                                           
VYOS-CONFIGD:run_script_try:  <module 'host_name' from '/usr/libexec/vyos//conf_mode/host_name.py'>                    
VYOS-CONFIGD:run_script_end:  19.163259820999997                                                                       
VYOS-CONFIGD:run_script_begin:  19.195938290999997                                                                     
VYOS-CONFIGD:run_script_try:  <module 'system_login_banner' from '/usr/libexec/vyos//conf_mode/system-login-banner.py'>
VYOS-CONFIGD:run_script_end:  19.196803369                                                                             
VYOS-CONFIGD:run_script_begin:  20.893047662                                                                           
TIMEIT:protocols_static.py:get_config:  0.0075951529999969125                                                          
VYOS-CONFIGD:run_script_try:  <module 'protocols_static' from '/usr/libexec/vyos//conf_mode/protocols_static.py'>      
TIMEIT:protocols_static.py:verify:  1.389400000562091e-05                                                              
TIMEIT:protocols_static.py:generate:  0.04035313099999627                                                              
TIMEIT:protocols_static.py:apply:  0.5889221110000022                                                                  
VYOS-CONFIGD:run_script_end:  21.530099100999998                                                                       
VYOS-CONFIGD:run_script_begin:  24.209474817999997                                                                     
VYOS-CONFIGD:run_script_try:  <module 'ntp' from '/usr/libexec/vyos//conf_mode/ntp.py'>                                
VYOS-CONFIGD:run_script_end:  24.93206147                                                                              
VYOS-CONFIGD:run_script_begin:  24.950765015                                                                           
VYOS-CONFIGD:run_script_try:  <module 'dhcpv6_server' from '/usr/libexec/vyos//conf_mode/dhcpv6_server.py'>            
VYOS-CONFIGD:run_script_end:  24.995545117                                                                             
VYOS-CONFIGD:run_script_begin:  25.013624328999995                                                                     
VYOS-CONFIGD:run_script_try:  <module 'service_router_advert' from '/usr/libexec/vyos//conf_mode/service_router-advert.py'>
VYOS-CONFIGD:run_script_end:  25.123546110999996                                                                           
VYOS-CONFIGD:run_script_begin:  25.14164435                                                                                
VYOS-CONFIGD:run_script_try:  <module 'dhcp_server' from '/usr/libexec/vyos//conf_mode/dhcp_server.py'>                    
VYOS-CONFIGD:run_script_end:  25.164572153                                                                                 
VYOS-CONFIGD:run_script_begin:  25.182628940999997                                                                         
VYOS-CONFIGD:run_script_try:  <module 'lldp' from '/usr/libexec/vyos//conf_mode/lldp.py'>                                  
VYOS-CONFIGD:run_script_end:  25.273275784                                                                                 
VYOS-CONFIGD:run_script_begin:  25.53734548                                                                                
VYOS-CONFIGD:run_script_try:  <module 'ssh' from '/usr/libexec/vyos//conf_mode/ssh.py'>                                    
VYOS-CONFIGD:run_script_end:  26.184768411                                                                                 
VYOS-CONFIGD:run_script_begin:  27.306124353                                                                               
VYOS-CONFIGD:run_script_try:  <module 'system_option' from '/usr/libexec/vyos//conf_mode/system-option.py'>                
VYOS-CONFIGD:run_script_end:  30.372170951999998

Adding 200 static routes:

TIMEIT:protocols_static.py:get_config:  0.02207272999999077
TIMEIT:protocols_static.py:verify:  0.0006020580000267728
TIMEIT:protocols_static.py:generate:  0.010337683999978253
TIMEIT:protocols_static.py:apply:  3.877477278000015

real	1m5.663s
user	0m24.879s
sys	0m25.156s

Reboot increased from about 56 seconds to 84 seconds:

#cat /tmp/vyos-configd-script-stdout
VYOS-CONFIGD:run_script_begin:  18.726243765999996
VYOS-CONFIGD:run_script_try:  <module 'host_name' from '/usr/libexec/vyos//conf_mode/host_name.py'>
VYOS-CONFIGD:run_script_end:  18.798971103
VYOS-CONFIGD:run_script_begin:  19.152930014999995
VYOS-CONFIGD:run_script_try:  <module 'system_timezone' from '/usr/libexec/vyos//conf_mode/system-timezone.py'>
VYOS-CONFIGD:run_script_end:  19.187117711999996
VYOS-CONFIGD:run_script_begin:  19.212101175
VYOS-CONFIGD:run_script_try:  <module 'system_console' from '/usr/libexec/vyos//conf_mode/system_console.py'>
VYOS-CONFIGD:run_script_end:  19.692861612999998
VYOS-CONFIGD:run_script_begin:  23.415672379
VYOS-CONFIGD:run_script_begin:  26.912587295
VYOS-CONFIGD:run_script_try:  <module 'conntrack' from '/usr/libexec/vyos//conf_mode/conntrack.py'>
VYOS-CONFIGD:run_script_end:  27.019585714999998
VYOS-CONFIGD:run_script_begin:  27.040607504999997
VYOS-CONFIGD:run_script_try:  <module 'system_ipv6' from '/usr/libexec/vyos//conf_mode/system-ipv6.py'>
VYOS-CONFIGD:run_script_end:  27.503235157999995
VYOS-CONFIGD:run_script_begin:  27.525897743999998
VYOS-CONFIGD:run_script_try:  <module 'system_ip' from '/usr/libexec/vyos//conf_mode/system-ip.py'>
VYOS-CONFIGD:run_script_end:  27.933882779999998
VYOS-CONFIGD:run_script_begin:  28.052068213999995
VYOS-CONFIGD:run_script_try:  <module 'vrf' from '/usr/libexec/vyos//conf_mode/vrf.py'>
VYOS-CONFIGD:run_script_end:  28.846978459
VYOS-CONFIGD:run_script_begin:  28.873068544
VYOS-CONFIGD:run_script_try:  <module 'interfaces_loopback' from '/usr/libexec/vyos//conf_mode/interfaces-loopback.py'>
VYOS-CONFIGD:run_script_end:  29.010165162999996
VYOS-CONFIGD:run_script_begin:  29.08565859
VYOS-CONFIGD:run_script_try:  <module 'interfaces_ethernet' from '/usr/libexec/vyos//conf_mode/interfaces-ethernet.py'>
Adapter does not support changing large-receive-offload settings!
VYOS-CONFIGD:run_script_end:  29.312797157
VYOS-CONFIGD:run_script_begin:  29.393148052
VYOS-CONFIGD:run_script_try:  <module 'interfaces_ethernet' from '/usr/libexec/vyos//conf_mode/interfaces-ethernet.py'>
Adapter does not support changing large-receive-offload settings!
VYOS-CONFIGD:run_script_end:  29.590058651
VYOS-CONFIGD:run_script_begin:  29.736225392
VYOS-CONFIGD:run_script_try:  <module 'system_sysctl' from '/usr/libexec/vyos//conf_mode/system_sysctl.py'>
VYOS-CONFIGD:run_script_end:  29.768532338
VYOS-CONFIGD:run_script_begin:  29.85514389
VYOS-CONFIGD:run_script_try:  <module 'interfaces_ethernet' from '/usr/libexec/vyos//conf_mode/interfaces-ethernet.py'>
Adapter does not support changing large-receive-offload settings!
VYOS-CONFIGD:run_script_end:  30.049165605999995
VYOS-CONFIGD:run_script_begin:  30.118185144999998
VYOS-CONFIGD:run_script_try:  <module 'interfaces_ethernet' from '/usr/libexec/vyos//conf_mode/interfaces-ethernet.py'>
Adapter does not support changing large-receive-offload settings!
VYOS-CONFIGD:run_script_end:  30.328637698                                                                             
VYOS-CONFIGD:run_script_begin:  31.979960829999996                                                                     
VYOS-CONFIGD:run_script_try:  <module 'system_syslog' from '/usr/libexec/vyos//conf_mode/system-syslog.py'>            
VYOS-CONFIGD:run_script_end:  32.484875472                                                                             
VYOS-CONFIGD:run_script_begin:  32.56745915                                                                            
VYOS-CONFIGD:run_script_try:  <module 'host_name' from '/usr/libexec/vyos//conf_mode/host_name.py'>                    
VYOS-CONFIGD:run_script_end:  32.635327                                                                                
VYOS-CONFIGD:run_script_begin:  32.652576118999995                                                                     
VYOS-CONFIGD:run_script_try:  <module 'host_name' from '/usr/libexec/vyos//conf_mode/host_name.py'>                    
VYOS-CONFIGD:run_script_end:  32.718611931                                                                             
VYOS-CONFIGD:run_script_begin:  32.753270729                                                                           
VYOS-CONFIGD:run_script_try:  <module 'system_login_banner' from '/usr/libexec/vyos//conf_mode/system-login-banner.py'>
VYOS-CONFIGD:run_script_end:  32.754111576999996                                                                       
VYOS-CONFIGD:run_script_begin:  40.897680537999996                                                                     
TIMEIT:protocols_static.py:get_config:  0.015755945999998744                                                           
VYOS-CONFIGD:run_script_try:  <module 'protocols_static' from '/usr/libexec/vyos//conf_mode/protocols_static.py'>      
TIMEIT:protocols_static.py:verify:  0.00039619600000406763                                                             
TIMEIT:protocols_static.py:generate:  0.04196425900000378                                                              
TIMEIT:protocols_static.py:apply:  4.022751331999999                                                                   
VYOS-CONFIGD:run_script_end:  44.978702930999994                                                                       
VYOS-CONFIGD:run_script_begin:  48.841757167000004                                                                     
VYOS-CONFIGD:run_script_try:  <module 'ntp' from '/usr/libexec/vyos//conf_mode/ntp.py'>                                
VYOS-CONFIGD:run_script_end:  49.601881935                                                                             
VYOS-CONFIGD:run_script_begin:  49.620059592                                                                           
VYOS-CONFIGD:run_script_try:  <module 'dhcpv6_server' from '/usr/libexec/vyos//conf_mode/dhcpv6_server.py'>            
VYOS-CONFIGD:run_script_end:  49.64023094499999                                                                        
VYOS-CONFIGD:run_script_begin:  49.657710547                                                                           
VYOS-CONFIGD:run_script_try:  <module 'service_router_advert' from '/usr/libexec/vyos//conf_mode/service_router-advert.py'>
VYOS-CONFIGD:run_script_end:  49.762974029                                                                                 
VYOS-CONFIGD:run_script_begin:  49.779962691                                                                               
VYOS-CONFIGD:run_script_try:  <module 'dhcp_server' from '/usr/libexec/vyos//conf_mode/dhcp_server.py'>                    
VYOS-CONFIGD:run_script_end:  49.798431224999995                                                                           
VYOS-CONFIGD:run_script_begin:  49.816787251                                                                               
VYOS-CONFIGD:run_script_try:  <module 'lldp' from '/usr/libexec/vyos//conf_mode/lldp.py'>                                  
VYOS-CONFIGD:run_script_end:  49.901903671999996                                                                           
VYOS-CONFIGD:run_script_begin:  50.160319695999995                                                                         
VYOS-CONFIGD:run_script_try:  <module 'ssh' from '/usr/libexec/vyos//conf_mode/ssh.py'>                                    
VYOS-CONFIGD:run_script_end:  50.840437198                                                                                 
VYOS-CONFIGD:run_script_begin:  52.716843755999996                                                                         
VYOS-CONFIGD:run_script_try:  <module 'system_option' from '/usr/libexec/vyos//conf_mode/system-option.py'>                
VYOS-CONFIGD:run_script_end:  55.89480316

That relates would seem reasonable. I'm seeing a similar explosion in commit lag but I have zero static routes. I did change to zone-based firewall and added about 6 vlans. Lines of my config went from ~500 to ~3000. Commit times increased almost linearly.

I can grab some times if that would be helpful..

Moving along in the blamegame I will after a tip try to disable the various validators being runned.

They can be seen here before compilation:

https://github.com/vyos/vyos-1x/blob/current/interface-definitions/protocols-static.xml.in

Or after compilation as node.def files at places such as (among other places):

/opt/vyatta/share/vyatta-cfg/templates/protocols/static
/opt/vyatta/share/vyatta-cfg/templates/vrf/name/node.tag/protocols/static

Because looking at the times without static routes the vyos-configd work is performed at timemark 10-30 seconds of the boot (approx 20 seconds in total).

While with 200 static routes the same operation is at timemark 18-55 seconds (approx 37 seconds in total).

Complete boot time with 200 static routes which is approx 84 seconds equals to (sort of):

original boot time + (diff between starttime for vyos-configd after minus before) + (diff between runtime for vyos-configd after minus before)

56 + (18-10) + ((55-18)-(30-10)) = 56 + 8 + 37 - 20 = 81 seconds which is close enough :-)

That is something takes additional 8 seconds before vyos-configd starts to do its work and vyos-configd itself will be approx 17 seconds slower with 200 static routes vs 1 static route.

Modifying node.def (comment out "syntax:expression:") recursively in the paths of:

/opt/vyatta/share/vyatta-cfg/templates/protocols/static
/opt/vyatta/share/vyatta-cfg/templates/vrf/name/node.tag/protocols/static

Shaved off 7 seconds from the boot time (76 seconds instead of 84 seconds):

#cat /tmp/vyos-configd-script-stdout
VYOS-CONFIGD:run_script_begin:  18.525269043999998                                                                     
VYOS-CONFIGD:run_script_try:  <module 'host_name' from '/usr/libexec/vyos//conf_mode/host_name.py'>        
VYOS-CONFIGD:run_script_end:  18.594439580999996                                                           
VYOS-CONFIGD:run_script_begin:  18.949239702                                                                           
VYOS-CONFIGD:run_script_try:  <module 'system_timezone' from '/usr/libexec/vyos//conf_mode/system-timezone.py'>
VYOS-CONFIGD:run_script_end:  18.987168798999996                                                           
VYOS-CONFIGD:run_script_begin:  19.012153692                                                                           
VYOS-CONFIGD:run_script_try:  <module 'system_console' from '/usr/libexec/vyos//conf_mode/system_console.py'>          
VYOS-CONFIGD:run_script_end:  19.472351859999996                                                           
VYOS-CONFIGD:run_script_begin:  21.741476257000002                                                               
VYOS-CONFIGD:run_script_try:  <module 'firewall' from '/usr/libexec/vyos//conf_mode/firewall.py'>          
VYOS-CONFIGD:run_script_begin:  24.294071455999998                                                         
VYOS-CONFIGD:run_script_try:  <module 'conntrack' from '/usr/libexec/vyos//conf_mode/conntrack.py'>
VYOS-CONFIGD:run_script_end:  24.398823967          
VYOS-CONFIGD:run_script_begin:  24.419568937999998                                                                     
VYOS-CONFIGD:run_script_try:  <module 'system_ipv6' from '/usr/libexec/vyos//conf_mode/system-ipv6.py'>
VYOS-CONFIGD:run_script_end:  24.85280442                                              
VYOS-CONFIGD:run_script_begin:  24.874327960000002
VYOS-CONFIGD:run_script_try:  <module 'system_ip' from '/usr/libexec/vyos//conf_mode/system-ip.py'>                    
VYOS-CONFIGD:run_script_end:  25.285795201                                                                 
VYOS-CONFIGD:run_script_begin:  25.318199479    
VYOS-CONFIGD:run_script_try:  <module 'vrf' from '/usr/libexec/vyos//conf_mode/vrf.py'>
VYOS-CONFIGD:run_script_end:  26.074309692                                                                                 
VYOS-CONFIGD:run_script_begin:  26.100471415999998
VYOS-CONFIGD:run_script_try:  <module 'interfaces_loopback' from '/usr/libexec/vyos//conf_mode/interfaces-loopback.py'>
VYOS-CONFIGD:run_script_end:  26.236048081                                                             
VYOS-CONFIGD:run_script_begin:  26.312604158999996
VYOS-CONFIGD:run_script_try:  <module 'interfaces_ethernet' from '/usr/libexec/vyos//conf_mode/interfaces-ethernet.py'>
Adapter does not support changing large-receive-offload settings!                                  
VYOS-CONFIGD:run_script_end:  26.551168945999997
VYOS-CONFIGD:run_script_begin:  26.62330384 
VYOS-CONFIGD:run_script_try:  <module 'interfaces_ethernet' from '/usr/libexec/vyos//conf_mode/interfaces-ethernet.py'>
Adapter does not support changing large-receive-offload settings!
VYOS-CONFIGD:run_script_end:  26.824133746999998  
VYOS-CONFIGD:run_script_begin:  27.010123372000002                                                               
VYOS-CONFIGD:run_script_try:  <module 'system_sysctl' from '/usr/libexec/vyos//conf_mode/system_sysctl.py'>
VYOS-CONFIGD:run_script_end:  27.043471679999996         
VYOS-CONFIGD:run_script_begin:  27.134908865              
VYOS-CONFIGD:run_script_try:  <module 'interfaces_ethernet' from '/usr/libexec/vyos//conf_mode/interfaces-ethernet.py'>
Adapter does not support changing large-receive-offload settings!
VYOS-CONFIGD:run_script_end:  27.321540759999998
VYOS-CONFIGD:run_script_begin:  27.393922879999998                                     
VYOS-CONFIGD:run_script_try:  <module 'interfaces_ethernet' from '/usr/libexec/vyos//conf_mode/interfaces-ethernet.py'>
Adapter does not support changing large-receive-offload settings!
VYOS-CONFIGD:run_script_end:  27.593953767000002                                                                       
VYOS-CONFIGD:run_script_begin:  29.436117891000002                                                                     
VYOS-CONFIGD:run_script_try:  <module 'system_syslog' from '/usr/libexec/vyos//conf_mode/system-syslog.py'>            
VYOS-CONFIGD:run_script_end:  29.932529052                                                                             
VYOS-CONFIGD:run_script_begin:  30.019748979999996                                                                     
VYOS-CONFIGD:run_script_try:  <module 'host_name' from '/usr/libexec/vyos//conf_mode/host_name.py'>                    
VYOS-CONFIGD:run_script_end:  30.088338772                                                                             
VYOS-CONFIGD:run_script_begin:  30.105249209999997                                                                     
VYOS-CONFIGD:run_script_try:  <module 'host_name' from '/usr/libexec/vyos//conf_mode/host_name.py'>                    
VYOS-CONFIGD:run_script_end:  30.176395753999998                                                                       
VYOS-CONFIGD:run_script_begin:  30.20746277                                                                            
VYOS-CONFIGD:run_script_try:  <module 'system_login_banner' from '/usr/libexec/vyos//conf_mode/system-login-banner.py'>
VYOS-CONFIGD:run_script_end:  30.208473828000002                                                                       
VYOS-CONFIGD:run_script_begin:  33.295797586999996                                                                         
VYOS-CONFIGD:run_script_try:  <module 'protocols_static' from '/usr/libexec/vyos//conf_mode/protocols_static.py'>      
TIMEIT:protocols_static.py:get_config:  0.015931811999998047                                                           
TIMEIT:protocols_static.py:verify:  0.0003653660000040304                                                              
TIMEIT:protocols_static.py:generate:  0.049397399000000064                                                             
TIMEIT:protocols_static.py:apply:  3.892500712999997                                                                   
VYOS-CONFIGD:run_script_end:  37.254181486                                                                             
VYOS-CONFIGD:run_script_begin:  40.904345369                                                                           
VYOS-CONFIGD:run_script_try:  <module 'ntp' from '/usr/libexec/vyos//conf_mode/ntp.py'>                                
VYOS-CONFIGD:run_script_end:  41.624672208999996                                                                       
VYOS-CONFIGD:run_script_begin:  41.643624009999996                                                                     
VYOS-CONFIGD:run_script_try:  <module 'dhcpv6_server' from '/usr/libexec/vyos//conf_mode/dhcpv6_server.py'>            
VYOS-CONFIGD:run_script_end:  41.662031063                                                                             
VYOS-CONFIGD:run_script_begin:  41.679832122                                                                           
VYOS-CONFIGD:run_script_try:  <module 'service_router_advert' from '/usr/libexec/vyos//conf_mode/service_router-advert.py'>
VYOS-CONFIGD:run_script_end:  41.791809956                                                                                 
VYOS-CONFIGD:run_script_begin:  41.807964969                                                                               
VYOS-CONFIGD:run_script_try:  <module 'dhcp_server' from '/usr/libexec/vyos//conf_mode/dhcp_server.py'>                    
VYOS-CONFIGD:run_script_end:  41.830856909                                                                                 
VYOS-CONFIGD:run_script_begin:  41.848238964                                                                               
VYOS-CONFIGD:run_script_try:  <module 'lldp' from '/usr/libexec/vyos//conf_mode/lldp.py'>                                  
VYOS-CONFIGD:run_script_end:  41.936486762                                                                                 
VYOS-CONFIGD:run_script_begin:  42.230533167                                                                               
VYOS-CONFIGD:run_script_try:  <module 'ssh' from '/usr/libexec/vyos//conf_mode/ssh.py'>                                    
VYOS-CONFIGD:run_script_end:  42.867986026000004                                                                           
VYOS-CONFIGD:run_script_begin:  45.25861186699999                                                                          
VYOS-CONFIGD:run_script_try:  <module 'system_option' from '/usr/libexec/vyos//conf_mode/system-option.py'>                
VYOS-CONFIGD:run_script_end:  48.480499333999994

Disabling all validators for both vyatta-cfg and vyatta-op bring the boot time down to approx 73 seconds.

Still way higher than the approx 56 seconds without any static routes, but lower than the 84 seconds with 200 static routes.

#cat /tmp/vyos-configd-script-stdout
VYOS-CONFIGD:run_script_begin:  17.418318160000002
VYOS-CONFIGD:run_script_try:  <module 'host_name' from '/usr/libexec/vyos//conf_mode/host_name.py'>
VYOS-CONFIGD:run_script_end:  17.485769191
VYOS-CONFIGD:run_script_begin:  17.508065821
VYOS-CONFIGD:run_script_try:  <module 'system_timezone' from '/usr/libexec/vyos//conf_mode/system-timezone.py'>
VYOS-CONFIGD:run_script_end:  17.651155008
VYOS-CONFIGD:run_script_begin:  17.671078108
VYOS-CONFIGD:run_script_try:  <module 'system_console' from '/usr/libexec/vyos//conf_mode/system_console.py'>
VYOS-CONFIGD:run_script_end:  18.155886527000003
VYOS-CONFIGD:run_script_begin:  19.785088172
VYOS-CONFIGD:run_script_try:  <module 'firewall' from '/usr/libexec/vyos//conf_mode/firewall.py'>
VYOS-CONFIGD:run_script_begin:  21.804374508
VYOS-CONFIGD:run_script_try:  <module 'conntrack' from '/usr/libexec/vyos//conf_mode/conntrack.py'>
VYOS-CONFIGD:run_script_end:  21.910536820999997
VYOS-CONFIGD:run_script_begin:  21.927631309000002
VYOS-CONFIGD:run_script_try:  <module 'system_ipv6' from '/usr/libexec/vyos//conf_mode/system-ipv6.py'>
VYOS-CONFIGD:run_script_end:  22.366587413999998
VYOS-CONFIGD:run_script_begin:  22.385354556
VYOS-CONFIGD:run_script_try:  <module 'system_ip' from '/usr/libexec/vyos//conf_mode/system-ip.py'>
VYOS-CONFIGD:run_script_end:  22.811346998
VYOS-CONFIGD:run_script_begin:  22.829712160000003
VYOS-CONFIGD:run_script_try:  <module 'vrf' from '/usr/libexec/vyos//conf_mode/vrf.py'>
VYOS-CONFIGD:run_script_end:  23.601457221
VYOS-CONFIGD:run_script_begin:  23.619948308999998
VYOS-CONFIGD:run_script_try:  <module 'interfaces_loopback' from '/usr/libexec/vyos//conf_mode/interfaces-loopback.py'>
VYOS-CONFIGD:run_script_end:  23.758412277999998
VYOS-CONFIGD:run_script_begin:  23.77630632
VYOS-CONFIGD:run_script_try:  <module 'interfaces_ethernet' from '/usr/libexec/vyos//conf_mode/interfaces-ethernet.py'>
Adapter does not support changing large-receive-offload settings!
VYOS-CONFIGD:run_script_end:  24.018829956
VYOS-CONFIGD:run_script_begin:  24.047540301
VYOS-CONFIGD:run_script_try:  <module 'interfaces_ethernet' from '/usr/libexec/vyos//conf_mode/interfaces-ethernet.py'>
Adapter does not support changing large-receive-offload settings!
VYOS-CONFIGD:run_script_end:  24.280592048
VYOS-CONFIGD:run_script_begin:  24.303461559000002
VYOS-CONFIGD:run_script_try:  <module 'system_sysctl' from '/usr/libexec/vyos//conf_mode/system_sysctl.py'>
VYOS-CONFIGD:run_script_end:  24.339641887000003
VYOS-CONFIGD:run_script_begin:  24.366281097999998
VYOS-CONFIGD:run_script_try:  <module 'interfaces_ethernet' from '/usr/libexec/vyos//conf_mode/interfaces-ethernet.py'>
Adapter does not support changing large-receive-offload settings!
VYOS-CONFIGD:run_script_end:  24.616201504
VYOS-CONFIGD:run_script_begin:  24.646442871999998
VYOS-CONFIGD:run_script_try:  <module 'interfaces_ethernet' from '/usr/libexec/vyos//conf_mode/interfaces-ethernet.py'>
Adapter does not support changing large-receive-offload settings!
VYOS-CONFIGD:run_script_end:  24.910821610000003                                                                       
VYOS-CONFIGD:run_script_begin:  26.944980132                                                                           
VYOS-CONFIGD:run_script_try:  <module 'system_syslog' from '/usr/libexec/vyos//conf_mode/system-syslog.py'>            
VYOS-CONFIGD:run_script_end:  27.413008287999997                                                                       
VYOS-CONFIGD:run_script_begin:  27.431501514                                                                           
VYOS-CONFIGD:run_script_try:  <module 'host_name' from '/usr/libexec/vyos//conf_mode/host_name.py'>                    
VYOS-CONFIGD:run_script_end:  27.50017333                                                                              
VYOS-CONFIGD:run_script_begin:  27.517527806999997                                                                     
VYOS-CONFIGD:run_script_try:  <module 'host_name' from '/usr/libexec/vyos//conf_mode/host_name.py'>                    
VYOS-CONFIGD:run_script_end:  27.58643237                                                                              
VYOS-CONFIGD:run_script_begin:  27.604186436000003                                                                     
VYOS-CONFIGD:run_script_try:  <module 'system_login_banner' from '/usr/libexec/vyos//conf_mode/system-login-banner.py'>
VYOS-CONFIGD:run_script_end:  27.605183960999998                                                                       
VYOS-CONFIGD:run_script_begin:  29.743588822000003                                                                     
VYOS-CONFIGD:run_script_try:  <module 'protocols_static' from '/usr/libexec/vyos//conf_mode/protocols_static.py'>      
TIMEIT:protocols_static.py:get_config:  0.015561939000001246                                                           
TIMEIT:protocols_static.py:verify:  0.0003611840000061761                                                              
TIMEIT:protocols_static.py:generate:  0.04073315800000188                                                              
TIMEIT:protocols_static.py:apply:  3.9014388180000026                                                                  
VYOS-CONFIGD:run_script_end:  33.701838374000005                                                                       
VYOS-CONFIGD:run_script_begin:  37.741800045999994                                                                     
VYOS-CONFIGD:run_script_try:  <module 'ntp' from '/usr/libexec/vyos//conf_mode/ntp.py'>                                
VYOS-CONFIGD:run_script_end:  38.501922320000006                                                                       
VYOS-CONFIGD:run_script_begin:  38.52415971800001                                                                      
VYOS-CONFIGD:run_script_try:  <module 'dhcpv6_server' from '/usr/libexec/vyos//conf_mode/dhcpv6_server.py'>            
VYOS-CONFIGD:run_script_end:  38.542166251                                                                             
VYOS-CONFIGD:run_script_begin:  38.561522778                                                                           
VYOS-CONFIGD:run_script_try:  <module 'service_router_advert' from '/usr/libexec/vyos//conf_mode/service_router-advert.py'>
VYOS-CONFIGD:run_script_end:  38.680827281000006                                                                           
VYOS-CONFIGD:run_script_begin:  38.697877719000005                                                                         
VYOS-CONFIGD:run_script_try:  <module 'dhcp_server' from '/usr/libexec/vyos//conf_mode/dhcp_server.py'>                    
VYOS-CONFIGD:run_script_end:  38.721091042                                                                                 
VYOS-CONFIGD:run_script_begin:  38.738674923999994                                                                         
VYOS-CONFIGD:run_script_try:  <module 'lldp' from '/usr/libexec/vyos//conf_mode/lldp.py'>                                  
VYOS-CONFIGD:run_script_end:  38.833144528999995                                                                           
VYOS-CONFIGD:run_script_begin:  38.864993287999994                                                                         
VYOS-CONFIGD:run_script_try:  <module 'ssh' from '/usr/libexec/vyos//conf_mode/ssh.py'>                                    
VYOS-CONFIGD:run_script_end:  39.594408184                                                                                 
VYOS-CONFIGD:run_script_begin:  41.20679968                                                                                
VYOS-CONFIGD:run_script_try:  <module 'system_option' from '/usr/libexec/vyos//conf_mode/system-option.py'>                
VYOS-CONFIGD:run_script_end:  44.45542422999999

Disable validators:

find /opt/vyatta/share/vyatta-cfg/templates -type f -name "node.def" -exec sed -i 's/syntax:expression:/#syntax:expression:/g' {} +
find /opt/vyatta/share/vyatta-op/templates -type f -name "node.def" -exec sed -i 's/syntax:expression:/#syntax:expression:/g' {} +

Enable validators:

find /opt/vyatta/share/vyatta-cfg/templates -type f -name "node.def" -exec sed -i 's/#syntax:expression:/syntax:expression:/g' {} +
find /opt/vyatta/share/vyatta-op/templates -type f -name "node.def" -exec sed -i 's/#syntax:expression:/syntax:expression:/g' {} +

Looking at the kernel configs from both arm and x86 arch:

https://github.com/vyos/vyos-build/blob/current/packages/linux-kernel/arch/arm64/configs/vyos_defconfig

CONFIG_SQUASHFS=m
CONFIG_SQUASHFS_FILE_CACHE=y
# CONFIG_SQUASHFS_FILE_DIRECT is not set
CONFIG_SQUASHFS_DECOMP_SINGLE=y
# CONFIG_SQUASHFS_DECOMP_MULTI is not set
# CONFIG_SQUASHFS_DECOMP_MULTI_PERCPU is not set
CONFIG_SQUASHFS_XATTR=y
CONFIG_SQUASHFS_ZLIB=y
# CONFIG_SQUASHFS_LZ4 is not set
CONFIG_SQUASHFS_LZO=y
CONFIG_SQUASHFS_XZ=y
# CONFIG_SQUASHFS_ZSTD is not set
# CONFIG_SQUASHFS_4K_DEVBLK_SIZE is not set
# CONFIG_SQUASHFS_EMBEDDED is not set
CONFIG_SQUASHFS_FRAGMENT_CACHE_SIZE=3

https://github.com/vyos/vyos-build/blob/current/packages/linux-kernel/arch/x86/configs/vyos_defconfig

CONFIG_SQUASHFS=m
CONFIG_SQUASHFS_FILE_CACHE=y
# CONFIG_SQUASHFS_FILE_DIRECT is not set
CONFIG_SQUASHFS_DECOMP_SINGLE=y
# CONFIG_SQUASHFS_DECOMP_MULTI is not set
# CONFIG_SQUASHFS_DECOMP_MULTI_PERCPU is not set
CONFIG_SQUASHFS_XATTR=y
CONFIG_SQUASHFS_ZLIB=y
CONFIG_SQUASHFS_LZ4=y
CONFIG_SQUASHFS_LZO=y
CONFIG_SQUASHFS_XZ=y
CONFIG_SQUASHFS_ZSTD=y
# CONFIG_SQUASHFS_4K_DEVBLK_SIZE is not set
# CONFIG_SQUASHFS_EMBEDDED is not set
CONFIG_SQUASHFS_FRAGMENT_CACHE_SIZE=3

Im thinking except that the above should be in sync with each other wouldnt a change from:

CONFIG_SQUASHFS_FILE_CACHE=y
# CONFIG_SQUASHFS_FILE_DIRECT is not set
CONFIG_SQUASHFS_DECOMP_SINGLE=y
# CONFIG_SQUASHFS_DECOMP_MULTI is not set
# CONFIG_SQUASHFS_DECOMP_MULTI_PERCPU is not set

into

#CONFIG_SQUASHFS_FILE_CACHE is not set
CONFIG_SQUASHFS_FILE_DIRECT=y
# CONFIG_SQUASHFS_DECOMP_SINGLE is not set
# CONFIG_SQUASHFS_DECOMP_MULTI is not set
CONFIG_SQUASHFS_DECOMP_MULTI_PERCPU=y

boost the read performance which would improve the current boot/commit situation?

Ref:

https://cateee.net/lkddb/web-lkddb/SQUASHFS_FILE_DIRECT.html

Directly decompress file data into the page cache. Doing so can significantly improve performance because it eliminates a memcpy and it also removes the lock contention on the single buffer.

https://cateee.net/lkddb/web-lkddb/SQUASHFS_DECOMP_MULTI_PERCPU.html

By default Squashfs uses a single decompressor but it gives poor performance on parallel I/O workloads when using multiple CPU machines due to waiting on decompressor availability.

This decompressor implementation uses a maximum of one decompressor per core. It uses percpu variables to ensure decompression is load-balanced across the cores.

Something else to consider is to increase the readcache of squashfs by changing this:

CONFIG_SQUASHFS_FRAGMENT_CACHE_SIZE=3

into for example this:

CONFIG_SQUASHFS_FRAGMENT_CACHE_SIZE=256

The above change would mean increase of squashfs memory usage from:

block_size * number_of_cached_fragments

3*256k = 768kbyte

to

256*256k = 65536kbyte = 64MB

Ref: https://elinux.org/images/3/32/Squashfs-elce.pdf (page 24)

Im guessing that what this task complains about has a huge part of the time it takes to complete smoketests.

Runned today time sudo make test:

real	111m46.879s
user	113m34.954s
sys	16m38.894s

I got some funny results which I hope somebody else (with a faster cpu) are able to verify?

The kernel config used for original VyOS (Linux LTS kernel 6.1.53) is available at:

https://github.com/vyos/vyos-build/blob/current/packages/linux-kernel/arch/x86/configs/vyos_defconfig

What I did was to change this:

CONFIG_SQUASHFS=m
CONFIG_SQUASHFS_FILE_CACHE=y
# CONFIG_SQUASHFS_FILE_DIRECT is not set
CONFIG_SQUASHFS_DECOMP_SINGLE=y
# CONFIG_SQUASHFS_DECOMP_MULTI is not set
# CONFIG_SQUASHFS_DECOMP_MULTI_PERCPU is not set
CONFIG_SQUASHFS_XATTR=y
CONFIG_SQUASHFS_ZLIB=y
CONFIG_SQUASHFS_LZ4=y
CONFIG_SQUASHFS_LZO=y
CONFIG_SQUASHFS_XZ=y
CONFIG_SQUASHFS_ZSTD=y
# CONFIG_SQUASHFS_4K_DEVBLK_SIZE is not set
# CONFIG_SQUASHFS_EMBEDDED is not set
CONFIG_SQUASHFS_FRAGMENT_CACHE_SIZE=3

Into this:

CONFIG_SQUASHFS=m
# CONFIG_SQUASHFS_FILE_CACHE is not set
CONFIG_SQUASHFS_FILE_DIRECT=y
# CONFIG_SQUASHFS_DECOMP_SINGLE is not set
# CONFIG_SQUASHFS_DECOMP_MULTI is not set
CONFIG_SQUASHFS_DECOMP_MULTI_PERCPU=y
CONFIG_SQUASHFS_XATTR=y
CONFIG_SQUASHFS_ZLIB=y
CONFIG_SQUASHFS_LZ4=y
CONFIG_SQUASHFS_LZO=y
CONFIG_SQUASHFS_XZ=y
CONFIG_SQUASHFS_ZSTD=y
CONFIG_SQUASHFS_4K_DEVBLK_SIZE=y
CONFIG_SQUASHFS_EMBEDDED=y
CONFIG_SQUASHFS_FRAGMENT_CACHE_SIZE=256

And then recompiled and built a new VyOS image, verified that the modified kernel config is used both by looking in the /boot/config-* but also the memory usage after boot and checked the date of the kernel being used (uname).

I booted the live image to compare boot times (see below).

Orig kernel:

Boot time:
20s
28s
49s

246M usage after boot (htop).

Time to run smoketests (sudo make test in docker):

real	111m46.879s
user	113m34.954s
sys	16m38.894s

Modified kernel:

Boot time:
17s
24s
45s

303M usage after boot (htop).

Time to run smoketests (sudo make test in docker):

real	120m21.881s
user	1m18.079s
sys	0m10.475s

Some highly unscientific tests (only did 3 reboots of each to rule out that any uncached data at the host would affect the result since I run this in a VM through VirtualBox 7.0) shows a difference of up to 2.1% improvment when having a config with 200 static routes.

That is a regular config didnt have much of a change (totalt boot time went from 62 to 61.5 seconds).

While the 200 static routes config had following boot times:

VyOS 1.5-rolling-202309190603 (default squashfs kernel settings): 24.1, 30.1, 85.7 seconds.

That is 85.7 seconds in total boot time.

Custom kernel (tweaked squashfs kernel settings): 23.6, 29.9, 83.9 seconds.

That is 83.9 seconds in total boot time.

Improvement of 1.8 seconds or about 2.1%.

For production using a 256 block cache is probably unwanted (means 64MB of RAM will contantly be wasted as readcache - memory that can better be used for conntrack tables or such) so some more tests needs to be performed if a smaller CONFIG_SQUASHFS_FRAGMENT_CACHE_SIZE can be used and how that would affect the performance (lets say 16 blocks or so which would mean 4 MB of readcache compared to the default of 3 blocks meaning 768kbyte of readcache).

We can however conclude that the main issue is located elsewhere since optimizing the read part of squashfs didnt affect the total times that much (2.1% is still 2.1% but also more reboots are needed to conclude that those 2.1% isnt just some flux in the matrix).

Viacheslav triaged this task as Normal priority.Jan 20 2024, 1:00 PM

Hi!

Sorry for the noise, but Is there any progress with this issue?

I simply tried to add 100 VLAN interfaces, and the commit did not complete within 30 minutes.

set interfaces ethernet eth2 vif 102
set interfaces ethernet eth2 vif 103
set interfaces ethernet eth2 vif 104
...
...
set interfaces ethernet eth2 vif 199

I couldn't even access the Vyos VM via SSH from another console during the attempt to add 100 VLAN interfaces. The VMware perf monitor showed 100% CPU usage during this process.

If I added the VLANs in batches of 10, the commit was successful, within 2minutes per batch.

I'm trying to migrate from an ASA that has 10,000 ACL lines hundreds of vlans etc....
Which would be approximately 40,000 "set" commands.
Has anyone tested with such a large configuration already?

Adding https://forum.vyos.io/t/quick-and-dirty-benchmark-of-cores-vs-mhz/13831/ for reference which also concludes that something is off with the commit and boot times of VyOS.

The above example was about large firewall rulesets.

Question is if there is a quickfix for the extremely high commit and boot times that is without a complete rebuild of vyos-configd?

Like some flag for python which seems to be the one being used at the backend during the commit/boot?