I notice using netconf-console-tcp that an XML request to create or delete a list-entry in a container takes close to 500 milliseconds on a 1.2 GHz (2 core 2 cpu) powerpc based switch. This seems too high given that our proprietary TCP based CLI takes 4 milliseconds to create a comparable entry in a file on the switch.
I like to know if any performance tuning I missed and how to improve the request/response turn-around down to low teens or single digits.
I’m doing this test “without” any callback subscriptions into the switch - the switch process is actually not running - its just confd on a ppc linux box.
I do ‘date’ command before and after netconf-console-tcp and print the diff.
I also look at the timestamps, inside the switch, via the netconf.log file of confd. Following lines from netconf.log file show 452 millisecond elapsed between got-rpc and sending rpc-reply.
Are you storing the data in CDB or are you using the external Data Provider API? If you are storing the data in CDB, how many subscribers do you have, and how long do they take to process the change?
There are a number of variables that come into play when processing any configuration change, since inside of ConfD the changes are handled as a transaction, and any interaction with user-written software can introduce delays.
To put into perspective the difference in performance between ConfD’s CLI and NETCONF in making a configuration change with the configuration data stored in CDB, I have modified the intro/1-2-3 example and have removed the CDB subscriber when running my performance tests. I have set the developerLogLevel in confd.conf to trace in order to capture the devel.log output. This is run on a 15-inch MacBook Pro with a 2.2 GHz intel Core i7 processor.
Following is the output of my performance tests:
localhost:1-2-3-start-query-model $ ./perf.sh
+ echo '*** Start of NETCONF edit-config performance testing'
*** Start of NETCONF edit-config performance testing
+ make clean all
+ make start
connection refused (stop)
No matching processes belonging to you were found
+ cat cmd-set-subnet1.xml
<?xml version="1.0" encoding="UTF-8"?>
<hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
<capabilities>
<capability>urn:ietf:params:netconf:base:1.0</capability>
</capabilities>
</hello>
]]>]]>
<?xml version="1.0" encoding="UTF-8"?>
<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="1">
<edit-config>
<target>
<running/>
</target>
<config>
<dhcp xmlns="http://tail-f.com/ns/example/dhcpd"
xmlns:nc="urn:ietf:params:xml:ns:netconf:base:1.0">
<SubNets>
<subNet nc:operation="create">
<net>192.168.128.0</net>
<mask>255.255.255.0</mask>
<range>
<lowAddr>192.168.128.60</lowAddr>
<hiAddr>192.168.128.89</hiAddr>
</range>
</subNet>
</SubNets>
</dhcp>
</config>
</edit-config>
</rpc>
]]>]]>
<?xml version="1.0" encoding="UTF-8"?>
<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="2">
<close-session/>
</rpc>
+ netconf-console-tcp cmd-set-subnet1.xml
+ tail -n 19 devel.log
<DEBUG> 25-May-2016::14:26:44.049 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: entering validate phase for running...
<DEBUG> 25-May-2016::14:26:44.049 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: validate: grabbing transaction lock...
<DEBUG> 25-May-2016::14:26:44.049 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: ok
<DEBUG> 25-May-2016::14:26:44.049 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: validate: creating rollback file...
<DEBUG> 25-May-2016::14:26:44.080 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: ok
<DEBUG> 25-May-2016::14:26:44.080 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: validate: run transforms and transaction hooks...
<DEBUG> 25-May-2016::14:26:44.089 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: ok
<DEBUG> 25-May-2016::14:26:44.089 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: validate: pre validate...
<DEBUG> 25-May-2016::14:26:44.089 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: ok
<DEBUG> 25-May-2016::14:26:44.090 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: validate: run validation over the change set...
<DEBUG> 25-May-2016::14:26:44.090 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: validate: validation over the change set done
<DEBUG> 25-May-2016::14:26:44.090 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: validate: run dependency-triggered validation...
<DEBUG> 25-May-2016::14:26:44.090 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: validate: dependency-triggered validation done
<DEBUG> 25-May-2016::14:26:44.090 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: entering write phase for running...
<DEBUG> 25-May-2016::14:26:44.090 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: cdb: write_start
<DEBUG> 25-May-2016::14:26:44.090 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: entering prepare phase for running...
<DEBUG> 25-May-2016::14:26:44.090 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: cdb: prepare
<DEBUG> 25-May-2016::14:26:44.090 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: entering commit phase for running...
<DEBUG> 25-May-2016::14:26:44.090 localhost confd[95295]: confd commit progress db=running usid=11 thandle=6: cdb: commit
+ make stop
No matching processes belonging to you were found
+ echo '*** Start of CLI script performance testing'
*** Start of CLI script performance testing
+ make clean all
+ make start
connection refused (stop)
No matching processes belonging to you were found
+ cat cli-set-subnet1.sh
#!/bin/sh
confd_cli << EOF
config t
dhcp SubNets subNet 192.168.128.0 255.255.255.0 range lowAddr 192.168.128.60 hiAddr 192.168.128.89
commit
exit no-confirm
exit
EOF
+ ./cli-set-subnet1.sh
Commit complete.
+ tail -n 19 devel.log
<DEBUG> 25-May-2016::14:26:52.140 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: entering validate phase for running...
<DEBUG> 25-May-2016::14:26:52.140 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: validate: grabbing transaction lock...
<DEBUG> 25-May-2016::14:26:52.140 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: ok
<DEBUG> 25-May-2016::14:26:52.140 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: validate: creating rollback file...
<DEBUG> 25-May-2016::14:26:52.162 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: ok
<DEBUG> 25-May-2016::14:26:52.162 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: validate: run transforms and transaction hooks...
<DEBUG> 25-May-2016::14:26:52.175 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: ok
<DEBUG> 25-May-2016::14:26:52.176 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: validate: pre validate...
<DEBUG> 25-May-2016::14:26:52.176 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: ok
<DEBUG> 25-May-2016::14:26:52.176 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: validate: run validation over the change set...
<DEBUG> 25-May-2016::14:26:52.176 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: validate: validation over the change set done
<DEBUG> 25-May-2016::14:26:52.176 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: validate: run dependency-triggered validation...
<DEBUG> 25-May-2016::14:26:52.176 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: validate: dependency-triggered validation done
<DEBUG> 25-May-2016::14:26:52.176 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: entering write phase for running...
<DEBUG> 25-May-2016::14:26:52.176 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: cdb: write_start
<DEBUG> 25-May-2016::14:26:52.177 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: entering prepare phase for running...
<DEBUG> 25-May-2016::14:26:52.177 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: cdb: prepare
<DEBUG> 25-May-2016::14:26:52.177 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: entering commit phase for running...
<DEBUG> 25-May-2016::14:26:52.177 localhost confd[95889]: confd commit progress db=running usid=11 thandle=7: cdb: commit
+ make stop
No matching processes belonging to you were found
+ set +x
As you can see from my above test results, it took 41 ms to complete NETCONF’s edit-config request whereas it took 37 ms to complete the CLI script for making the same configuration change.
There are factors as pointed out by Greg that will affect your system’s performance. It may be good for you to perform the same test that I have shown here and compare the results when running on your target platform.
If you provide more details about your confd.conf configuration and your environment, we may be able to provide more input.
My yang model is storing data in CDB only and during test I kept my switch process off - only confd daemon was running on the target ppc platform. I also verified using confd --status that there are no registered callpoints/actionpoints/subscriptions or any registered client around.
Next are the results of running intro/1-2-3 dhcpd example per Wai Tai’s request.
It seems most time is spent during steps "validate: creating rollback file..." (~50+%) and "validate: run transforms and transaction hooks..." (~20+%).
Besides "devel.log", if you look into "netconf.log" there you'll see additional 100 ms spent in a step "got rpc:".
So total turn around is close to 100ms (netconf.log) + 276 ms (devel.log) = ~376 ms.
**My machine:**
# cat /proc/cpuinfo
processor : 0
cpu : e500v2
clock : 1200.000000MHz
revision : 5.1 (pvr 8021 1051)
bogomips : 150.00
processor : 1
cpu : e500v2
clock : 1200.000000MHz
revision : 5.1 (pvr 8021 1051)
bogomips : 150.00
total bogomips : 300.00
timebase : 75000000
platform : P2020 DS
model : fsl,P2020
Memory : 2048 MB
**My confd.conf:**
<confdConfig xmlns="http://tail-f.com/ns/confd_cfg/1.0">
<!-- The loadPath is searched for .fxs files, javascript files, etc.
NOTE: if you change the loadPath, the daemon must be restarted,
or the "In-service Data Model Upgrade" procedure described in
the User Guide can be used - 'confd - -reload' is not enough.
-->
<loadPath>
<dir>.</dir>
</loadPath>
<stateDir>.</stateDir>
<enableAttributes>true</enableAttributes>
<cdb>
<enabled>true</enabled>
<dbDir>./confd-cdb</dbDir>
<operational>
<enabled>true</enabled>
</operational>
</cdb>
<rollback>
<enabled>true</enabled>
<directory>./confd-cdb</directory>
</rollback>
<!-- These keys are used to encrypt values adhering to the types
tailf:des3-cbc-encrypted-string and tailf:aes-cfb-128-encrypted-string
as defined in the tailf-common YANG module. These types are
described in confd_types(3).
-->
<encryptedStrings>
<DES3CBC>
<key1>0123456789abcdef</key1>
<key2>0123456789abcdef</key2>
<key3>0123456789abcdef</key3>
<initVector>0123456789abcdef</initVector>
</DES3CBC>
<AESCFB128>
<key>0123456789abcdef0123456789abcdef</key>
<initVector>0123456789abcdef0123456789abcdef</initVector>
</AESCFB128>
</encryptedStrings>
<logs>
<!-- Shared settings for how to log to syslog.
Each log can be configured to log to file and/or syslog. If a
log is configured to log to syslog, the settings below are used.
-->
<syslogConfig>
<!-- facility can be 'daemon', 'local0' ... 'local7' or an integer -->
<facility>daemon</facility>
<!-- if udp is not enabled, messages will be sent to local syslog -->
<udp>
<enabled>false</enabled>
<host>syslogsrv.example.com</host>
<port>514</port>
</udp>
</syslogConfig>
<!-- 'confdlog' is a normal daemon log. Check this log for
startup problems of confd itself.
By default, it logs directly to a local file, but it can be
configured to send to a local or remote syslog as well.
-->
<confdLog>
<enabled>false</enabled>
<file>
<enabled>true</enabled>
<name>./confd.log</name>
</file>
<syslog>
<enabled>true</enabled>
</syslog>
</confdLog>
<!-- The developer logs are supposed to be used as debug logs
for troubleshooting user-written javascript and c code. Enable
and check these logs for problems with validation code etc.
-->
<developerLog>
<enabled>true</enabled>
<file>
<enabled>true</enabled>
<name>./devel.log</name>
</file>
<syslog>
<enabled>false</enabled>
</syslog>
</developerLog>
<developerLogLevel>trace</developerLogLevel>
<auditLog>
<enabled>false</enabled>
<file>
<enabled>true</enabled>
<name>./audit.log</name>
</file>
<syslog>
<enabled>true</enabled>
</syslog>
</auditLog>
<!-- The netconf log can be used to troubleshoot NETCONF operations,
such as checking why e.g. a filter operation didn't return the
data requested.
-->
<netconfLog>
<enabled>true</enabled>
<file>
<enabled>true</enabled>
<name>./netconf.log</name>
</file>
<syslog>
<enabled>false</enabled>
</syslog>
</netconfLog>
<webuiBrowserLog>
<enabled>false</enabled>
<filename>./browser.log</filename>
</webuiBrowserLog>
<webuiAccessLog>
<enabled>false</enabled>
<dir>./</dir>
</webuiAccessLog>
<netconfTraceLog>
<enabled>false</enabled>
<filename>./netconf.trace</filename>
<format>pretty</format>
</netconfTraceLog>
<xpathTraceLog>
<enabled>false</enabled>
<filename>./xpath.trace</filename>
</xpathTraceLog>
</logs>
<!-- Defines which datastores confd will handle. -->
<datastores>
<!-- 'startup' means that the system keeps separate running and
startup configuration databases. When the system reboots for
whatever reason, the running config database is lost, and the
startup is read.
Enable this only if your system uses a separate startup and
running database.
-->
<startup>
<enabled>false</enabled>
</startup>
<!-- The 'candidate' is a shared, named alternative configuration
database which can be modified without impacting the running
configuration. Changes in the candidate can be commit to running,
or discarded.
Enable this if you want your users to use this feature from
NETCONF, CLI or WebGUI, or other agents.
-->
<candidate>
<enabled>false</enabled>
<!-- By default, confd implements the candidate configuration
without impacting the application. But if your system
already implements the candidate itself, set 'implementation' to
'external'.
-->
<!--implementation>external</implementation-->
<implementation>confd</implementation>
<storage>auto</storage>
<filename>./confd_candidate.db</filename>
</candidate>
<!-- By default, the running configuration is writable. This means
that the application must be prepared to handle changes to
the configuration dynamically. If this is not the case, set
'access' to 'read-only'. If running is read-only, 'startup'
must be enabled, and 'candidate' must be disabled. This means that
the application reads the configuration at startup, and then
the box must reboort in order for the application to re-read it's
configuration.
NOTE: this is not the same as the NETCONF capability
:writable-running, which merely controls which NETCONF
operations are allowed to write to the running configuration.
-->
<running>
<access>read-write</access>
</running>
</datastores>
<aaa>
<sshServerKeyDir>./ssh-keydir</sshServerKeyDir>
</aaa>
<confdIpcAddress>
<port>4565</port>
</confdIpcAddress>
<cli>
<ssh>
<enabled>true</enabled>
<ip>0.0.0.0</ip>
<port>2024</port>
</ssh>
</cli>
<netconf>
<enabled>true</enabled>
<transport>
<ssh>
<enabled>true</enabled>
<ip>0.0.0.0</ip>
<port>2022</port>
</ssh>
<!-- NETCONF over TCP is not standardized, but it can be useful
during development in order to use e.g. netcat for scripting.
-->
<tcp>
<enabled>true</enabled>
<ip>0.0.0.0</ip>
<port>2023</port>
</tcp>
</transport>
<capabilities>
<!-- enable only if /confdConfig/datastores/startup is enabled -->
<startup>
<enabled>false</enabled>
</startup>
<!-- enable only if /confdConfig/datastores/candidate is enabled -->
<candidate>
<enabled>false</enabled>
</candidate>
<confirmed-commit>
<enabled>false</enabled>
</confirmed-commit>
<!--
enable only if /confdConfig/datastores/running/access is read-write
-->
<writable-running>
<enabled>true</enabled>
</writable-running>
<rollback-on-error>
<enabled>true</enabled>
</rollback-on-error>
<actions>
<enabled>true</enabled>
</actions>
<notification>
<enabled>true</enabled>
</notification>
</capabilities>
</netconf>
<webui>
<enabled>false</enabled>
<transport>
<tcp>
<enabled>true</enabled>
<ip>0.0.0.0</ip>
<port>8008</port>
</tcp>
<ssl>
<enabled>true</enabled>
<ip>0.0.0.0</ip>
<port>8888</port>
</ssl>
</transport>
<cgi>
<enabled>true</enabled>
<php>
<enabled>true</enabled>
</php>
</cgi>
</webui>
</confdConfig>
Disk access time is typically one of the biggest performance bottleneck as you have already observed here. Based on your confd.conf settings, the rollback option is probably the only one that you may want to consider disabling if performance is a concern. I can’t think of anything else that can be tuned to improve performance.
Do you have a runtime-performance datasheet for confd for a couple of RAM/CPU configurations of Linux 686 and Linux powerpc platforms? Is there a benchmark that you can share? e.g for basic netconf operations (get-config, edit-config ) doing single list entry, then 10, 100, 1000, 10,000 list entries in a single xml rpc.
In my earlier post, I mentioned that my netconf.log file is showing 100 ms additional is spent doing compute cycles in step called “got rpc:” - it sounds like on my powerpc 1.2 GHz with 2048 MB RAM, the netconf RPC parser is taking 100 ms - this is significant amount of time doing just parsing!
On your 2.2 Ghz laptop, your sample test took 40 ms in devel.log, do you see about 10-20 ms additional is spent right away upon request arrival in your netconf.log doing “got rpc:”!
Do you have some numbers from say an embedded confd on a cisco router? Or any embedded box numbers would do (from your customer base experience), so I have a sense of how bad my box is doing!
How much CPU and RAM and type of Disk ( ramdisk vs flash vs solid state) you recommend for best performance of NETCONF using Confd.
We do have an application note on ConfD performance that we can provide upon execution of a NDA. You can submit your request at Contact Us | Tail-f Systems.
about 20 ms between “got rpc:” and “edit-config” in my netconf.log.
I don’t have any performance numbers from other embedded systems on this same test. Other ConfD users will typically perform their own performance benchmark testing. What we provide is the Performance App Note that I have mentioned above. Perhaps other Forum users can chime in to provide their numbers.
This will depend on what is acceptable performance per your own system requirements. There is no general recommendation.