Sairamp
February 2, 2023, 10:23am
1
Hi,
We are facing performance issue in confd 6.2.1, test case executed as below,
uploaded config xml ~3mb size.
Above configXml has >4k records for a particular list.
In the same list we tried to add 10 more records through edit-config in a loop.
We are receving the RPC reply for each record ~1000ms . Please find the below netconf logs.
Could you suggest what could be the cause for this delay and how can we improve this.
<INFO> 2-Feb-2023::05:06:51.553 v1 confd[45277]: netconf id=4759 got rpc: {urn:ietf:params:xml:ns:netconf:base:1.0}edit-config attrs: message-id="1"
<INFO> 2-Feb-2023::05:07:20.659 v1 confd[45277]: netconf id=4759 edit-config target=running attrs: message-id="1"
<INFO> 2-Feb-2023::05:07:21.154 v1 confd[45277]: netconf id=4759 sending rpc-reply, attrs: message-id="1"
<INFO> 2-Feb-2023::05:07:23.263 v1 confd[45277]: netconf id=4759 ssh transport closed
<INFO> 2-Feb-2023::05:07:23.263 v1 confd[45277]: netconf id=4760 ssh transport closed
<INFO> 2-Feb-2023::05:07:24.838 v1 confd[45277]: netconf id=4761 new ssh session for user "admin" from 127.0.0.1
<INFO> 2-Feb-2023::05:07:24.853 v1 confd[45277]: netconf id=4761 got rpc: {urn:ietf:params:xml:ns:netconf:base:1.0}edit-config attrs: nc:message-id="1"
<INFO> 2-Feb-2023::05:07:24.857 v1 confd[45277]: netconf id=4761 edit-config target=running attrs: nc:message-id="1"
<INFO> 2-Feb-2023::05:07:25.879 v1 confd[45277]: netconf id=4761 sending rpc-reply, attrs: nc:message-id="1"
<INFO> 2-Feb-2023::05:07:28.284 v1 confd[45277]: netconf id=4761 got rpc: {urn:ietf:params:xml:ns:netconf:base:1.0}edit-config attrs: nc:message-id="2"
<INFO> 2-Feb-2023::05:07:28.291 v1 confd[45277]: netconf id=4761 edit-config target=running attrs: nc:message-id="2"
<INFO> 2-Feb-2023::05:07:29.292 v1 confd[45277]: netconf id=4761 sending rpc-reply, attrs: nc:message-id="2"
<INFO> 2-Feb-2023::05:07:30.000 v1 confd[45277]: netconf id=4761 got rpc: {urn:ietf:params:xml:ns:netconf:base:1.0}edit-config attrs: nc:message-id="3"
<INFO> 2-Feb-2023::05:07:30.005 v1 confd[45277]: netconf id=4761 edit-config target=running attrs: nc:message-id="3"
<INFO> 2-Feb-2023::05:07:30.924 v1 confd[45277]: netconf id=4761 sending rpc-reply, attrs: nc:message-id="3"
<INFO> 2-Feb-2023::05:07:31.728 v1 confd[45277]: netconf id=4761 got rpc: {urn:ietf:params:xml:ns:netconf:base:1.0}edit-config attrs: nc:message-id="4"
<INFO> 2-Feb-2023::05:07:31.733 v1 confd[45277]: netconf id=4761 edit-config target=running attrs: nc:message-id="4"
<INFO> 2-Feb-2023::05:07:32.690 v1 confd[45277]: netconf id=4761 sending rpc-reply, attrs: nc:message-id="4"
<INFO> 2-Feb-2023::05:07:35.411 v1 confd[45277]: netconf id=4761 got rpc: {urn:ietf:params:xml:ns:netconf:base:1.0}edit-config attrs: nc:message-id="5"
<INFO> 2-Feb-2023::05:07:35.416 v1 confd[45277]: netconf id=4761 edit-config target=running attrs: nc:message-id="5"
<INFO> 2-Feb-2023::05:07:36.330 v1 confd[45277]: netconf id=4761 sending rpc-reply, attrs: nc:message-id="5"
<INFO> 2-Feb-2023::05:07:36.938 v1 confd[45277]: netconf id=4761 got rpc: {urn:ietf:params:xml:ns:netconf:base:1.0}edit-config attrs: nc:message-id="6"
<INFO> 2-Feb-2023::05:07:36.943 v1 confd[45277]: netconf id=4761 edit-config target=running attrs: nc:message-id="6"
<INFO> 2-Feb-2023::05:07:37.855 v1 confd[45277]: netconf id=4761 sending rpc-reply, attrs: nc:message-id="6"
<INFO> 2-Feb-2023::05:07:38.483 v1 confd[45277]: netconf id=4761 got rpc: {urn:ietf:params:xml:ns:netconf:base:1.0}edit-config attrs: nc:message-id="7"
<INFO> 2-Feb-2023::05:07:38.489 v1 confd[45277]: netconf id=4761 edit-config target=running attrs: nc:message-id="7"
<INFO> 2-Feb-2023::05:07:39.440 v1 confd[45277]: netconf id=4761 sending rpc-reply, attrs: nc:message-id="7"
<INFO> 2-Feb-2023::05:07:40.033 v1 confd[45277]: netconf id=4761 got rpc: {urn:ietf:params:xml:ns:netconf:base:1.0}edit-config attrs: nc:message-id="8"
<INFO> 2-Feb-2023::05:07:40.037 v1 confd[45277]: netconf id=4761 edit-config target=running attrs: nc:message-id="8"
<INFO> 2-Feb-2023::05:07:41.047 v1 confd[45277]: netconf id=4761 sending rpc-reply, attrs: nc:message-id="8"
<INFO> 2-Feb-2023::05:07:41.701 v1 confd[45277]: netconf id=4761 got rpc: {urn:ietf:params:xml:ns:netconf:base:1.0}edit-config attrs: nc:message-id="9"
<INFO> 2-Feb-2023::05:07:41.708 v1 confd[45277]: netconf id=4761 edit-config target=running attrs: nc:message-id="9"
<INFO> 2-Feb-2023::05:07:42.663 v1 confd[45277]: netconf id=4761 sending rpc-reply, attrs: nc:message-id="9"
<INFO> 2-Feb-2023::05:07:45.328 v1 confd[45277]: netconf id=4761 got rpc: {urn:ietf:params:xml:ns:netconf:base:1.0}edit-config attrs: nc:message-id="10"
<INFO> 2-Feb-2023::05:07:45.333 v1 confd[45277]: netconf id=4761 edit-config target=running attrs: nc:message-id="10"
<INFO> 2-Feb-2023::05:07:46.373 v1 confd[45277]: netconf id=4761 sending rpc-reply, attrs: nc:message-id="10"
cohult
February 2, 2023, 1:57pm
2
Hi,
Thanks prompt reply.
As suggested, I have collected devel.log with trace enabled. Can you please help in checking the performance bottleneck.
netconf.log:
<INFO> 8-Feb-2023::07:44:21.633 v1 confd[61586]: netconf id=18 got rpc: {urn:ietf:params:xml:ns:netconf:base:1.0}edit-config attrs: nc:message-id="1"
<INFO> 8-Feb-2023::07:44:21.638 v1 confd[61586]: netconf id=18 edit-config target=running attrs: nc:message-id="1"
<INFO> 8-Feb-2023::07:44:22.533 v1 confd[61586]: netconf id=18 sending rpc-reply, attrs: nc:message-id="1"
<INFO> 8-Feb-2023::07:44:25.352 v1 confd[61586]: netconf id=18 got rpc: {urn:ietf:params:xml:ns:netconf:base:1.0}edit-config attrs: nc:message-id="2"
<INFO> 8-Feb-2023::07:44:25.355 v1 confd[61586]: netconf id=18 edit-config target=running attrs: nc:message-id="2"
<INFO> 8-Feb-2023::07:44:26.255 v1 confd[61586]: netconf id=18 sending rpc-reply, attrs: nc:message-id="2"
devel.log:
<DEBUG> 8-Feb-2023::07:44:21.638 v1 confd[61586]: confd commit progress db=running usid=18 thandle=15: entering validate phase for running...
<DEBUG> 8-Feb-2023::07:44:21.638 v1 confd[61586]: confd commit progress db=running usid=18 thandle=15: validate: grabbing transaction lock...
<DEBUG> 8-Feb-2023::07:44:21.639 v1 confd[61586]: confd commit progress db=running usid=18 thandle=15: ok
<DEBUG> 8-Feb-2023::07:44:21.639 v1 confd[61586]: confd commit progress db=running usid=18 thandle=15: validate: creating rollback file...
<DEBUG> 8-Feb-2023::07:44:21.641 v1 confd[61586]: confd commit progress db=running usid=18 thandle=15: ok
<DEBUG> 8-Feb-2023::07:44:21.642 v1 confd[61586]: confd commit progress db=running usid=18 thandle=15: validate: run transforms and transaction hooks...
<DEBUG> 8-Feb-2023::07:44:21.642 v1 confd[61586]: confd commit progress db=running usid=18 thandle=15: ok
<DEBUG> 8-Feb-2023::07:44:21.642 v1 confd[61586]: confd commit progress db=rnvunning usid=18 thandle=15: validate: pre validate...
<DEBUG> 8-Feb-2023::07:44:21.643 v1 confd[61586]: confd commit progress db=running usid=18 thandle=15: ok
<DEBUG> 8-Feb-2023::07:44:21.643 v1 confd[61586]: confd commit progress db=running usid=18 thandle=15: validate: run validation over the change set...
<DEBUG> 8-Feb-2023::07:44:22.502 v1 confd[61586]: confd commit progress db=running usid=18 thandle=15: validate: validation over the change set done
<DEBUG> 8-Feb-2023::07:44:22.502 v1 confd[61586]: confd commit progress db=running usid=18 thandle=15: validate: run dependency-triggered validation...
<DEBUG> 8-Feb-2023::07:44:22.503 v1 confd[61586]: confd commit progress db=running usid=18 thandle=15: validate: dependency-triggered validation done
<DEBUG> 8-Feb-2023::07:44:22.512 v1 confd[61586]: confd commit progress db=running usid=18 thandle=15: entering write phase for running...
<DEBUG> 8-Feb-2023::07:44:22.513 v1 confd[61586]: confd commit progress db=running usid=18 thandle=15: cdb: write_start
<DEBUG> 8-Feb-2023::07:44:22.513 v1 confd[61586]: confd commit progress db=running usid=18 thandle=15: entering prepare phase for running...
<DEBUG> 8-Feb-2023::07:44:22.514 v1 confd[61586]: confd commit progress db=running usid=18 thandle=15: cdb: prepare
<DEBUG> 8-Feb-2023::07:44:22.514 v1 confd[61586]: confd commit progress db=running usid=18 thandle=15: entering commit phase for running...
<DEBUG> 8-Feb-2023::07:44:22.514 v1 confd[61586]: confd commit progress db=running usid=18 thandle=15: cdb: commit
<DEBUG> 8-Feb-2023::07:44:25.356 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: entering validate phase for running...
<DEBUG> 8-Feb-2023::07:44:25.356 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: validate: grabbing transaction lock...
<DEBUG> 8-Feb-2023::07:44:25.356 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: ok
<DEBUG> 8-Feb-2023::07:44:25.356 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: validate: creating rollback file...
<DEBUG> 8-Feb-2023::07:44:25.359 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: ok
<DEBUG> 8-Feb-2023::07:44:25.360 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: validate: run transforms and transaction hooks...
<DEBUG> 8-Feb-2023::07:44:25.360 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: ok
<DEBUG> 8-Feb-2023::07:44:25.361 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: validate: pre validate...
<DEBUG> 8-Feb-2023::07:44:25.361 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: ok
<DEBUG> 8-Feb-2023::07:44:25.361 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: validate: run validation over the change set...
<DEBUG> 8-Feb-2023::07:44:26.229 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: validate: validation over the change set done
<DEBUG> 8-Feb-2023::07:44:26.230 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: validate: run dependency-triggered validation...
<DEBUG> 8-Feb-2023::07:44:26.230 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: validate: dependency-triggered validation done
<DEBUG> 8-Feb-2023::07:44:26.230 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: entering write phase for running...
<DEBUG> 8-Feb-2023::07:44:26.230 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: cdb: write_start
<DEBUG> 8-Feb-2023::07:44:26.231 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: entering prepare phase for running...
<DEBUG> 8-Feb-2023::07:44:26.231 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: cdb: prepare
<DEBUG> 8-Feb-2023::07:44:26.232 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: entering commit phase for running...
<DEBUG> 8-Feb-2023::07:44:26.232 v1 confd[61586]: confd commit progress db=running usid=18 thandle=17: cdb: commit
There seems to be “long” delay here (859ms) between the start/end of change set validation.
I am not familiar with internals at this stage, so am just guessing around - do you maybe have some validation call-point registered that may be taking long time to check loaded config? Or maybe some complex/less effective must/when statements in YANG model that need to be re-evaluated for all the new elements loaded?
1 Like
Sairamp
February 21, 2023, 7:03am
5
Hi Josephm,
We have reviewed our yang there are no complex ‘must’ /‘when’ statements in YANG model and no call-point registration also. Can you suggest further.
josephm
February 27, 2023, 11:41am
6
Oops, sorry for no feedback since last response.
Hard to say what specifically is “wrong” - 3MB file can be quite a “lot of data” to process into database, so this could be just “normal” processing time for the amount of data (all-in all, ConfD is IMHO not primarily high performance r/w database only).
You could try iterating with different number of records and see if the validation time has linear or worse “big-o” complexity… (not that it solves the problem itself, but could shed more light into matter)?
Also, It could be interesting to see if there’s a difference for latest ConfD version (better or worse).