CloudStack starts misbehaving under minimal load

[akrasnov-drv]

I opened several other discussions/issues for my scale problems with CloudStack (partially solved). But now I managed to simplify the env, and want to start it clean as a new discussion

My env

CloudStack 4.20.0.0
on Ubuntu 22.04.5 LTS (amd64)
with libvirt 8.0.0-1ubuntu7.10
OpenJDK 64-Bit Server VM (build 17.0.13+11-Ubuntu-2ubuntu122.04, mixed mode, sharing)

I configured basic shared network, IPs are from my /24 internal subnet. VRouter serves as dhcp, metadata and dns server, but VMs are directly accessible from network and have direct outside access (via subnet gateway). I left single host to run VMs, separate from CloudStack management host. VM host can run about 20 VMs. Network is 1 Gbps. Primary and secondary storage are in NFS from another host in the same subnet.

The task

I'm trying to start 20 VMs from the same qcow image and the same compute offering using local disk (on RAID-0 of 2 SSDs)
There is several seconds delay between VM deployments.

The problem

2-3 first VMs start fine. Then VMs in starting state begin accumulating.
2 running + 1 starting
3 running + 2 starting
Finally I get about 7 running and 13 starting and that state persists. I mean even after some 15 minutes those starting are still starting.
To make sure, I see just those running ones in virsh output. All "starting" ones are not even created.
When I tried to start more (in hope to see them in virsh), they just joined to the pool of "starting" ones (at the moment I see about 28 in "starting" state on the host that can run just 20)

But that's just a part of problem.
The second part is that from those 7 running just 3-5 started well, and the rest did not get hostname from VR metadata server.
Sometimes I also see VMs that do not get IP, but that's more rare. For such ones reboot/reset does not help, but reinstall via UI button usually fixes the problem.

Logs on the agent side are quite idle. Just periodically I see messages like this

2025-02-17 18:03:09,959 WARN  [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-2:[]) (logid:402faf9c) Groovy script '/etc/cloudstack/agent/hooks/libvirt-vm-state-change.groovy' is not available. Transformations will not be applied.
2025-02-17 18:03:09,959 WARN  [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-2:[]) (logid:402faf9c) Groovy scripting engine is not initialized. Data transformation skipped.

Management log is active.
In these tests I did not feel UI slowdown as it was when I had more hosts connected with advanced network. Nevertheless I was not able to start properly VMs I wanted.

My questions

• Lately I've got an impression that the last CloudStack versions are imperfect. Would be great if someone could share positive experience of running dozens of VMs with later versions.
• If you are happy with some older CloudStack version, please also share
• If default configuration is not suitable for dozens of VMs, please advise on config changes. If there is any document on this, I'd be glad to work through it.

I continue to experiment and am able to share logs if required.
All useful information is appreciated.

Thanks,
Alex.

[weizhouapache]

just to confirm,

• has you applied the fix in VR: fix duplicated lines in .htaccess #10254 ?
• has you updated global setting workers ?

[akrasnov-drv]

yes, the fix is applied
workers set to 50

And several more detail.
Today I found 11 VMs running (all new). So, part of VMs hanging in "starting" state yesterday managed to start. In event log I see for example

INFO	VM.CREATE	Started
	admin	admin	ROOT	17 Feb 2025 20:04:20
INFO	VM.CREATE	Completed
	admin	admin	ROOT	17 Feb 2025 20:45:33

41 min between started and completed
All VMs have approximately the same timing (completed at 20:45 - 20:46), like some block disappeared and they all continued start.

In the VR event log there is a long gap that ends approximately at this same time:

INFO	Health check	Completed
	system	system	ROOT	11 Feb 2025 12:26:32
INFO	Health check	Completed
	system	system	ROOT	17 Feb 2025 20:49:13

Looks like it was sleeping or suspended, but VR VM was running (I mean on kvm level).
I really did not touch CloudStack installation for several days. Could something (e.g. VR) be sleeping/suspended meanwhile?

I'll try cleaning the env and retry on freshly started system from cli.

[rajujith]

@akrasnov-drv Can you make sure execute.in.sequence.hypervisor.commands is set to false. The default value is false. I would find the async job/s for the instance that took a long time to start and review the management-server.log to identify where is the delay or if is it waiting for other operations/tasks etc.

[akrasnov-drv]

Thanks @rajujith . It was set to false.
After I removed/recreated VR, set the variable to true and restarted both management and agent, I was able to start 16 VMs on the host. A lot better than yesterday.
I'll try several more times on the same env, then, if all goes well, I'll enable my other hosts to see if it manages to start a hundred.

Btw, I enabled libvirtd to to listen on TCP port, and CloudStack configured SSL there. What should be better to use on agent hosts just libvirtd socket, or to have tcp port open too?

[rajujith]

@akrasnov-drv I deployed 20 instances using the same template to a single KVM host using local storage. All of them use the same guest network. I created them using a for loop and cmk. All are in the 'Running' state. I used the default settings.
ACS 4.20, KVM Ubuntu 22.0.4. I used an advanced zone isolated guest network.

In your tests, you tried deploying 20 instances in parallel? I tried both and no issues were observed.

[rajujith]

@akrasnov-drv I did the same tests in a basic zone creating instances in parallel using the default template. They were created in a minute to two minutes. It would be faster in faster hardware. I used a nested KVM.

mysql> SELECT
    ->     id,
    ->     instance_id,
    ->     job_status,
    ->     job_result_code,
    ->     created,
    ->     last_updated,
    ->     TIME_TO_SEC(TIMEDIFF(last_updated, created)) AS time_diff_seconds
    -> FROM async_job
    -> WHERE job_cmd='org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin'
    -> ORDER BY instance_id DESC
    -> LIMIT 20;
+-----+-------------+------------+-----------------+---------------------+---------------------+-------------------+
| id  | instance_id | job_status | job_result_code | created             | last_updated        | time_diff_seconds |
+-----+-------------+------------+-----------------+---------------------+---------------------+-------------------+
| 206 |          43 |          1 |               0 | 2025-02-19 06:35:07 | 2025-02-19 06:36:26 |                79 |
| 205 |          42 |          1 |               0 | 2025-02-19 06:35:07 | 2025-02-19 06:36:27 |                80 |
| 199 |          41 |          1 |               0 | 2025-02-19 06:35:06 | 2025-02-19 06:36:18 |                72 |
| 194 |          40 |          1 |               0 | 2025-02-19 06:35:06 | 2025-02-19 06:36:31 |                85 |
| 197 |          39 |          1 |               0 | 2025-02-19 06:35:06 | 2025-02-19 06:36:16 |                70 |
| 201 |          38 |          1 |               0 | 2025-02-19 06:35:07 | 2025-02-19 06:36:28 |                81 |
| 196 |          37 |          1 |               0 | 2025-02-19 06:35:06 | 2025-02-19 06:36:40 |                94 |
| 192 |          36 |          1 |               0 | 2025-02-19 06:35:06 | 2025-02-19 06:36:16 |                70 |
| 189 |          35 |          1 |               0 | 2025-02-19 06:35:06 | 2025-02-19 06:36:19 |                73 |
| 193 |          34 |          1 |               0 | 2025-02-19 06:35:06 | 2025-02-19 06:36:12 |                66 |
| 191 |          33 |          1 |               0 | 2025-02-19 06:35:06 | 2025-02-19 06:36:30 |                84 |
| 186 |          32 |          1 |               0 | 2025-02-19 06:35:06 | 2025-02-19 06:36:20 |                74 |
| 188 |          31 |          1 |               0 | 2025-02-19 06:35:06 | 2025-02-19 06:36:11 |                65 |
| 185 |          30 |          1 |               0 | 2025-02-19 06:35:05 | 2025-02-19 06:36:33 |                88 |
| 184 |          29 |          1 |               0 | 2025-02-19 06:35:05 | 2025-02-19 06:36:17 |                72 |
| 187 |          28 |          1 |               0 | 2025-02-19 06:35:06 | 2025-02-19 06:36:29 |                83 |
| 180 |          27 |          1 |               0 | 2025-02-19 06:35:05 | 2025-02-19 06:36:33 |                88 |
| 179 |          26 |          1 |               0 | 2025-02-19 06:35:05 | 2025-02-19 06:36:14 |                69 |
| 177 |          25 |          1 |               0 | 2025-02-19 06:35:04 | 2025-02-19 06:36:15 |                71 |
| 178 |          24 |          1 |               0 | 2025-02-19 06:35:04 | 2025-02-19 06:36:10 |                66 |
+-----+-------------+------------+-----------------+---------------------+---------------------+-------------------+

[akrasnov-drv]

@rajujith First of all thank you, changing execute.in.sequence.hypervisor.commands to true significantly improved the state.
Just now I started 38 VMs and they really started. Though I still saw kind of echo of the same problem. First 22 started fine, but then the rest were hanging in Starting state longer than I'd expect them to, e.g.

INFO	VM.CREATE	Started
	admin	admin	ROOT	20 Feb 2025 12:25:18
INFO	VM.CREATE	Completed
	admin	admin	ROOT	20 Feb 2025 12:27:07

Almost 2 minutes, while the 1st ones started within 5-10 seconds

INFO	VM.CREATE	Started
	admin	admin	ROOT	20 Feb 2025 12:22:08
INFO	VM.CREATE	Completed
	admin	admin	ROOT	20 Feb 2025 12:22:13

The problem may appear just on faster hardware, it may be some timing issue - I use 2x Xeon CPU physical servers.
I mean, if you can't reproduce it on VM, you may need to try it on 2xCPU physical server.
I'm using basic network now to exclude additional influences (e.g. VR), and I'm sure it will be no better on advanced network.
Meanwhile I'll go further and try to add hosts and start more VMs.

[akrasnov-drv]

Nice SQL query btw.
I managed to start 100 VMs on 5 hosts. I mean all properly started.
Again after first several ones delays increased, sometimes to more than 1.5 minutes. Still I've got all I requested in the end.

+------+-------------+------------+-----------------+---------------------+---------------------+-------------------+
| id   | instance_id | job_status | job_result_code | created             | last_updated        | time_diff_seconds |
+------+-------------+------------+-----------------+---------------------+---------------------+-------------------+
| 4725 |        1082 |          1 |               0 | 2025-02-20 11:46:58 | 2025-02-20 11:47:06 |                 8 |
| 4722 |        1081 |          1 |               0 | 2025-02-20 11:46:49 | 2025-02-20 11:46:54 |                 5 |
| 4719 |        1080 |          1 |               0 | 2025-02-20 11:44:18 | 2025-02-20 11:44:25 |                 7 |
| 4716 |        1079 |          1 |               0 | 2025-02-20 11:44:09 | 2025-02-20 11:44:14 |                 5 |
| 4696 |        1078 |          1 |               0 | 2025-02-20 11:38:49 | 2025-02-20 11:39:49 |                60 |
| 4694 |        1077 |          1 |               0 | 2025-02-20 11:38:48 | 2025-02-20 11:39:53 |                65 |
| 4690 |        1076 |          1 |               0 | 2025-02-20 11:38:39 | 2025-02-20 11:39:43 |                64 |
| 4688 |        1075 |          1 |               0 | 2025-02-20 11:38:38 | 2025-02-20 11:39:48 |                70 |
| 4686 |        1074 |          1 |               0 | 2025-02-20 11:38:28 | 2025-02-20 11:39:44 |                76 |
| 4683 |        1073 |          1 |               0 | 2025-02-20 11:38:00 | 2025-02-20 11:39:34 |                94 |
| 4681 |        1072 |          1 |               0 | 2025-02-20 11:38:00 | 2025-02-20 11:39:37 |                97 |
| 4679 |        1071 |          1 |               0 | 2025-02-20 11:37:59 | 2025-02-20 11:39:31 |                92 |
| 4677 |        1070 |          1 |               0 | 2025-02-20 11:37:59 | 2025-02-20 11:39:42 |               103 |
....
| 4432 |         986 |          1 |               0 | 2025-02-20 11:32:08 | 2025-02-20 11:32:25 |                17 |
| 4431 |         985 |          1 |               0 | 2025-02-20 11:32:07 | 2025-02-20 11:32:23 |                16 |
| 4430 |         984 |          1 |               0 | 2025-02-20 11:32:07 | 2025-02-20 11:32:29 |                22 |
| 4427 |         983 |          1 |               0 | 2025-02-20 11:31:58 | 2025-02-20 11:32:03 |                 5 |
+------+-------------+------------+-----------------+---------------------+---------------------+-------------------+
100 rows in set (0.00 sec)

here are maximum delays

+------+-------------+------------+-----------------+---------------------+---------------------+-------------------+
| id   | instance_id | job_status | job_result_code | created             | last_updated        | time_diff_seconds |
+------+-------------+------------+-----------------+---------------------+---------------------+-------------------+
| 4498 |        1015 |          1 |               0 | 2025-02-20 11:32:39 | 2025-02-20 11:34:33 |               114 |
| 4473 |        1005 |          1 |               0 | 2025-02-20 11:32:29 | 2025-02-20 11:34:17 |               108 |
| 4505 |        1017 |          1 |               0 | 2025-02-20 11:32:48 | 2025-02-20 11:34:35 |               107 |
| 4493 |        1012 |          1 |               0 | 2025-02-20 11:32:38 | 2025-02-20 11:34:24 |               106 |
| 4663 |        1063 |          1 |               0 | 2025-02-20 11:37:48 | 2025-02-20 11:39:32 |               104 |
| 4677 |        1070 |          1 |               0 | 2025-02-20 11:37:59 | 2025-02-20 11:39:42 |               103 |
| 4673 |        1068 |          1 |               0 | 2025-02-20 11:37:51 | 2025-02-20 11:39:33 |               102 |
| 4681 |        1072 |          1 |               0 | 2025-02-20 11:38:00 | 2025-02-20 11:39:37 |                97 |

[akrasnov-drv]

To summon

• execute.in.sequence.hypervisor.commands=True solves the main issue of stuck on Starting VMs. Still there are significant delays, but at list VMs start
• Would be great to get recommendation on use of libvirt socket or tcp connections (what's better)
• Still there is a question if VR or management itself sleeps when unused for several days

[weizhouapache]

thanks for the update and summary
@akrasnov-drv

great advise @rajujith