Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

vpp-agent taking 500ms (with WaitDone == true) for simple transaction #1748

Closed
edwarnicke opened this issue Oct 19, 2020 · 14 comments
Closed

vpp-agent taking 500ms (with WaitDone == true) for simple transaction #1748

edwarnicke opened this issue Oct 19, 2020 · 14 comments
Labels
✖️invalid

Comments

@edwarnicke
Copy link
Contributor

Placeholder
@edwarnicke
Copy link
Contributor Author

Log output:

Oct 19 21:32:33.134�[36m [INFO] �[0mSENDING UPDATE COMMIT: 
{
  "update": {
    "vpp_config": {
      "interfaces": [
        {
          "name": "server-3b292af6-7a09-4f83-a6f7-39f79fb84035",
          "type": "AF_PACKET",
          "enabled": true,
          "afpacket": {
            "hostIfName": "server-3b292af6"
          }
        },
        {
          "name": "client-3b292af6-7a09-4f83-a6f7-39f79fb84035",
          "type": "MEMIF",
          "enabled": true,
          "memif": {
            "socketFilename": "/proc/3601/fd/14"
          }
        }
      ],
      "xconnect_pairs": [
        {
          "receive_interface": "server-3b292af6-7a09-4f83-a6f7-39f79fb84035",
          "transmit_interface": "client-3b292af6-7a09-4f83-a6f7-39f79fb84035"
        },
        {
          "receive_interface": "client-3b292af6-7a09-4f83-a6f7-39f79fb84035",
          "transmit_interface": "server-3b292af6-7a09-4f83-a6f7-39f79fb84035"
        }
      ]
    },
    "linux_config": {
      "interfaces": [
        {
          "name": "server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth",
          "type": "VETH",
          "hostIfName": "server-3b292af6",
          "enabled": true,
          "veth": {
            "peerIfName": "server-3b292af6-7a09-4f83-a6f7-39f79fb84035",
            "rxChecksumOffloading": "CHKSM_OFFLOAD_DISABLED",
            "txChecksumOffloading": "CHKSM_OFFLOAD_DISABLED"
          }
        },
        {
          "name": "server-3b292af6-7a09-4f83-a6f7-39f79fb84035",
          "type": "VETH",
          "namespace": {
            "type": "FD",
            "reference": "/proc/3601/fd/12"
          },
          "hostIfName": "k2mns-3b292af6-",
          "enabled": true,
          "ipAddresses": [
            "10.0.0.1/32"
          ],
          "veth": {
            "peerIfName": "server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth",
            "rxChecksumOffloading": "CHKSM_OFFLOAD_DISABLED",
            "txChecksumOffloading": "CHKSM_OFFLOAD_DISABLED"
          }
        }
      ],
      "routes": [
        {
          "outgoing_interface": "server-3b292af6-7a09-4f83-a6f7-39f79fb84035",
          "scope": 3,
          "dst_network": "10.0.0.0/32"
        }
      ]
    },
    "netalloc_config": {}
  },
  "wait_done": true
}
time="2020-10-19 21:32:33.13562" level=debug msg="Push data with 7 KV pairs (source: grpc)" loc="orchestrator/dispatcher.go(110)" logger=dispatcher
time="2020-10-19 21:32:33.13569" level=debug msg=" - UPDATE: \"config/vpp/v2/interfaces/server-3b292af6-7a09-4f83-a6f7-39f79fb84035\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:33.13574" level=debug msg=" - UPDATE: \"config/vpp/v2/interfaces/client-3b292af6-7a09-4f83-a6f7-39f79fb84035\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:33.13579" level=debug msg=" - UPDATE: \"config/vpp/l2/v2/xconnect/server-3b292af6-7a09-4f83-a6f7-39f79fb84035\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:33.13582" level=debug msg=" - UPDATE: \"config/vpp/l2/v2/xconnect/client-3b292af6-7a09-4f83-a6f7-39f79fb84035\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:33.13585" level=debug msg=" - UPDATE: \"config/linux/interfaces/v2/interface/server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:33.13590" level=debug msg=" - UPDATE: \"config/linux/interfaces/v2/interface/server-3b292af6-7a09-4f83-a6f7-39f79fb84035\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:33.13593" level=debug msg=" - UPDATE: \"config/linux/l3/v2/route/10.0.0.0/32/server-3b292af6-7a09-4f83-a6f7-39f79fb84035\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
+======================================================================================================================+
| #11 - NBTransaction                                                                                                  |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 11
      - type: NB Transaction
      - values:
          - key: config/linux/interfaces/v2/interface/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
            val: { name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  type:VETH  namespace:{type:FD  reference:"/proc/3601/fd/12"}  host_if_name:"k2mns-3b292af6-"  enabled:true  ip_addresses:"10.0.0.1/32"  veth:{peer_if_name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth"  rx_checksum_offloading:CHKSM_OFFLOAD_DISABLED  tx_checksum_offloading:CHKSM_OFFLOAD_DISABLED} }
          - key: config/linux/interfaces/v2/interface/server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth
            val: { name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth"  type:VETH  host_if_name:"server-3b292af6"  enabled:true  veth:{peer_if_name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  rx_checksum_offloading:CHKSM_OFFLOAD_DISABLED  tx_checksum_offloading:CHKSM_OFFLOAD_DISABLED} }
          - key: config/linux/l3/v2/route/10.0.0.0/32/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
            val: { outgoing_interface:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  scope:LINK  dst_network:"10.0.0.0/32" }
          - key: config/vpp/l2/v2/xconnect/client-3b292af6-7a09-4f83-a6f7-39f79fb84035
            val: { receive_interface:"client-3b292af6-7a09-4f83-a6f7-39f79fb84035"  transmit_interface:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035" }
          - key: config/vpp/l2/v2/xconnect/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
            val: { receive_interface:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  transmit_interface:"client-3b292af6-7a09-4f83-a6f7-39f79fb84035" }
          - key: config/vpp/v2/interfaces/client-3b292af6-7a09-4f83-a6f7-39f79fb84035
            val: { name:"client-3b292af6-7a09-4f83-a6f7-39f79fb84035"  type:MEMIF  enabled:true  memif:{socket_filename:"/proc/3601/fd/14"} }
          - key: config/vpp/v2/interfaces/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
            val: { name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  type:AF_PACKET  enabled:true  afpacket:{host_if_name:"server-3b292af6"} }

time="2020-10-19 21:32:33.19079" level=debug msg="Memif socket filename /proc/3601/fd/14 registered under ID 1" loc="descriptor/interface.go(949)" logger=vpp-ifplugin.if-descriptor
time="2020-10-19 21:32:33.19465" level=debug msg="publish add to ifplugin_ifstate{{client-3b292af6-7a09-4f83-a6f7-39f79fb84035 false false vpp-interface-index} 0xc000b5d4f0}" loc="mem/inmemory_name_mapping.go(277)" logger=vpp-ifplugin.if-descriptor
o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:33.136 +0000 UTC -> 2020-10-19 21:32:33.195 +0000 UTC, dur: 59ms):
      1. CREATE:
          - key: config/linux/interfaces/v2/interface/server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth
          - value: { name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth"  type:VETH  host_if_name:"server-3b292af6"  enabled:true  veth:{peer_if_name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  rx_checksum_offloading:CHKSM_OFFLOAD_DISABLED  tx_checksum_offloading:CHKSM_OFFLOAD_DISABLED} } 
      2. CREATE:
          - key: config/linux/interfaces/v2/interface/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
          - value: { name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  type:VETH  namespace:{type:FD  reference:"/proc/3601/fd/12"}  host_if_name:"k2mns-3b292af6-"  enabled:true  ip_addresses:"10.0.0.1/32"  veth:{peer_if_name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth"  rx_checksum_offloading:CHKSM_OFFLOAD_DISABLED  tx_checksum_offloading:CHKSM_OFFLOAD_DISABLED} } 
      3. CREATE [DERIVED]:
          - key: linux/interface/server-3b292af6-7a09-4f83-a6f7-39f79fb84035/address/static/10.0.0.1/32
          - value: <EMPTY> 
      4. CREATE [PROPERTY]:
          - key: linux/interface/state/server-3b292af6-7a09-4f83-a6f7-39f79fb84035/UP
          - value: <EMPTY> 
      5. CREATE [PROPERTY]:
          - key: linux/interface/state/server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth/UP
          - value: <EMPTY> 
      6. CREATE:
          - key: config/linux/l3/v2/route/10.0.0.0/32/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
          - value: { outgoing_interface:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  scope:LINK  dst_network:"10.0.0.0/32" } 
      7. CREATE [PROPERTY]:
          - key: linux/link-local-route/server-3b292af6-7a09-4f83-a6f7-39f79fb84035/dest-address/10.0.0.0/32
          - value: <EMPTY> 
      8. CREATE [NOOP IS-PENDING]:
          - key: config/vpp/l2/v2/xconnect/client-3b292af6-7a09-4f83-a6f7-39f79fb84035
          - value: { receive_interface:"client-3b292af6-7a09-4f83-a6f7-39f79fb84035"  transmit_interface:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035" } 
      9. CREATE [NOOP IS-PENDING]:
          - key: config/vpp/l2/v2/xconnect/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
          - value: { receive_interface:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  transmit_interface:"client-3b292af6-7a09-4f83-a6f7-39f79fb84035" } 
      10. CREATE:
          - key: config/vpp/v2/interfaces/client-3b292af6-7a09-4f83-a6f7-39f79fb84035
          - value: { name:"client-3b292af6-7a09-4f83-a6f7-39f79fb84035"  type:MEMIF  enabled:true  memif:{socket_filename:"/proc/3601/fd/14"} } 
      11. CREATE [NOOP IS-PENDING]:
          - key: config/vpp/v2/interfaces/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
          - value: { name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  type:AF_PACKET  enabled:true  afpacket:{host_if_name:"server-3b292af6"} } 
x----------------------------------------------------------------------------------------------------------------------x
| #11 - NBTransaction                                                                                      took 58.8ms |
x----------------------------------------------------------------------------------------------------------------------x

+======================================================================================================================+
| #12 - SBNotification                                                                                                 |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 12
      - type: SB Notification
      - values:
          - key: vpp/interface/client-3b292af6-7a09-4f83-a6f7-39f79fb84035/link-state/DOWN
            val: <EMPTY>

time="2020-10-19 21:32:33.19527" level=info msg="Transaction #11 successful! (took 59.2ms)" loc="orchestrator/dispatcher.go(178)" logger=dispatcher
o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:33.195 +0000 UTC -> 2020-10-19 21:32:33.195 +0000 UTC, dur: 0s):
      1. CREATE [OBTAINED]:
          - key: vpp/interface/client-3b292af6-7a09-4f83-a6f7-39f79fb84035/link-state/DOWN
          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
| #12 - SBNotification                                                                                      took 100µs |
x----------------------------------------------------------------------------------------------------------------------x

time="2020-10-19 21:32:33.19576" level=info msg="waiting for 3 pending keys to be done" loc="configurator/configurator.go(137)" logger=configurator.configurator
time="2020-10-19 21:32:33.19594" level=info msg="Transaction 12 successful!" loc="kvscheduler/txn_process.go(405)" logger=kvscheduler
+======================================================================================================================+
| #13 - SBNotification                                                                                                 |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 13
+======================================================================================================================+
| #6 - SBNotification                                                                                                  |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 6
      - type: SB Notification
      - values:
          - key: linux/interface/host-name/server-3b292af6
            val: <EMPTY>

o----------------------------------------------------------------------------------------------------------------------o
      - type: SB Notification
  * executed operations (2020-10-19 21:32:33.653 +0000 UTC -> 2020-10-19 21:32:33.653 +0000 UTC, dur: 0s):
      1. CREATE [OBTAINED]:
          - key: linux/interface/host-name/server-3b292af6
          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
| #6 - SBNotification                                                                                       took 200µs |
x----------------------------------------------------------------------------------------------------------------------x

+======================================================================================================================+
| #4 - SBNotification                                                                                                  |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 4
      - type: SB Notification
      - values:
          - key: linux/interface/host-name/server-3b292af6
            val: <EMPTY>

time="2020-10-19 21:32:33.65325" level=info msg="Transaction 6 successful!" loc="kvscheduler/txn_process.go(405)" logger=kvscheduler
o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:33.653 +0000 UTC -> 2020-10-19 21:32:33.653 +0000 UTC, dur: 0s):
      1. CREATE [OBTAINED]:
          - key: linux/interface/host-name/server-3b292af6
          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
| #4 - SBNotification                                                                                       took 200µs |
x----------------------------------------------------------------------------------------------------------------------x

time="2020-10-19 21:32:33.65334" level=info msg="Transaction 4 successful!" loc="kvscheduler/txn_process.go(405)" logger=kvscheduler
      - values:
          - key: linux/interface/host-name/server-3b292af6
            val: <EMPTY>

time="2020-10-19 21:32:33.67924" level=debug msg="publish add to ifplugin_ifstate{{server-3b292af6-7a09-4f83-a6f7-39f79fb84035 false false vpp-interface-index} 0xc000ac7ae0}" loc="mem/inmemory_name_mapping.go(277)" logger=vpp-ifplugin.if-descriptor
o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:33.653 +0000 UTC -> 2020-10-19 21:32:33.681 +0000 UTC, dur: 29ms):
      1. CREATE [OBTAINED]:
          - key: linux/interface/host-name/server-3b292af6
          - value: <EMPTY> 
      2. CREATE [WAS-PENDING]:
          - key: config/vpp/v2/interfaces/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
          - value: { name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  type:AF_PACKET  enabled:true  afpacket:{host_if_name:"server-3b292af6"} } 
      3. CREATE [WAS-PENDING]:
          - key: config/vpp/l2/v2/xconnect/client-3b292af6-7a09-4f83-a6f7-39f79fb84035
          - value: { receive_interface:"client-3b292af6-7a09-4f83-a6f7-39f79fb84035"  transmit_interface:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035" } 
      4. CREATE [WAS-PENDING]:
          - key: config/vpp/l2/v2/xconnect/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
          - value: { receive_interface:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  transmit_interface:"client-3b292af6-7a09-4f83-a6f7-39f79fb84035" } 
x----------------------------------------------------------------------------------------------------------------------x
| #13 - SBNotification                                                                                     took 28.9ms |
x----------------------------------------------------------------------------------------------------------------------x

time="2020-10-19 21:32:33.68161" level=info msg="Transaction 13 successful!" loc="kvscheduler/txn_process.go(405)" logger=kvscheduler
time="2020-10-19 21:32:33.68168" level=info msg="finished waiting for pending keys to be done (took 486.299447ms)" loc="configurator/configurator.go(147)" logger=configurator.configurator
time="2020-10-19 21:32:33.68175" level=debug msg="config update finished with 8 results" loc="configurator/configurator.go(153)" logger=configurator.configurator
+======================================================================================================================+
| #14 - SBNotification                                                                                                 |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 14
      - type: SB Notification
      - values:
          - key: vpp/interface/server-3b292af6-7a09-4f83-a6f7-39f79fb84035/link-state/DOWN
            val: <EMPTY>

o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:33.682 +0000 UTC -> 2020-10-19 21:32:33.682 +0000 UTC, dur: 0s):
      1. CREATE [OBTAINED]:
          - key: vpp/interface/server-3b292af6-7a09-4f83-a6f7-39f79fb84035/link-state/DOWN
          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
| #14 - SBNotification                                                                                      took 100µs |
x----------------------------------------------------------------------------------------------------------------------x

Oct 19 21:32:33.681�[36m [INFO] �[0mUPDATE COMMIT TOOK 547.210853ms

@edwarnicke
Copy link
Contributor Author

edwarnicke commented Oct 19, 2020 •
edited
Loading

Similar log output from a different event:

Oct 19 21:32:44.127�[36m [INFO] �[0mSENDING UPDATE COMMIT: 
{
  "update": {
    "vpp_config": {
      "interfaces": [
        {
          "name": "server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0",
          "type": "MEMIF",
          "enabled": true,
          "memif": {
            "master": true,
            "socketFilename": "/tmp/forwarder-510286340/memif/362baafd-a5e4-4f6c-a6b2-e2bab84422f0.memif.socket"
          }
        },
        {
          "name": "client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0",
          "type": "AF_PACKET",
          "enabled": true,
          "afpacket": {
            "hostIfName": "client-362baafd"
          }
        }
      ],
      "xconnect_pairs": [
        {
          "receive_interface": "server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0",
          "transmit_interface": "client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"
        },
        {
          "receive_interface": "client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0",
          "transmit_interface": "server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"
        }
      ]
    },
    "linux_config": {
      "interfaces": [
        {
          "name": "client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth",
          "type": "VETH",
          "hostIfName": "client-362baafd",
          "enabled": true,
          "veth": {
            "peerIfName": "client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0",
            "rxChecksumOffloading": "CHKSM_OFFLOAD_DISABLED",
            "txChecksumOffloading": "CHKSM_OFFLOAD_DISABLED"
          }
        },
        {
          "name": "client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0",
          "type": "VETH",
          "namespace": {
            "type": "FD",
            "reference": "/proc/3601/fd/16"
          },
          "hostIfName": "m2kns-362baafd-",
          "enabled": true,
          "ipAddresses": [
            "10.0.0.0/32"
          ],
          "veth": {
            "peerIfName": "client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth",
            "rxChecksumOffloading": "CHKSM_OFFLOAD_DISABLED",
            "txChecksumOffloading": "CHKSM_OFFLOAD_DISABLED"
          }
        }
      ],
      "routes": [
        {
          "outgoing_interface": "client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0",
          "scope": 3,
          "dst_network": "10.0.0.1/32"
        }
      ]
    },
    "netalloc_config": {}
  },
  "wait_done": true
}
time="2020-10-19 21:32:44.12827" level=debug msg="Push data with 7 KV pairs (source: grpc)" loc="orchestrator/dispatcher.go(110)" logger=dispatcher
time="2020-10-19 21:32:44.12833" level=debug msg=" - UPDATE: \"config/vpp/v2/interfaces/server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:44.12836" level=debug msg=" - UPDATE: \"config/vpp/v2/interfaces/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:44.12840" level=debug msg=" - UPDATE: \"config/vpp/l2/v2/xconnect/server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:44.12843" level=debug msg=" - UPDATE: \"config/vpp/l2/v2/xconnect/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:44.12848" level=debug msg=" - UPDATE: \"config/linux/interfaces/v2/interface/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:44.12854" level=debug msg=" - UPDATE: \"config/linux/interfaces/v2/interface/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:44.12857" level=debug msg=" - UPDATE: \"config/linux/l3/v2/route/10.0.0.1/32/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
+======================================================================================================================+
| #23 - NBTransaction                                                                                                  |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 23
      - type: NB Transaction
      - values:
          - key: config/linux/interfaces/v2/interface/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
            val: { name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  type:VETH  namespace:{type:FD  reference:"/proc/3601/fd/16"}  host_if_name:"m2kns-362baafd-"  enabled:true  ip_addresses:"10.0.0.0/32"  veth:{peer_if_name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth"  rx_checksum_offloading:CHKSM_OFFLOAD_DISABLED  tx_checksum_offloading:CHKSM_OFFLOAD_DISABLED} }
          - key: config/linux/interfaces/v2/interface/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth
            val: { name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth"  type:VETH  host_if_name:"client-362baafd"  enabled:true  veth:{peer_if_name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  rx_checksum_offloading:CHKSM_OFFLOAD_DISABLED  tx_checksum_offloading:CHKSM_OFFLOAD_DISABLED} }
          - key: config/linux/l3/v2/route/10.0.0.1/32/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
            val: { outgoing_interface:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  scope:LINK  dst_network:"10.0.0.1/32" }
          - key: config/vpp/l2/v2/xconnect/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
            val: { receive_interface:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  transmit_interface:"server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0" }
          - key: config/vpp/l2/v2/xconnect/server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
            val: { receive_interface:"server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  transmit_interface:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0" }
          - key: config/vpp/v2/interfaces/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
            val: { name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  type:AF_PACKET  enabled:true  afpacket:{host_if_name:"client-362baafd"} }
          - key: config/vpp/v2/interfaces/server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
            val: { name:"server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  type:MEMIF  enabled:true  memif:{master:true  socket_filename:"/tmp/forwarder-510286340/memif/362baafd-a5e4-4f6c-a6b2-e2bab84422f0.memif.socket"} }

time="2020-10-19 21:32:44.17598" level=debug msg="Memif socket filename /tmp/forwarder-510286340/memif/362baafd-a5e4-4f6c-a6b2-e2bab84422f0.memif.socket registered under ID 2" loc="descriptor/interface.go(949)" logger=vpp-ifplugin.if-descriptor
vpp[3609]: memif_plugin: clib_file_add fd 15 private_data 2 idx 7

Oct 19 21:32:29.226�[36m [INFO] [cmd:vpp] �[0mvpp[3609]: memif_plugin: clib_file_add fd 15 private_data 2 idx 7
time="2020-10-19 21:32:44.17974" level=debug msg="publish add to ifplugin_ifstate{{server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0 false false vpp-interface-index} 0xc000665590}" loc="mem/inmemory_name_mapping.go(277)" logger=vpp-ifplugin.if-descriptor
o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:44.129 +0000 UTC -> 2020-10-19 21:32:44.18 +0000 UTC, dur: 51ms):
      1. CREATE:
          - key: config/linux/interfaces/v2/interface/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth
          - value: { name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth"  type:VETH  host_if_name:"client-362baafd"  enabled:true  veth:{peer_if_name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  rx_checksum_offloading:CHKSM_OFFLOAD_DISABLED  tx_checksum_offloading:CHKSM_OFFLOAD_DISABLED} } 
      2. CREATE:
          - key: config/linux/interfaces/v2/interface/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
          - value: { name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  type:VETH  namespace:{type:FD  reference:"/proc/3601/fd/16"}  host_if_name:"m2kns-362baafd-"  enabled:true  ip_addresses:"10.0.0.0/32"  veth:{peer_if_name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth"  rx_checksum_offloading:CHKSM_OFFLOAD_DISABLED  tx_checksum_offloading:CHKSM_OFFLOAD_DISABLED} } 
      3. CREATE [DERIVED]:
          - key: linux/interface/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0/address/static/10.0.0.0/32
          - value: <EMPTY> 
      4. CREATE [PROPERTY]:
          - key: linux/interface/state/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0/UP
          - value: <EMPTY> 
      5. CREATE [PROPERTY]:
          - key: linux/interface/state/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth/UP
          - value: <EMPTY> 
      6. CREATE:
          - key: config/linux/l3/v2/route/10.0.0.1/32/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
          - value: { outgoing_interface:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  scope:LINK  dst_network:"10.0.0.1/32" } 
      7. CREATE [PROPERTY]:
          - key: linux/link-local-route/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0/dest-address/10.0.0.1/32
          - value: <EMPTY> 
      8. CREATE [NOOP IS-PENDING]:
          - key: config/vpp/l2/v2/xconnect/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
          - value: { receive_interface:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  transmit_interface:"server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0" } 
      9. CREATE [NOOP IS-PENDING]:
          - key: config/vpp/l2/v2/xconnect/server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
          - value: { receive_interface:"server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  transmit_interface:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0" } 
      10. CREATE [NOOP IS-PENDING]:
          - key: config/vpp/v2/interfaces/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
          - value: { name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  type:AF_PACKET  enabled:true  afpacket:{host_if_name:"client-362baafd"} } 
      11. CREATE:
          - key: config/vpp/v2/interfaces/server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
          - value: { name:"server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  type:MEMIF  enabled:true  memif:{master:true  socket_filename:"/tmp/forwarder-510286340/memif/362baafd-a5e4-4f6c-a6b2-e2bab84422f0.memif.socket"} } 
x----------------------------------------------------------------------------------------------------------------------x
| #23 - NBTransaction                                                                                      took 51.3ms |
x----------------------------------------------------------------------------------------------------------------------x

+======================================================================================================================+
| #24 - SBNotification                                                                                                 |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 24
      - type: SB Notification
      - values:
          - key: vpp/interface/server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0/link-state/DOWN
            val: <EMPTY>

time="2020-10-19 21:32:44.18041" level=info msg="Transaction #23 successful! (took 51.7ms)" loc="orchestrator/dispatcher.go(178)" logger=dispatcher
o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:44.18 +0000 UTC -> 2020-10-19 21:32:44.18 +0000 UTC, dur: 0s):
      1. CREATE [OBTAINED]:
          - key: vpp/interface/server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0/link-state/DOWN
          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
| #24 - SBNotification                                                                                      took 100µs |
x----------------------------------------------------------------------------------------------------------------------x

time="2020-10-19 21:32:44.18053" level=info msg="Transaction 24 successful!" loc="kvscheduler/txn_process.go(405)" logger=kvscheduler
time="2020-10-19 21:32:44.18060" level=info msg="waiting for 3 pending keys to be done" loc="configurator/configurator.go(137)" logger=configurator.configurator
+======================================================================================================================+
| #6 - SBNotification                                                                                                  |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 6
      - type: SB Notification
      - values:
          - key: linux/interface/host-name/client-362baafd
            val: <EMPTY>

o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:44.646 +0000 UTC -> 2020-10-19 21:32:44.646 +0000 UTC, dur: 0s):
      1. CREATE [OBTAINED]:
          - key: linux/interface/host-name/client-362baafd
          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
+======================================================================================================================+
| #11 - SBNotification                                                                                                 |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 11
      - type: SB Notification
      - values:
          - key: linux/interface/host-name/client-362baafd
+======================================================================================================================+
| #25 - SBNotification                                                                                                 |
            val: <EMPTY>
+======================================================================================================================+
  * transaction arguments:

      - seqNum: 25
o----------------------------------------------------------------------------------------------------------------------o
      - type: SB Notification
  * executed operations (2020-10-19 21:32:44.646 +0000 UTC -> 2020-10-19 21:32:44.646 +0000 UTC, dur: 0s):
      - values:
      1. CREATE [OBTAINED]:
          - key: linux/interface/host-name/client-362baafd
            val: <EMPTY>
          - key: linux/interface/host-name/client-362baafd

          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
| #11 - SBNotification                                                                                      took 100µs |
x----------------------------------------------------------------------------------------------------------------------x

time="2020-10-19 21:32:44.64633" level=info msg="Transaction 11 successful!" loc="kvscheduler/txn_process.go(405)" logger=kvscheduler
| #6 - SBNotification                                                                                       took 100µs |
x----------------------------------------------------------------------------------------------------------------------x

time="2020-10-19 21:32:44.64634" level=info msg="Transaction 6 successful!" loc="kvscheduler/txn_process.go(405)" logger=kvscheduler
time="2020-10-19 21:32:44.67663" level=debug msg="publish add to ifplugin_ifstate{{client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0 false false vpp-interface-index} 0xc000ac6050}" loc="mem/inmemory_name_mapping.go(277)" logger=vpp-ifplugin.if-descriptor
time="2020-10-19 21:32:44.67928" level=info msg="finished waiting for pending keys to be done (took 498.663608ms)" loc="configurator/configurator.go(147)" logger=configurator.configurator
time="2020-10-19 21:32:44.67935" level=debug msg="config update finished with 8 results" loc="configurator/configurator.go(153)" logger=configurator.configurator
Oct 19 21:32:44.679�[36m [INFO] �[0mUPDATE COMMIT TOOK 552.087497ms
o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:44.646 +0000 UTC -> 2020-10-19 21:32:44.679 +0000 UTC, dur: 33ms):
      1. CREATE [OBTAINED]:
          - key: linux/interface/host-name/client-362baafd
          - value: <EMPTY> 
      2. CREATE [WAS-PENDING]:
          - key: config/vpp/v2/interfaces/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
          - value: { name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  type:AF_PACKET  enabled:true  afpacket:{host_if_name:"client-362baafd"} } 
      3. CREATE [WAS-PENDING]:
          - key: config/vpp/l2/v2/xconnect/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
          - value: { receive_interface:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  transmit_interface:"server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0" } 
      4. CREATE [WAS-PENDING]:
          - key: config/vpp/l2/v2/xconnect/server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
          - value: { receive_interface:"server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  transmit_interface:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0" } 
Oct 19 21:32:44.679�[36m [INFO] [cmd:forwarder] �[0m>><<---------------------------------------- response={"id":"362baafd-a5e4-4f6c-a6b2-e2bab84422f0","network_service":"m2kns","mechanism":{"cls":"LOCAL","type":"MEMIF","parameters":{"inodeURL":"inode://109/1463156"}},"context":{"ip_context":{"src_ip_addr":"10.0.0.1/32","dst_ip_addr":"10.0.0.0/32"}},"path":{"index":1,"path_segments":[{"name":"testClient","id":"91b29fdb-b41a-4d8d-bc2e-b9517f1aba6c","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJleHAiOjE2MDMxNDY3NDksInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL2NtZC1mb3J3YXJkZXItdnBwYWdlbnQudGVzdCJ9.7utLndTifFJ4f5isKk55C4vRA1B4uW7cfCRV0E2438unyDtquCucIVPFJAGUhpL-3yPBISC81qa22_x1wSSZ_g","expires":{"seconds":1603146749}},{"name":"forwarder","id":"362baafd-a5e4-4f6c-a6b2-e2bab84422f0","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9jbWQtZm9yd2FyZGVyLXZwcGFnZW50LnRlc3QiLCJleHAiOjE2MDMxNDY3NDksInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL2ZvcndhcmRlciJ9.187rsKzzA_pPCFGD11CEMKkUtzh2uC2ruF1BQWZcnZ6WYGuoIZlroSByDJ61XxAEptZeM9WtQ1C12DRaHKWkPg","expires":{"seconds":1603146749}},{"name":"testServer","id":"2de8cbc8-c391-420e-b771-bf1c8121ab0d","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9mb3J3YXJkZXIiLCJleHAiOjE2MDMxNDY3NDksInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL2NtZC1mb3J3YXJkZXItdnBwYWdlbnQudGVzdCJ9.Mdc3VufZs5dMSZfzQ-CJNWPq7Bklv7FR-9P-biLDCkKUvVAwipEyaY6A5tUa6G28NKiNEa038vtJNUzo6ZW3qQ","expires":{"seconds":1603146749}}]}} span={}
Oct 19 21:32:44.680�[36m [INFO] [cmd:forwarder] �[0m>><<-------------------------------------- response={"id":"362baafd-a5e4-4f6c-a6b2-e2bab84422f0","network_service":"m2kns","mechanism":{"cls":"LOCAL","type":"MEMIF","parameters":{"inodeURL":"inode://109/1463156"}},"context":{"ip_context":{"src_ip_addr":"10.0.0.1/32","dst_ip_addr":"10.0.0.0/32"}},"path":{"index":1,"path_segments":[{"name":"testClient","id":"91b29fdb-b41a-4d8d-bc2e-b9517f1aba6c","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJleHAiOjE2MDMxNDY3NDksInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL2NtZC1mb3J3YXJkZXItdnBwYWdlbnQudGVzdCJ9.7utLndTifFJ4f5isKk55C4vRA1B4uW7cfCRV0E2438unyDtquCucIVPFJAGUhpL-3yPBISC81qa22_x1wSSZ_g","expires":{"seconds":1603146749}},{"name":"forwarder","id":"362baafd-a5e4-4f6c-a6b2-e2bab84422f0","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9jbWQtZm9yd2FyZGVyLXZwcGFnZW50LnRlc3QiLCJleHAiOjE2MDMxNDY3NDksInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL2ZvcndhcmRlciJ9.187rsKzzA_pPCFGD11CEMKkUtzh2uC2ruF1BQWZcnZ6WYGuoIZlroSByDJ61XxAEptZeM9WtQ1C12DRaHKWkPg","expires":{"seconds":1603146749}},{"name":"testServer","id":"2de8cbc8-c391-420e-b771-bf1c8121ab0d","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9mb3J3YXJkZXIiLCJleHAiOjE2MDMxNDY3NDksInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL2NtZC1mb3J3YXJkZXItdnBwYWdlbnQudGVzdCJ9.Mdc3VufZs5dMSZfzQ-CJNWPq7Bklv7FR-9P-biLDCkKUvVAwipEyaY6A5tUa6G28NKiNEa038vtJNUzo6ZW3qQ","expires":{"seconds":1603146749}}]}} span={}
Oct 19 21:32:44.680�[37m [DEBU] [operation:github.com/networkservicemesh/sdk-vppagent/pkg/networkservice/metrics/metricsServer.Request] [span:{}] �[0mMetricsServer: Request Metrics
x----------------------------------------------------------------------------------------------------------------------x
| #25 - SBNotification                                                                                     took 32.6ms |
x----------------------------------------------------------------------------------------------------------------------x

time="2020-10-19 21:32:44.67971" level=info msg="Transaction 25 successful!" loc="kvscheduler/txn_process.go(405)" logger=kvscheduler
+======================================================================================================================+
| #26 - SBNotification                                                                                                 |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 26
      - type: SB Notification
      - values:
          - key: vpp/interface/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0/link-state/DOWN
            val: <EMPTY>

o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:44.68 +0000 UTC -> 2020-10-19 21:32:44.68 +0000 UTC, dur: 0s):
      1. CREATE [OBTAINED]:
          - key: vpp/interface/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0/link-state/DOWN
          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
| #26 - SBNotification                                                                                      took 100µs |
x----------------------------------------------------------------------------------------------------------------------x

time="2020-10-19 21:32:44.67994" level=info msg="Transaction 26 successful!" loc="kvscheduler/txn_process.go(405)" logger=kvscheduler
time="2020-10-19 21:32:44.68123" level=debug msg="streaming 4 interface stats" loc="telemetry/stats_poller.go(106)" logger=telemetry.stats-poller
time="2020-10-19 21:32:44.68137" level=debug msg="sending vpp stats: interface:{name:\"UNTAGGED-local0\"  rx:{}  tx:{}  rx_unicast:{}  rx_multicast:{}  rx_broadcast:{}  tx_unicast:{}  tx_multicast:{}  tx_broadcast:{}}" loc="telemetry/stats_poller.go(48)" logger=telemetry.stats-poller
time="2020-10-19 21:32:44.68152" level=debug msg="sending vpp stats: interface:{name:\"eth0\"  rx:{packets:2  bytes:112}  tx:{packets:1  bytes:42}  rx_unicast:{}  rx_multicast:{}  rx_broadcast:{}  tx_unicast:{}  tx_multicast:{}  tx_broadcast:{}  drops:2  ip6:1}" loc="telemetry/stats_poller.go(48)" logger=telemetry.stats-poller
time="2020-10-19 21:32:44.68167" level=debug msg="sending vpp stats: interface:{name:\"server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0\"  rx:{}  tx:{}  rx_unicast:{}  rx_multicast:{}  rx_broadcast:{}  tx_unicast:{}  tx_multicast:{}  tx_broadcast:{}}" loc="telemetry/stats_poller.go(48)" logger=telemetry.stats-poller

@edwarnicke edwarnicke changed the title vpp-agent taking 500ms (with WaidDone == true) for simple transaction vpp-agent taking 500ms (with WaitDone == true) for simple transaction Oct 19, 2020
@edwarnicke
Copy link
Contributor Author

edwarnicke commented Oct 19, 2020 •
edited
Loading

Looks like 2ms from when I send my call till you start your first execution: super good!

Oct 19 21:32:44.127�[36m [INFO] �[0mSENDING UPDATE COMMIT: 
...
executed operations (2020-10-19 21:32:44.129 +0000 UTC -> 2020-10-19 21:32:44.18 +0000 UTC, dur: 51ms):

and pretty much instantly returned after its last execution (note: log ordering got a little messed up here, but check the timestamps).

Oct 19 21:32:44.679�[36m [INFO] �[0mUPDATE COMMIT TOOK 552.087497ms
* executed operations (2020-10-19 21:32:44.68 +0000 UTC -> 2020-10-19 21:32:44.68 +0000 UTC, dur: 0s):

@edwarnicke
Copy link
Contributor Author

edwarnicke commented Oct 19, 2020 •
edited
Loading

Looks like 551ms is accounted for by the execution - so we know where all the time is going here.

executed operations (2020-10-19 21:32:44.129 +0000 UTC -> 2020-10-19 21:32:44.18 +0000 UTC, dur: 51ms):
...
* executed operations (2020-10-19 21:32:44.18 +0000 UTC -> 2020-10-19 21:32:44.18 +0000 UTC, dur: 0s):
...
* executed operations (2020-10-19 21:32:44.646 +0000 UTC -> 2020-10-19 21:32:44.646 +0000 UTC, dur: 0s):
...
* executed operations (2020-10-19 21:32:44.646 +0000 UTC -> 2020-10-19 21:32:44.646 +0000 UTC, dur: 0s):
...
* executed operations (2020-10-19 21:32:44.646 +0000 UTC -> 2020-10-19 21:32:44.679 +0000 UTC, dur: 33ms):
...
 * executed operations (2020-10-19 21:32:44.68 +0000 UTC -> 2020-10-19 21:32:44.68 +0000 UTC, dur: 0s):

@edwarnicke
Copy link
Contributor Author

Related to: #1739

@ondrej-fabry
Copy link
Member

Could you mention exact vpp-agent version as well? If you print the header of the log it is next to the logo.

@edwarnicke
Copy link
Contributor Author

vppagent version from the go.mod:

go.ligato.io/vpp-agent/v3 v3.2.0-alpha.0.20201016122127-eca11ab3bbca

And the Dockerfile:

FROM ligato/vpp-agent:latest as go

@ondrej-fabry
Copy link
Member

ondrej-fabry commented Oct 20, 2020 •
edited
Loading

vppagent version from the go.mod:

go.ligato.io/vpp-agent/v3 v3.2.0-alpha.0.20201016122127-eca11ab3bbca

This should not really matter as you only use vpp-agent Go module for generated gRPC client and this issue is about server behavior.

And the Dockerfile:

FROM ligato/vpp-agent:latest as go

That is not unique identifier..

To be reference docker image uniquely, use Digest (or RepoDigest) that shows up in docker inspect <image> or when in output of docker pull:

Digest: sha256:d11256b24c296117cdce33382571c7525bd4f6d76066b327229e051679a3ac93

Or even better would be to copy this part of the log with logo:

                                       __
  _  _____  ___ _______ ____ ____ ___ / /_  
 | |/ / _ \/ _ /___/ _ '/ _ '/ -_/ _ / __/  vpp-agent v3.2.0-alpha-75-geca11ab3b
 |___/ .__/ .__/   \_'_/\_' /\__/_//_\__/   Fri Oct 16 12:21:57 UTC 2020 (6 minutes ago)
    /_/  /_/           /___/                root@97d8490f6cf1 (go1.15.2 linux/amd64)

@edwarnicke
Copy link
Contributor Author

edwarnicke commented Oct 20, 2020 •
edited
Loading 

                                       __
  _  _____  ___ _______ ____ ____ ___ / /_  
 | |/ / _ \/ _ /___/ _ '/ _ '/ -_/ _ / __/  vpp-agent v3.2.0-alpha-67-g0ead9d2f7
 |___/ .__/ .__/   \_'_/\_' /\__/_//_\__/   Mon Oct  5 11:47:39 UTC 2020 (15 days ago)
    /_/  /_/           /___/                root@c4b52bfc2c26 (go1.15.2 linux/amd64)

@ondrej-fabry
Copy link
Member

Please update your image you seem to have older version that did not have the fix: 6766786

@edwarnicke
Copy link
Contributor Author

Updated images and a few observations:

  1. I am not obviously seeing the interface up issue, but need to beat on it a bit more (its a race condition) to be certain.
  2. I do appear to be seeing 'the routes aren't programmed in the namespace' as an issue... is that something we should open a new issue for?
  3. Much much faster... except on startup where there are still some issues apparent. Will marshal more data for you on that.

@ondrej-fabry
Copy link
Member

Updated images and a few observations:

1. I am not obviously seeing the interface up issue, but need to beat on it a bit more (its a race condition) to be certain.

Tracked in #1751

2. I _do_ appear to be seeing 'the routes aren't programmed in the namespace' as an issue... is that something we should open a new issue for?

Yes, open new issue please.

3. Much much faster... except on startup where there are still some issues apparent.  Will marshal more data for you on that.

Kinda tracked in #1749

@ondrej-fabry
Copy link
Member

ondrej-fabry commented Oct 20, 2020 •
edited
Loading

Can I close this issue? Other problems are unrelated to this issue of "WaitDone taking ~500ms.." and should be tracked separately.

@edwarnicke
Copy link
Contributor Author

Don't close quite yet, need to beat on it a bit more to be sure.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
✖️invalid
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@edwarnicke @ondrej-fabry