Page MenuHomeVyOS Platform

Increased boot time from 1.2.4 -> 1.3 rolling by 100%
Open, Requires assessmentPublicBUG

Description

The following configuration takes 430 seconds to boot on my APU4C4 (quad core 1GHz, 4GB ECC RAM) board using VyOS 1.2.4.
Boot time increases to 1000 seconds running VyOS 1.3 rolling.

I hope this configuration helps performance testing.

Details

Difficulty level
Hard (possibly days)
Version
1.3-rolling-20200229
Why the issue appeared?
Will be filled on close
Is it a breaking change?
Unspecified (possibly destroys the router)

Event Timeline

c-po created this task.Mar 1 2020, 2:48 PM
c-po added a comment.Mar 1 2020, 5:55 PM

One of the offeners is

vyos@vyos# show system config-management commit-archive
 location tftp://172.16.20.200/CONFIGS/BR1.wueIII

removing this line will reduce the boot time to 700 seocnds (down by 30%) .. weird

c-po added a comment.May 20 2020, 6:13 AM
This comment was removed by c-po.

0-18 kernel boot
18-41 system starting inc FRR
70-120 the python most of the time is spend/wasted in cli-shell-api - so I would think reading the configuration file. If we can optimise / reduce this number of calls it would be very good.
140-220 is more or less firewall setup with vyatta-firewall / vyatta-upset.pl / ip6tables

rounding numbes:

So 22% in cli-shell-api
So 36% in firewall

pasik added a subscriber: pasik.May 20 2020, 8:48 AM
c-po added a comment.May 20 2020, 10:16 AM

Please see attached the full log of the boot process. I try to supply a PNG later on but I guess it will be really huge.

Every call to /bin/cli-shell-api --show-working-only --show-show-defaults --show-ignore-edit showConfig takes multiples seconds (6?)
/usr/libexec/vyos/conf_mode/system-timezone.py call it twice.
/usr/libexec/vyos/conf_mode/nat.py call it twice
/usr/libexec/vyos/conf_mode/interfaces-loopback.py call it twice ... etc.

Looking at the ... seconds it takes to set the hostname ...
The code for /usr/libexec/vyos/conf_mode/host_name.py is spent waiting for vyos-hostd to come back

sudo apt install python3-pip
sudo pip3 install -U pip setuptools wheel virtualenv
pip3 install git+https://github.com/evanhempel/python-flamegraph.git
python3 -m flamegraph -o perf.log /usr/libexec/vyos/conf_mode/host_name.py
./flamegraph.pl perf.log > unix-time.svg
c-po added a comment.May 30 2020, 6:07 PM

Why is it sometimes called twice?

jjakob added a subscriber: jjakob.May 30 2020, 7:06 PM

Possibly it's in cases where it's first called in get_config(), then also later in verify() or apply() - the object is function local scope and isn't saved in a global variable. It would be a simple fix if Config() were initialised in main() and passed as an argument to any function that needs it.

runar added a subscriber: runar.EditedMay 31 2020, 5:50 AM

I've created some proof of concept code that i think could help on this issue. https://github.com/runborg/vyos-1x/blob/main-cfg/src/conf_mode/main.py this is a conf-mode executor that handles multiple conf mode scripts. The reason i think this could seriously help on this issue is that as this is all running inside a single python tnterpreter, its able to load the config object once and pass it to all needed conf_mode scripts without a need for reinitialization.

The only big bottleneck with this script is that it only executes as a single vyatta-cfg priority so all executed scripts needs to be in a continous order without old bash dependencies.

runar added a comment.May 31 2020, 6:14 AM

As the current "priority map" there aren't a loot of concurrent python blocks, but i think many of the remaining bash/perl scripts could be moved to new places. https://pastebin.com/z6ZvkJKB

I used @runar code on my branch working on T2522 .. Configuring 100 dummy interface went from 42 to 8 seconds.