yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1651368] Re: Dhcpagent not efficient during initialization process

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: OpenStack Infra <1651368@xxxxxxxxxxxxxxxxxx>
Date: Thu, 19 Jan 2017 08:25:30 -0000
Reply-to: Bug 1651368 <1651368@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Reviewed:  https://review.openstack.org/413010
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=f15851b98974dc16606da195cf3ecee577cd0ef8
Submitter: Jenkins
Branch:    master

commit f15851b98974dc16606da195cf3ecee577cd0ef8
Author: Bertrand Lallau <bertrand.lallau@xxxxxxxxxxxxxxx>
Date:   Tue Dec 20 10:53:41 2016 +0100

    DHCP: enhance DHCPAgent startup procedure
    
    During DhcpAgent startup procedure all the following networks
    initialization is actually perform twice:
     * Killing old dnsmasq processes
     * set and configure all TAP interfaces
     * building all Dnsmasq config files (lease and host files)
     * launching dnsmasq processes
    What is done during the second iteration is just clean and redo
    exactly the same another time! This is really inefficient and
    increase dramatically DHCP startup time (near twice than needed).
    
    Initialization process 'sync_state' method is called twice:
     * one time during init_host()
     * another time during _report_state()
    
    sync_state() call must stay in init_host() due to bug #1420042.
    
    sync_state() is always called during startup in init_host()
    and will be periodically called by periodic_resync()
    to do reconciliation.
    Hence it can safely be removed from the run() method.
    
    Change-Id: Id6433598d5c833d2e86be605089d42feee57c257
    Closes-bug: #1651368
    Closes-Bug: #1650611


** Changed in: neutron
       Status: In Progress => Fix Released

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/1651368

Title:
  Dhcpagent not efficient during initialization process

Status in neutron:
  Fix Released

Bug description:
  During DhcpAgent startup procedure all networks initialization will be done twice:
   * Killing old dnsmasq processes
   * set and configure all TAP interfaces
   * building all Dnsmasq config files (lease and host files)
   * launching dnsmasq processes
  This is really inefficient and can be strange in case of namespaces monitoring.

  The following Dhcpagent traces show the actual init process
  (logs have been cleanup to show only relevant informations)
  Explanations details are described after logs.


  2016-12-20 09:02:42.200 DEBUG neutron.openstack.common.service [req-b0a2772 None None] ******************************************************************************** log_opt_values /usr/lib/python2.7/dist-packages/oslo_config/cfg.py:2197
  2016-12-20 09:02:42.214 INFO neutron.agent.dhcp.agent [-] Synchronizing state
  2016-12-20 09:02:43.262 DEBUG neutron.agent.dhcp.agent [-] Calling driver for network: 5be9fe58-0790-4342-9182-172438e8e0bc action: enable call_driver /usr/lib/python2.7/dist-packages/neutron/agent/dhcp/agent.py:106
  2016-12-20 09:02:43.314 DEBUG neutron.agent.dhcp.agent [-] Calling driver for network: f2a73fc1-6a93-4822-aa45-3333b789d50d action: enable call_driver /usr/lib/python2.7/dist-packages/neutron/agent/dhcp/agent.py:106
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'kill', '-9', '24540']
  2016-12-20 09:02:43.441 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'kill', '-9', '24542']
  2016-12-20 09:02:43.459 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'link', 'set', 'tap5c7f794d-08', 'up']
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'link', 'set', 'tap995da463-09', 'up']
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'addr', 'show', 'tap5c7f794d-08', 'permanent', 'scope', 'global']
  Stdout: 32: tap5c7f794d-08: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
      link/ether fa:16:3e:6b:cb:29 brd ff:ff:ff:ff:ff:ff
      inet 20.0.0.36/24 brd 20.0.0.255 scope global tap5c7f794d-08
         valid_lft forever preferred_lft forever
      inet 169.254.169.254/16 brd 169.254.255.255 scope global tap5c7f794d-08
         valid_lft forever preferred_lft forever

  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'addr', 'show', 'tap995da463-09', 'permanent', 'scope', 'global']
  Stdout: 35: tap995da463-09: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
      link/ether fa:16:3e:49:6e:68 brd ff:ff:ff:ff:ff:ff
      inet 20.0.1.36/24 brd 20.0.1.255 scope global tap995da463-09
         valid_lft forever preferred_lft forever
      inet 169.254.169.254/16 brd 169.254.255.255 scope global tap995da463-09
         valid_lft forever preferred_lft forever

  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', '-4', 'route', 'list', 'dev', 'tap995da463-09', 'scope', 'link']
  Stdout: 20.0.1.0/24  proto kernel  src 20.0.1.36
  169.254.0.0/16  proto kernel  src 169.254.169.254

  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', '-4', 'route', 'list', 'dev', 'tap5c7f794d-08', 'scope', 'link']
  Stdout: 20.0.0.0/24  proto kernel  src 20.0.0.36
  169.254.0.0/16  proto kernel  src 169.254.169.254

  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', '-6', 'route', 'list', 'dev', 'tap995da463-09', 'scope', 'link']
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', '-6', 'route', 'list', 'dev', 'tap5c7f794d-08', 'scope', 'link']
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'route', 'list', 'dev', 'tap995da463-09']
  Stdout: 20.0.1.0/24  proto kernel  scope link  src 20.0.1.36
  169.254.0.0/16  proto kernel  scope link  src 169.254.169.254
  2016-12-20 09:02:44.154 DEBUG neutron.agent.linux.dhcp [-] Building initial lease file: /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/leases _output_init_lease_file /home/T0125936/work/curr/neutron/neutron/agent/linux/dhcp.py:480
  2016-12-20 09:02:44.155 DEBUG neutron.agent.linux.dhcp [-] Done building initial lease file /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/leases with contents:
  1482310964 fa:16:3e:49:6e:68 20.0.1.36 * *
  1482310964 fa:16:3e:81:6c:f3 20.0.1.35 * *
   _output_init_lease_file /home/T0125936/work/curr/neutron/neutron/agent/linux/dhcp.py:507
  2016-12-20 09:02:44.156 DEBUG neutron.agent.linux.dhcp [-] Building host file: /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/host _output_hosts_file neutron/agent/linux/dhcp.py:538
  2016-12-20 09:02:44.156 DEBUG neutron.agent.linux.dhcp [-] Done building host file /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/host with contents:
  fa:16:3e:49:6e:68,host-20-0-1-36.openstacklocal,20.0.1.36
  fa:16:3e:81:6c:f3,host-20-0-1-35.openstacklocal,20.0.1.35
   _output_hosts_file neutron/agent/linux/dhcp.py:567
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'route', 'list', 'dev', 'tap5c7f794d-08']
  Stdout: 20.0.0.0/24  proto kernel  scope link  src 20.0.0.36
  169.254.0.0/16  proto kernel  scope link  src 169.254.169.254

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  2016-12-20 09:02:44.173 DEBUG neutron.agent.linux.dhcp [-] Building initial lease file: /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/leases _output_init_lease_file neutron/agent/linux/dhcp.py:480
  2016-12-20 09:02:44.173 DEBUG neutron.agent.linux.dhcp [-] Done building initial lease file /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/leases with contents:
  1482310964 fa:16:3e:6b:cb:29 20.0.0.36 * *
  1482310964 fa:16:3e:74:32:29 20.0.0.35 * *
   _output_init_lease_file neutron/agent/linux/dhcp.py:507
  2016-12-20 09:02:44.174 DEBUG neutron.agent.linux.dhcp [-] Building host file: /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/host _output_hosts_file neutron/agent/linux/dhcp.py:538
  2016-12-20 09:02:44.175 DEBUG neutron.agent.linux.dhcp [-] Done building host file /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/host with contents:
  fa:16:3e:6b:cb:29,host-20-0-0-36.openstacklocal,20.0.0.36
  fa:16:3e:74:32:29,host-20-0-0-35.openstacklocal,20.0.0.35
   _output_hosts_file neutron/agent/linux/dhcp.py:567
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'addr', 'show', 'tap995da463-09']
  Stdout: 35: tap995da463-09: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
      link/ether fa:16:3e:49:6e:68 brd ff:ff:ff:ff:ff:ff
      inet 20.0.1.36/24 brd 20.0.1.255 scope global tap995da463-09
         valid_lft forever preferred_lft forever
      inet 169.254.169.254/16 brd 169.254.255.255 scope global tap995da463-09
         valid_lft forever preferred_lft forever
      inet6 fe80::f816:3eff:fe49:6e68/64 scope link
         valid_lft forever preferred_lft forever

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  2016-12-20 09:02:44.293 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'addr', 'show', 'tap5c7f794d-08']
  Stdout: 32: tap5c7f794d-08: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
      link/ether fa:16:3e:6b:cb:29 brd ff:ff:ff:ff:ff:ff
      inet 20.0.0.36/24 brd 20.0.0.255 scope global tap5c7f794d-08
         valid_lft forever preferred_lft forever
      inet 169.254.169.254/16 brd 169.254.255.255 scope global tap5c7f794d-08
         valid_lft forever preferred_lft forever
      inet6 fe80::f816:3eff:fe6b:cb29/64 scope link
         valid_lft forever preferred_lft forever

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  2016-12-20 09:02:44.313 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'dnsmasq', '--no-hosts', '--no-resolv', '--strict-order', '--bind-interfaces', '--interface=tap995da463-09', '--except-interface=lo', '--pid-file=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/pid', '--dhcp-hostsfile=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/host', '--addn-hosts=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/addn_hosts', '--dhcp-optsfile=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/opts', '--dhcp-leasefile=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/leases', '--dhcp-range=set:tag0,20.0.1.0,static,86400s', '--dhcp-lease-max=256', '--conf-file=/etc/neutron/dnsmasq.conf', '--domain=openstacklocal']
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'dnsmasq', '--no-hosts', '--no-resolv', '--strict-order', '--bind-interfaces', '--interface=tap5c7f794d-08', '--except-interface=lo', '--pid-file=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/pid', '--dhcp-hostsfile=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/host', '--addn-hosts=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/addn_hosts', '--dhcp-optsfile=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/opts', '--dhcp-leasefile=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/leases', '--dhcp-range=set:tag0,20.0.0.0,static,86400s', '--dhcp-lease-max=256', '--conf-file=/etc/neutron/dnsmasq.conf', '--domain=openstacklocal']
  2016-12-20 09:02:44.441 INFO neutron.agent.dhcp.agent [-] Synchronizing state complete

  2016-12-20 09:02:44.453 DEBUG oslo_concurrency.lockutils [req-555b9ae None None] Lock "dhcp-agent" acquired by "sync_state" :: waited 2.081s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:444
  2016-12-20 09:02:44.453 INFO neutron.agent.dhcp.agent [req-555b9ae None None] Synchronizing state
  2016-12-20 09:02:44.479 INFO neutron.agent.dhcp.agent [-] DHCP agent started
  2016-12-20 09:02:44.696 DEBUG neutron.agent.dhcp.agent [-] Calling driver for network: 5be9fe58-0790-4342-9182-172438e8e0bc action: enable call_driver /usr/lib/python2.7/dist-packages/neutron/agent/dhcp/agent.py:106
  2016-12-20 09:02:44.704 DEBUG neutron.agent.dhcp.agent [-] Calling driver for network: f2a73fc1-6a93-4822-aa45-3333b789d50d action: enable call_driver /usr/lib/python2.7/dist-packages/neutron/agent/dhcp/agent.py:106
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'kill', '-9', '24936']
  2016-12-20 09:02:44.820 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
  2016-12-20 09:02:44.836 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'link', 'set', 'tap5c7f794d-08', 'up']
  2016-12-20 09:02:45.126 DEBUG neutron.agent.linux.dhcp [-] Reusing existing device: tap5c7f794d-08. setup neutron/agent/linux/dhcp.py:1009
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'link', 'set', 'tap995da463-09', 'up']
  2016-12-20 09:02:45.192 DEBUG neutron.agent.linux.dhcp [-] Reusing existing device: tap995da463-09. setup neutron/agent/linux/dhcp.py:1009
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'addr', 'show', 'tap5c7f794d-08', 'permanent', 'scope', 'global']
  Stdout: 32: tap5c7f794d-08: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
      link/ether fa:16:3e:6b:cb:29 brd ff:ff:ff:ff:ff:ff
      inet 20.0.0.36/24 brd 20.0.0.255 scope global tap5c7f794d-08
         valid_lft forever preferred_lft forever
      inet 169.254.169.254/16 brd 169.254.255.255 scope global tap5c7f794d-08
         valid_lft forever preferred_lft forever

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  2016-12-20 09:02:45.386 DEBUG neutron.agent.linux.utils [-]
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'addr', 'show', 'tap995da463-09', 'permanent', 'scope', 'global']
  Stdout: 35: tap995da463-09: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
      link/ether fa:16:3e:49:6e:68 brd ff:ff:ff:ff:ff:ff
      inet 20.0.1.36/24 brd 20.0.1.255 scope global tap995da463-09
         valid_lft forever preferred_lft forever
      inet 169.254.169.254/16 brd 169.254.255.255 scope global tap995da463-09
         valid_lft forever preferred_lft forever

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', '-4', 'route', 'list', 'dev', 'tap5c7f794d-08', 'scope', 'link']
  Stdout: 20.0.0.0/24  proto kernel  src 20.0.0.36
  169.254.0.0/16  proto kernel  src 169.254.169.254

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', '-4', 'route', 'list', 'dev', 'tap995da463-09', 'scope', 'link']
  Stdout: 20.0.1.0/24  proto kernel  src 20.0.1.36
  169.254.0.0/16  proto kernel  src 169.254.169.254

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', '-6', 'route', 'list', 'dev', 'tap5c7f794d-08', 'scope', 'link']
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', '-6', 'route', 'list', 'dev', 'tap995da463-09', 'scope', 'link']
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'route', 'list', 'dev', 'tap5c7f794d-08']
  Stdout: 20.0.0.0/24  proto kernel  scope link  src 20.0.0.36
  169.254.0.0/16  proto kernel  scope link  src 169.254.169.254

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  2016-12-20 09:02:45.862 DEBUG neutron.agent.linux.dhcp [-] Building initial lease file: /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/leases _output_init_lease_file neutron/agent/linux/dhcp.py:480
  2016-12-20 09:02:45.863 DEBUG neutron.agent.linux.dhcp [-] Done building initial lease file /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/leases with contents:
  1482310965 fa:16:3e:6b:cb:29 20.0.0.36 * *
  1482310965 fa:16:3e:74:32:29 20.0.0.35 * *
   _output_init_lease_file neutron/agent/linux/dhcp.py:507
  2016-12-20 09:02:45.865 DEBUG neutron.agent.linux.dhcp [-] Building host file: /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/host _output_hosts_file neutron/agent/linux/dhcp.py:538
  2016-12-20 09:02:45.874 DEBUG neutron.agent.linux.dhcp [-] Done building host file /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/host with contents:
  fa:16:3e:6b:cb:29,host-20-0-0-36.openstacklocal,20.0.0.36
  fa:16:3e:74:32:29,host-20-0-0-35.openstacklocal,20.0.0.35
   _output_hosts_file neutron/agent/linux/dhcp.py:567
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'route', 'list', 'dev', 'tap995da463-09']
  Exit code: 0
  Stdin:
  Stdout: 20.0.1.0/24  proto kernel  scope link  src 20.0.1.36
  169.254.0.0/16  proto kernel  scope link  src 169.254.169.254

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  2016-12-20 09:02:45.971 DEBUG neutron.agent.linux.dhcp [-] Building initial lease file: /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/leases _output_init_lease_file neutron/agent/linux/dhcp.py:480
  2016-12-20 09:02:45.977 DEBUG neutron.agent.linux.dhcp [-] Done building initial lease file /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/leases with contents:
  1482310965 fa:16:3e:49:6e:68 20.0.1.36 * *
  1482310965 fa:16:3e:81:6c:f3 20.0.1.35 * *
   _output_init_lease_file neutron/agent/linux/dhcp.py:507
  2016-12-20 09:02:45.978 DEBUG neutron.agent.linux.dhcp [-] Building host file: /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/host _output_hosts_file neutron/agent/linux/dhcp.py:538
  2016-12-20 09:02:45.986 DEBUG neutron.agent.linux.dhcp [-] Done building host file /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/host with contents:
  fa:16:3e:49:6e:68,host-20-0-1-36.openstacklocal,20.0.1.36
  fa:16:3e:81:6c:f3,host-20-0-1-35.openstacklocal,20.0.1.35
   _output_hosts_file neutron/agent/linux/dhcp.py:567
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'addr', 'show', 'tap5c7f794d-08']
  Stdout: 32: tap5c7f794d-08: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
      link/ether fa:16:3e:6b:cb:29 brd ff:ff:ff:ff:ff:ff
      inet 20.0.0.36/24 brd 20.0.0.255 scope global tap5c7f794d-08
         valid_lft forever preferred_lft forever
      inet 169.254.169.254/16 brd 169.254.255.255 scope global tap5c7f794d-08
         valid_lft forever preferred_lft forever
      inet6 fe80::f816:3eff:fe6b:cb29/64 scope link
         valid_lft forever preferred_lft forever

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  2016-12-20 09:02:46.107 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'addr', 'show', 'tap995da463-09']
  Stdout: 35: tap995da463-09: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
      link/ether fa:16:3e:49:6e:68 brd ff:ff:ff:ff:ff:ff
      inet 20.0.1.36/24 brd 20.0.1.255 scope global tap995da463-09
         valid_lft forever preferred_lft forever
      inet 169.254.169.254/16 brd 169.254.255.255 scope global tap995da463-09
         valid_lft forever preferred_lft forever
      inet6 fe80::f816:3eff:fe49:6e68/64 scope link
         valid_lft forever preferred_lft forever

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  2016-12-20 09:02:46.259 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'dnsmasq', '--no-hosts', '--no-resolv', '--strict-order', '--bind-interfaces', '--interface=tap5c7f794d-08', '--except-interface=lo', '--pid-file=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/pid', '--dhcp-hostsfile=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/host', '--addn-hosts=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/addn_hosts', '--dhcp-optsfile=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/opts', '--dhcp-leasefile=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/leases', '--dhcp-range=set:tag0,20.0.0.0,static,86400s', '--dhcp-lease-max=256', '--conf-file=/etc/neutron/dnsmasq.conf', '--domain=openstacklocal']
  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'dnsmasq', '--no-hosts', '--no-resolv', '--strict-order', '--bind-interfaces', '--interface=tap995da463-09', '--except-interface=lo', '--pid-file=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/pid', '--dhcp-hostsfile=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/host', '--addn-hosts=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/addn_hosts', '--dhcp-optsfile=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/opts', '--dhcp-leasefile=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/leases', '--dhcp-range=set:tag0,20.0.1.0,static,86400s', '--dhcp-lease-max=256', '--conf-file=/etc/neutron/dnsmasq.conf', '--domain=openstacklocal']
  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  2016-12-20 09:02:46.483 INFO neutron.agent.dhcp.agent [req-555b9ae None None] Synchronizing state complete
  2016-12-20 09:02:46.483 DEBUG oslo_concurrency.lockutils [req-555b9ae None None] Lock "dhcp-agent" released by "sync_state" :: held 2.031s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:456

  ***************** 
    Explanations
  *****************
  09:02:42.200: Dhcpagent config is loaded

  09:02:42.214: FIRST networks initialization BEGIN
  09:02:43.441: killing dnsmasq processes
  09:02:43.459 - 09:02:44.154: TAP interfaces configuration
  09:02:44.154 - 09:02:44.175: building dnsmasq files
  09:02:44.313 - 09:02:44.441: launching dnsmasq processes
  09:02:44.441: FIRST networks initialization END

  09:02:44.453: SECOND networks initialization BEGIN
  09:02:44.704: killing DNSMASQ processes
  09:02:44.836 - 09:02:45.862: TAP interfaces configuration
  09:02:45.862 - 09:02:46.107: building dnsmasq files
  09:02:46.259 - 09:02:46.483: launching dnsmasq processes
  09:02:46.483: SECOND networks initialization END

To manage notifications about this bug go to:
https://bugs.launchpad.net/neutron/+bug/1651368/+subscriptions
References

[Bug 1651368] [NEW] Dhcpagent not efficient during initialization process
From: Bertrand Lallau, 2016-12-20