| 2012-06-19 01:43:09 |
Gary Poster |
description |
We are gathering more data, but it feels like we have enough to start a bug report.
On Precise, on a 16 core/32 thread EC2 machine (instance type cc2.8xlarge), when starting approximately eight or more Lucid containers simultaneously, after the first seven or so connect to dnsmasq within just a few seconds, the next group takes just under three minutes to connect. We will provide short steps to duplicate this.
We also have past experience indicating that more grouping occurs, because simultaneously starting 32 containers occasionally (about once in 15 attempts) will result in one container that still has not connected to dnsmasq after ten minutes. We have not tried to duplicate this, because we hope that tackling the smaller issue will also address the larger one.
I have not yet had enough disk space on this machine to duplicate this without lxc-start-ephemeral. I intend to do so.
I have tried with a precise container. *Precise containers do not exhibit this bug* in the experiment I performed, at least up to 16 containers. I plan to duplicate this at least a couple more times to verify, but I'm comfortable saying initially that I believe this is specific to Lucid containers. I'll report back.
To duplicate (again, I am doing this on a specific EC2 machine with a lot of cores, but I believe you can see something similar to this even on a 4 core/8 hyperthread machine):
sudo apt-get install moreutils
sudo lxc-create -t ubuntu -n lucid -- -r lucid -a i386 -b ubuntu
parallel -j 16 bash -c "lxc-start-ephemeral -d -o lucid" -- 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16
Now look at /var/log/syslog at the most recent dnsmasq entries. You will see about seven containers get DHCPACK from dnsmasq within about 20 seconds; then you will see a pause of about three minutes; then you will see more containers report to dnsmasq. Here's an excerpt (the approximate three minute jump happens between lines 5 and 6):
...
Jun 18 20:40:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPACK(lxcbr0) 10.0.3.161 00:16:3e:38:9f:e2 lptests-temp-5uKcEua
Jun 18 20:40:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPREQUEST(lxcbr0) 10.0.3.37 00:16:3e:9c:ae:16
Jun 18 20:40:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPACK(lxcbr0) 10.0.3.37 00:16:3e:9c:ae:16 lptests-temp-1HxiwbU
Jun 18 20:40:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPREQUEST(lxcbr0) 10.0.3.62 00:16:3e:69:83:2b
Jun 18 20:40:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPACK(lxcbr0) 10.0.3.62 00:16:3e:69:83:2b lptests-temp-6o30rvH
Jun 18 20:43:05 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPDISCOVER(lxcbr0) 10.0.3.123 00:16:3e:0d:7b:65
Jun 18 20:43:05 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPOFFER(lxcbr0) 10.0.3.203 00:16:3e:0d:7b:65
Jun 18 20:43:08 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPDISCOVER(lxcbr0) 10.0.3.123 00:16:3e:32:5b:99
Jun 18 20:43:08 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPOFFER(lxcbr0) 10.0.3.68 00:16:3e:32:5b:99
Jun 18 20:43:11 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPDISCOVER(lxcbr0) 10.0.3.123 00:16:3e:7c:21:38
Jun 18 20:43:11 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPOFFER(lxcbr0) 10.0.3.35 00:16:3e:7c:21:38
Jun 18 20:43:14 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPDISCOVER(lxcbr0) 10.0.3.123 00:16:3e:72:0c:64
Jun 18 20:43:14 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPOFFER(lxcbr0) 10.0.3.208 00:16:3e:72:0c:64
Jun 18 20:43:17 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPDISCOVER(lxcbr0) 10.0.3.123 00:16:3e:ed:b3:a0
Jun 18 20:43:17 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPOFFER(lxcbr0) 10.0.3.82 00:16:3e:ed:b3:a0
Jun 18 20:43:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPDISCOVER(lxcbr0) 10.0.3.123 00:16:3e:e3:8f:1a
Jun 18 20:43:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPOFFER(lxcbr0) 10.0.3.247 00:16:3e:e3:8f:1a
Jun 18 20:43:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPDISCOVER(lxcbr0) 10.0.3.123 00:16:3e:5c:99:20
Jun 18 20:43:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPOFFER(lxcbr0) 10.0.3.225 00:16:3e:5c:99:20
Jun 18 20:43:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPDISCOVER(lxcbr0) 10.0.3.123 00:16:3e:ed:b3:a0
Jun 18 20:43:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPOFFER(lxcbr0) 10.0.3.82 00:16:3e:ed:b3:a0
Jun 18 20:43:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPREQUEST(lxcbr0) 10.0.3.203 00:16:3e:0d:7b:65
Jun 18 20:43:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPACK(lxcbr0) 10.0.3.203 00:16:3e:0d:7b:65 lptests-temp-C5po26y
...
What I expect to see is all of the containers reporting without a three minute break, so that all containers are ready for work much sooner.
I looked in the syslogs of the started containers. The first one to connect to dnsmasq *after* the three minute pause showed a three minute pause in its own syslog. This is an excerpt from the syslog of that machine (notice the jump between 20:40 to 20:43). The "udevtrigger post-stop process" lines and following dhclient startup lines, down through the "plymouth-splash" line, are not found in the two fast machine syslogs that I looked at.
Jun 18 20:40:10 lptests-temp-C5po26y ntpd[542]: frequency initialized 0.000 PPM from /var/lib/ntp/ntp.drift
Jun 18 20:40:12 lptests-temp-C5po26y kernel: 6n[8su4vP >25vs3e6e3 rr[2zIr
Jun 18 20:40:12 lptests-temp-C5po26y kernel: <7[9]zPrt26t6pl3 w
Jun 18 20:40:13 lptests-temp-C5po26y kernel: 03rntt8hot<7[91h:6st42nre72.]Oorr67eq6 44vqvs
Jun 18 20:43:02 lptests-temp-C5po26y init: udevtrigger post-stop process (65) terminated with status 1
Jun 18 20:43:02 lptests-temp-C5po26y dhclient: Internet Systems Consortium DHCP Client V3.1.3
Jun 18 20:43:02 lptests-temp-C5po26y dhclient: Copyright 2004-2009 Internet Systems Consortium.
Jun 18 20:43:02 lptests-temp-C5po26y dhclient: All rights reserved.
Jun 18 20:43:02 lptests-temp-C5po26y dhclient: For info, please visit https://www.isc.org/software/dhcp/
Jun 18 20:43:02 lptests-temp-C5po26y dhclient:
Jun 18 20:43:02 lptests-temp-C5po26y init: plymouth-splash main process (639) terminated with status 1
Jun 18 20:43:02 lptests-temp-C5po26y dhclient: Listening on LPF/eth0/00:16:3e:0d:7b:65
Jun 18 20:43:02 lptests-temp-C5po26y dhclient: Sending on LPF/eth0/00:16:3e:0d:7b:65
Jun 18 20:43:02 lptests-temp-C5po26y dhclient: Sending on Socket/fallback
Jun 18 20:43:02 lptests-temp-C5po26y dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 5
Jun 18 20:43:05 lptests-temp-C5po26y dhclient: DHCPOFFER of 10.0.3.203 from 10.0.3.1
Jun 18 20:43:05 lptests-temp-C5po26y dhclient: DHCPREQUEST of 10.0.3.203 on eth0 to 255.255.255.255 port 67
Finally, according to the stats we gathered while doing this, as far as we could tell, the following are not causes of contention, even when starting 24 simultaneous containers on a 16 core hyperthreaded machine:
* cpu (never got higher than about 80% utilization, load average still had some headroom)
* RAM (never got even half utilization of RAM)
* ioutil% never got above 1 or 2%
* dnsmasq itself does not seem to be an issue, looking at syslog, since we do not see restarts there
We plan to do a bit more analysis, as mentioned above, but we think this data might be good enough to ask for your input at this point. Thank you. |
We are gathering more data, but it feels like we have enough to start a bug report.
On Precise, on a 16 core/32 thread EC2 machine (instance type cc2.8xlarge), when starting approximately eight or more Lucid containers simultaneously: after the first seven or so connect to dnsmasq within just a few seconds, the next group waits just under three minutes before they start to connect.
This affects our ability to ssh into the containers and do work.
We will provide short steps to duplicate this. Please note also the extra data we include at the end of this report, showing experiments we have run to rule out certain causes and scenarios.
To duplicate (again, I am doing this on a specific EC2 machine with a lot of cores, but I believe you can see something similar to this even on a 4 core/8 hyperthread machine):
sudo apt-get install moreutils
sudo lxc-create -t ubuntu -n lucid -- -r lucid -a i386 -b ubuntu
parallel -j 16 bash -c "lxc-start-ephemeral -d -o lucid" -- 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16
Now look at /var/log/syslog at the most recent dnsmasq entries. You will see that about seven containers get DHCPACK from dnsmasq within about 20 seconds; then you will see a pause of about three minutes; then you will see more containers report to dnsmasq. Here's an excerpt (the approximate three minute jump happens between lines 5 and 6, and then I include all lines up to the next ACK):
...
Jun 18 20:40:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPACK(lxcbr0) 10.0.3.161 00:16:3e:38:9f:e2 lptests-temp-5uKcEua
Jun 18 20:40:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPREQUEST(lxcbr0) 10.0.3.37 00:16:3e:9c:ae:16
Jun 18 20:40:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPACK(lxcbr0) 10.0.3.37 00:16:3e:9c:ae:16 lptests-temp-1HxiwbU
Jun 18 20:40:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPREQUEST(lxcbr0) 10.0.3.62 00:16:3e:69:83:2b
Jun 18 20:40:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPACK(lxcbr0) 10.0.3.62 00:16:3e:69:83:2b lptests-temp-6o30rvH
Jun 18 20:43:05 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPDISCOVER(lxcbr0) 10.0.3.123 00:16:3e:0d:7b:65
Jun 18 20:43:05 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPOFFER(lxcbr0) 10.0.3.203 00:16:3e:0d:7b:65
Jun 18 20:43:08 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPDISCOVER(lxcbr0) 10.0.3.123 00:16:3e:32:5b:99
Jun 18 20:43:08 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPOFFER(lxcbr0) 10.0.3.68 00:16:3e:32:5b:99
Jun 18 20:43:11 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPDISCOVER(lxcbr0) 10.0.3.123 00:16:3e:7c:21:38
Jun 18 20:43:11 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPOFFER(lxcbr0) 10.0.3.35 00:16:3e:7c:21:38
Jun 18 20:43:14 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPDISCOVER(lxcbr0) 10.0.3.123 00:16:3e:72:0c:64
Jun 18 20:43:14 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPOFFER(lxcbr0) 10.0.3.208 00:16:3e:72:0c:64
Jun 18 20:43:17 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPDISCOVER(lxcbr0) 10.0.3.123 00:16:3e:ed:b3:a0
Jun 18 20:43:17 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPOFFER(lxcbr0) 10.0.3.82 00:16:3e:ed:b3:a0
Jun 18 20:43:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPDISCOVER(lxcbr0) 10.0.3.123 00:16:3e:e3:8f:1a
Jun 18 20:43:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPOFFER(lxcbr0) 10.0.3.247 00:16:3e:e3:8f:1a
Jun 18 20:43:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPDISCOVER(lxcbr0) 10.0.3.123 00:16:3e:5c:99:20
Jun 18 20:43:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPOFFER(lxcbr0) 10.0.3.225 00:16:3e:5c:99:20
Jun 18 20:43:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPDISCOVER(lxcbr0) 10.0.3.123 00:16:3e:ed:b3:a0
Jun 18 20:43:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPOFFER(lxcbr0) 10.0.3.82 00:16:3e:ed:b3:a0
Jun 18 20:43:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPREQUEST(lxcbr0) 10.0.3.203 00:16:3e:0d:7b:65
Jun 18 20:43:20 ip-10-58-49-120 dnsmasq-dhcp[7546]: DHCPACK(lxcbr0) 10.0.3.203 00:16:3e:0d:7b:65 lptests-temp-C5po26y
...
What I expect to see is all of the containers reporting approximately together, without a three minute break, so that all containers are ready for work much sooner.
I looked in the syslogs of the started containers. The first one to connect to dnsmasq *after* the three minute pause also showed a three minute pause in its own syslog. The following is an excerpt from the syslog of that machine (notice the jump between 20:40 to 20:43). The "udevtrigger post-stop process" lines and following dhclient startup lines, down through the "plymouth-splash" line, are not found in the two fast machine syslogs that I looked at.
Jun 18 20:40:10 lptests-temp-C5po26y ntpd[542]: frequency initialized 0.000 PPM from /var/lib/ntp/ntp.drift
Jun 18 20:40:12 lptests-temp-C5po26y kernel: 6n[8su4vP >25vs3e6e3 rr[2zIr
Jun 18 20:40:12 lptests-temp-C5po26y kernel: <7[9]zPrt26t6pl3 w
Jun 18 20:40:13 lptests-temp-C5po26y kernel: 03rntt8hot<7[91h:6st42nre72.]Oorr67eq6 44vqvs
Jun 18 20:43:02 lptests-temp-C5po26y init: udevtrigger post-stop process (65) terminated with status 1
Jun 18 20:43:02 lptests-temp-C5po26y dhclient: Internet Systems Consortium DHCP Client V3.1.3
Jun 18 20:43:02 lptests-temp-C5po26y dhclient: Copyright 2004-2009 Internet Systems Consortium.
Jun 18 20:43:02 lptests-temp-C5po26y dhclient: All rights reserved.
Jun 18 20:43:02 lptests-temp-C5po26y dhclient: For info, please visit https://www.isc.org/software/dhcp/
Jun 18 20:43:02 lptests-temp-C5po26y dhclient:
Jun 18 20:43:02 lptests-temp-C5po26y init: plymouth-splash main process (639) terminated with status 1
Jun 18 20:43:02 lptests-temp-C5po26y dhclient: Listening on LPF/eth0/00:16:3e:0d:7b:65
Jun 18 20:43:02 lptests-temp-C5po26y dhclient: Sending on LPF/eth0/00:16:3e:0d:7b:65
Jun 18 20:43:02 lptests-temp-C5po26y dhclient: Sending on Socket/fallback
Jun 18 20:43:02 lptests-temp-C5po26y dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 5
Jun 18 20:43:05 lptests-temp-C5po26y dhclient: DHCPOFFER of 10.0.3.203 from 10.0.3.1
Jun 18 20:43:05 lptests-temp-C5po26y dhclient: DHCPREQUEST of 10.0.3.203 on eth0 to 255.255.255.255 port 67
Here's a bit more data to close with.
We have experience indicating that more waiting occurs when you add more containers to be run, because simultaneously starting 32 containers will occasionally (about once in 15 attempts) result in one container that still has not connected to dnsmasq after ten minutes. We have not tried to duplicate this, because we hope that tackling the smaller issue described here will also address the larger one.
I have tried with a precise container. *Precise containers do not exhibit this bug* in the experiment I performed, at least up to 16 containers. I plan to duplicate this at least a couple more times to verify, but I'm comfortable saying initially that I believe this is specific to Lucid containers. I'll report back.
I have not yet had enough disk space on this machine to duplicate this without lxc-start-ephemeral. I intend to do so. Because the Precise container did not exhibit the problem for me even with ephemeral containers, I suspected that the unusual ephemeral characteristics, such as the use of overlayfs, might not be involved.
Finally, according to the stats we gathered while doing this, as far as we could tell, the following are not causes of contention, even when starting 24 simultaneous containers on a 16 core hyperthreaded machine:
* cpu (never got higher than about 80% utilization, load average still had some headroom)
* RAM (never got even half utilization of RAM)
* ioutil% never got above 1 or 2%
* dnsmasq itself does not seem to be an issue, looking at syslog, since we do not see restarts there
We plan to do a bit more analysis, as mentioned above, but we think this data might be good enough to ask for your input at this point. Thank you. |
|
