Skip to content

Commit 6bd0ecd

Browse files
winterhazelJoaoJandre
authored and
dhslove
committed
Add logs to LibvirtComputingResource's metrics collection process (apache#8511)
* Add logs to LibvirtComputingResource's metrics collecting process * Apply Joao's suggestions Co-authored-by: João Jandre <48719461+JoaoJandre@users.noreply.github.com> * Adjust some logs * Print memory statistics log in one line --------- Co-authored-by: João Jandre <48719461+JoaoJandre@users.noreply.github.com>
1 parent 66ace64 commit 6bd0ecd

3 files changed

Lines changed: 395 additions & 195 deletions

File tree

‎plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/LibvirtComputingResource.java‎

Lines changed: 179 additions & 114 deletions
Original file line numberDiff line numberDiff line change
@@ -44,6 +44,8 @@
4444
import java.util.concurrent.ConcurrentHashMap;
4545
import java.util.regex.Matcher;
4646
import java.util.regex.Pattern;
47+
import java.util.stream.Collectors;
48+
import java.util.stream.Stream;
4749

4850
import javax.inject.Inject;
4951
import javax.naming.ConfigurationException;
@@ -81,6 +83,8 @@
8183
import org.apache.commons.lang.math.NumberUtils;
8284
import org.apache.commons.lang3.ObjectUtils;
8385
import org.apache.commons.lang3.StringUtils;
86+
import org.apache.commons.lang3.builder.ReflectionToStringBuilder;
87+
import org.apache.commons.lang3.builder.ToStringStyle;
8488
import org.apache.logging.log4j.Logger;
8589
import org.apache.logging.log4j.LogManager;
8690
import org.apache.xerces.impl.xpath.regex.Match;
@@ -462,7 +466,7 @@ public class LibvirtComputingResource extends ServerResourceBase implements Serv
462466
protected WatchDogModel watchDogModel = WatchDogModel.I6300ESB;
463467

464468
private final Map <String, String> pifs = new HashMap<String, String>();
465-
private final Map<String, VmStats> vmStats = new ConcurrentHashMap<String, VmStats>();
469+
private final Map<String, LibvirtExtendedVmStatsEntry> vmStats = new ConcurrentHashMap<>();
466470

467471
private final Map<String, DomainBlockStats> vmDiskStats = new ConcurrentHashMap<>();
468472

@@ -2498,7 +2502,7 @@ public PowerState getVmState(final Connect conn, final String vmName) {
24982502
final PowerState s = convertToPowerState(vms.getInfo().state);
24992503
return s;
25002504
} catch (final LibvirtException e) {
2501-
LOGGER.warn("Can't get vm state " + vmName + e.getMessage() + "retry:" + retry);
2505+
LOGGER.error("Could not get state for VM [{}] (retry={}) due to:", vmName, retry, e);
25022506
} finally {
25032507
try {
25042508
if (vms != null) {
@@ -4685,125 +4689,48 @@ protected String getDiskPathFromDiskDef(DiskDef disk) {
46854689
return null;
46864690
}
46874691

4688-
private class VmStats {
4689-
long usedTime;
4690-
long tx;
4691-
long rx;
4692-
long ioRead;
4693-
long ioWrote;
4694-
long bytesRead;
4695-
long bytesWrote;
4696-
Calendar timestamp;
4692+
private String vmToString(Domain dm) throws LibvirtException {
4693+
return String.format("{\"name\":\"%s\",\"uuid\":\"%s\"}", dm.getName(), dm.getUUIDString());
46974694
}
46984695

4696+
/**
4697+
* Returns metrics for the period since this function was last called for the specified VM.
4698+
* @param conn the Libvirt connection.
4699+
* @param vmName name of the VM.
4700+
* @return metrics for the period since last time this function was called for the VM.
4701+
* @throws LibvirtException
4702+
*/
46994703
public VmStatsEntry getVmStat(final Connect conn, final String vmName) throws LibvirtException {
47004704
Domain dm = null;
47014705
try {
4706+
LOGGER.debug("Trying to get VM with name [{}].", vmName);
47024707
dm = getDomain(conn, vmName);
47034708
if (dm == null) {
4709+
LOGGER.warn("Could not get VM with name [{}].", vmName);
47044710
return null;
47054711
}
4706-
DomainInfo info = dm.getInfo();
4707-
final VmStatsEntry stats = new VmStatsEntry();
4708-
4709-
stats.setNumCPUs(info.nrVirtCpu);
4710-
stats.setEntityType("vm");
4711-
4712-
stats.setMemoryKBs(info.maxMem);
4713-
stats.setTargetMemoryKBs(info.memory);
4714-
stats.setIntFreeMemoryKBs(getMemoryFreeInKBs(dm));
4715-
stats.setIntUsableMemoryKBs(getMemoryUsableInKBs(dm));
47164712

4717-
/* get cpu utilization */
4718-
VmStats oldStats = null;
4713+
LibvirtExtendedVmStatsEntry newStats = getVmCurrentStats(dm);
4714+
LibvirtExtendedVmStatsEntry oldStats = vmStats.get(vmName);
47194715

4720-
final Calendar now = Calendar.getInstance();
4721-
4722-
oldStats = vmStats.get(vmName);
4723-
4724-
long elapsedTime = 0;
4725-
if (oldStats != null) {
4726-
elapsedTime = now.getTimeInMillis() - oldStats.timestamp.getTimeInMillis();
4727-
double utilization = (info.cpuTime - oldStats.usedTime) / ((double)elapsedTime * 1000000);
4728-
4729-
utilization = utilization / info.nrVirtCpu;
4730-
if (utilization > 0) {
4731-
stats.setCPUUtilization(utilization * 100);
4732-
}
4733-
}
4734-
4735-
/* get network stats */
4736-
4737-
final List<InterfaceDef> vifs = getInterfaces(conn, vmName);
4738-
long rx = 0;
4739-
long tx = 0;
4740-
for (final InterfaceDef vif : vifs) {
4741-
final DomainInterfaceStats ifStats = dm.interfaceStats(vif.getDevName());
4742-
rx += ifStats.rx_bytes;
4743-
tx += ifStats.tx_bytes;
4744-
}
4745-
4746-
if (oldStats != null) {
4747-
final double deltarx = rx - oldStats.rx;
4748-
if (deltarx > 0) {
4749-
stats.setNetworkReadKBs(deltarx / 1024);
4750-
}
4751-
final double deltatx = tx - oldStats.tx;
4752-
if (deltatx > 0) {
4753-
stats.setNetworkWriteKBs(deltatx / 1024);
4754-
}
4755-
}
4756-
4757-
/* get disk stats */
4758-
final List<DiskDef> disks = getDisks(conn, vmName);
4759-
long io_rd = 0;
4760-
long io_wr = 0;
4761-
long bytes_rd = 0;
4762-
long bytes_wr = 0;
4763-
for (final DiskDef disk : disks) {
4764-
if (disk.getDeviceType() == DeviceType.CDROM || disk.getDeviceType() == DeviceType.FLOPPY) {
4765-
continue;
4766-
}
4767-
final DomainBlockStats blockStats = dm.blockStats(disk.getDiskLabel());
4768-
io_rd += blockStats.rd_req;
4769-
io_wr += blockStats.wr_req;
4770-
bytes_rd += blockStats.rd_bytes;
4771-
bytes_wr += blockStats.wr_bytes;
4772-
}
4716+
VmStatsEntry metrics = calculateVmMetrics(dm, oldStats, newStats);
4717+
vmStats.put(vmName, newStats);
47734718

4774-
if (oldStats != null) {
4775-
final long deltaiord = io_rd - oldStats.ioRead;
4776-
if (deltaiord > 0) {
4777-
stats.setDiskReadIOs(deltaiord);
4778-
}
4779-
final long deltaiowr = io_wr - oldStats.ioWrote;
4780-
if (deltaiowr > 0) {
4781-
stats.setDiskWriteIOs(deltaiowr);
4782-
}
4783-
final double deltabytesrd = bytes_rd - oldStats.bytesRead;
4784-
if (deltabytesrd > 0) {
4785-
stats.setDiskReadKBs(deltabytesrd / 1024);
4786-
}
4787-
final double deltabyteswr = bytes_wr - oldStats.bytesWrote;
4788-
if (deltabyteswr > 0) {
4789-
stats.setDiskWriteKBs(deltabyteswr / 1024);
4790-
}
4791-
}
47924719
Map<String, String> nicAddrMap = new HashMap<String, String>();
47934720
String qemuAgentVersion = "Not Installed";
4794-
stats.setQemuAgentVersion(qemuAgentVersion);
4721+
metrics.setQemuAgentVersion(qemuAgentVersion);
47954722

47964723
// String result = dm.qemuAgentCommand(QemuCommand.buildQemuCommand(QemuCommand.AGENT_INFO, null), 2, 0);
47974724
String mergeCommand = String.format("virsh qemu-agent-command %s '{\"execute\":\"guest-info\"}'", vmName);
47984725
String result = Script.runSimpleBashScript(mergeCommand);
47994726

48004727
if (result != null) {
48014728
qemuAgentVersion = new JsonParser().parse(result).getAsJsonObject().get("return").getAsJsonObject().get("version").getAsString();
4802-
stats.setQemuAgentVersion(qemuAgentVersion);
4729+
metrics.setQemuAgentVersion(qemuAgentVersion);
48034730

48044731
result = dm.qemuAgentCommand(QemuCommand.buildQemuCommand(QemuCommand.AGENT_NETWORK_GET_INTERFACES, null), 2, 0);
48054732
if (result != null && !(result.startsWith("error"))) {
4806-
logger.debug(dm.getName() +" >> " + result);
4733+
LOGGER.debug(dm.getName() +" >> " + result);
48074734
JsonArray arrData = (JsonArray) new JsonParser().parse(result).getAsJsonObject().get("return");
48084735
for (JsonElement je : arrData) {
48094736
JsonElement nicName = je.getAsJsonObject().get("name") == null ? null : je.getAsJsonObject().get("name");
@@ -4832,28 +4759,168 @@ public VmStatsEntry getVmStat(final Connect conn, final String vmName) throws Li
48324759
}
48334760
}
48344761
}
4835-
stats.setNicAddrMap(nicAddrMap);
4762+
metrics.setNicAddrMap(nicAddrMap);
48364763
}
48374764
}
4838-
/* save to Hashmap */
4839-
final VmStats newStat = new VmStats();
4840-
newStat.usedTime = info.cpuTime;
4841-
newStat.rx = rx;
4842-
newStat.tx = tx;
4843-
newStat.ioRead = io_rd;
4844-
newStat.ioWrote = io_wr;
4845-
newStat.bytesRead = bytes_rd;
4846-
newStat.bytesWrote = bytes_wr;
4847-
newStat.timestamp = now;
4848-
vmStats.put(vmName, newStat);
4849-
return stats;
4765+
4766+
return metrics;
48504767
} finally {
48514768
if (dm != null) {
48524769
dm.free();
48534770
}
48544771
}
48554772
}
48564773

4774+
/**
4775+
* Returns a VM's current statistics.
4776+
* @param dm domain of the VM.
4777+
* @return current statistics of the VM.
4778+
* @throws LibvirtException
4779+
*/
4780+
protected LibvirtExtendedVmStatsEntry getVmCurrentStats(final Domain dm) throws LibvirtException {
4781+
final LibvirtExtendedVmStatsEntry stats = new LibvirtExtendedVmStatsEntry();
4782+
4783+
getVmCurrentCpuStats(dm, stats);
4784+
getVmCurrentNetworkStats(dm, stats);
4785+
getVmCurrentDiskStats(dm, stats);
4786+
4787+
LOGGER.debug("Retrieved statistics for VM [{}]: [{}].", vmToString(dm), stats);
4788+
stats.setTimestamp(Calendar.getInstance());
4789+
return stats;
4790+
}
4791+
4792+
/**
4793+
* Passes a VM's current CPU statistics into the provided LibvirtExtendedVmStatsEntry.
4794+
* @param dm domain of the VM.
4795+
* @param stats LibvirtExtendedVmStatsEntry that will receive the current CPU statistics.
4796+
* @throws LibvirtException
4797+
*/
4798+
protected void getVmCurrentCpuStats(final Domain dm, final LibvirtExtendedVmStatsEntry stats) throws LibvirtException {
4799+
LOGGER.trace("Getting CPU stats for VM [{}].", vmToString(dm));
4800+
stats.setCpuTime(dm.getInfo().cpuTime);
4801+
}
4802+
4803+
/**
4804+
* Passes a VM's current network statistics into the provided LibvirtExtendedVmStatsEntry.
4805+
* @param dm domain of the VM.
4806+
* @param stats LibvirtExtendedVmStatsEntry that will receive the current network statistics.
4807+
* @throws LibvirtException
4808+
*/
4809+
protected void getVmCurrentNetworkStats(final Domain dm, final LibvirtExtendedVmStatsEntry stats) throws LibvirtException {
4810+
final String vmAsString = vmToString(dm);
4811+
LOGGER.trace("Getting network stats for VM [{}].", vmAsString);
4812+
final List<InterfaceDef> vifs = getInterfaces(dm.getConnect(), dm.getName());
4813+
LOGGER.debug("Found [{}] network interface(s) for VM [{}].", vifs.size(), vmAsString);
4814+
double rx = 0;
4815+
double tx = 0;
4816+
for (final InterfaceDef vif : vifs) {
4817+
final DomainInterfaceStats ifStats = dm.interfaceStats(vif.getDevName());
4818+
rx += ifStats.rx_bytes;
4819+
tx += ifStats.tx_bytes;
4820+
}
4821+
stats.setNetworkReadKBs(rx / 1024);
4822+
stats.setNetworkWriteKBs(tx / 1024);
4823+
}
4824+
4825+
/**
4826+
* Passes a VM's current disk statistics into the provided LibvirtExtendedVmStatsEntry.
4827+
* @param dm domain of the VM.
4828+
* @param stats LibvirtExtendedVmStatsEntry that will receive the current disk statistics.
4829+
* @throws LibvirtException
4830+
*/
4831+
protected void getVmCurrentDiskStats(final Domain dm, final LibvirtExtendedVmStatsEntry stats) throws LibvirtException {
4832+
final String vmAsString = vmToString(dm);
4833+
LOGGER.trace("Getting disk stats for VM [{}].", vmAsString);
4834+
final List<DiskDef> disks = getDisks(dm.getConnect(), dm.getName());
4835+
LOGGER.debug("Found [{}] disk(s) for VM [{}].", disks.size(), vmAsString);
4836+
long io_rd = 0;
4837+
long io_wr = 0;
4838+
double bytes_rd = 0;
4839+
double bytes_wr = 0;
4840+
for (final DiskDef disk : disks) {
4841+
if (disk.getDeviceType() == DeviceType.CDROM || disk.getDeviceType() == DeviceType.FLOPPY) {
4842+
LOGGER.debug("Ignoring disk [{}] in VM [{}]'s stats since its deviceType is [{}].", disk.toString().replace("\n", ""), vmAsString, disk.getDeviceType());
4843+
continue;
4844+
}
4845+
final DomainBlockStats blockStats = dm.blockStats(disk.getDiskLabel());
4846+
io_rd += blockStats.rd_req;
4847+
io_wr += blockStats.wr_req;
4848+
bytes_rd += blockStats.rd_bytes;
4849+
bytes_wr += blockStats.wr_bytes;
4850+
}
4851+
stats.setDiskReadIOs(io_rd);
4852+
stats.setDiskWriteIOs(io_wr);
4853+
stats.setDiskReadKBs(bytes_rd / 1024);
4854+
stats.setDiskWriteKBs(bytes_wr / 1024);
4855+
}
4856+
4857+
/**
4858+
* Calculates a VM's metrics for the period between the two statistics given as parameters.
4859+
* @param dm domain of the VM.
4860+
* @param oldStats old statistics. If null, the CPU, network and disk utilization won't be calculated.
4861+
* @param newStats new statistics.
4862+
* @return metrics for the period between the two statistics.
4863+
* @throws LibvirtException
4864+
*/
4865+
protected VmStatsEntry calculateVmMetrics(final Domain dm, final LibvirtExtendedVmStatsEntry oldStats, final LibvirtExtendedVmStatsEntry newStats) throws LibvirtException {
4866+
final VmStatsEntry metrics = new VmStatsEntry();
4867+
final DomainInfo info = dm.getInfo();
4868+
final String vmAsString = vmToString(dm);
4869+
4870+
metrics.setEntityType("vm");
4871+
LOGGER.trace("Writing VM [{}]'s CPU and memory information into the metrics.", vmAsString);
4872+
metrics.setNumCPUs(info.nrVirtCpu);
4873+
metrics.setMemoryKBs(info.maxMem);
4874+
metrics.setTargetMemoryKBs(info.memory);
4875+
LOGGER.trace("Trying to get free memory for VM [{}].", vmAsString);
4876+
metrics.setIntFreeMemoryKBs(getMemoryFreeInKBs(dm));
4877+
4878+
if (oldStats != null) {
4879+
LOGGER.debug("Old stats exist for VM [{}]; therefore, the utilization will be calculated.", vmAsString);
4880+
4881+
LOGGER.trace("Calculating CPU utilization for VM [{}].", vmAsString);
4882+
final Calendar now = Calendar.getInstance();
4883+
long elapsedTime = now.getTimeInMillis() - oldStats.getTimestamp().getTimeInMillis();
4884+
double utilization = (info.cpuTime - oldStats.getCpuTime()) / ((double) elapsedTime * 1000000 * info.nrVirtCpu);
4885+
if (utilization > 0) {
4886+
metrics.setCPUUtilization(utilization * 100);
4887+
}
4888+
4889+
LOGGER.trace("Calculating network utilization for VM [{}].", vmAsString);
4890+
final double deltarx = newStats.getNetworkReadKBs() - oldStats.getNetworkReadKBs();
4891+
if (deltarx > 0) {
4892+
metrics.setNetworkReadKBs(deltarx);
4893+
}
4894+
final double deltatx = newStats.getNetworkWriteKBs() - oldStats.getNetworkWriteKBs();
4895+
if (deltatx > 0) {
4896+
metrics.setNetworkWriteKBs(deltatx);
4897+
}
4898+
4899+
LOGGER.trace("Calculating disk utilization for VM [{}].", vmAsString);
4900+
final double deltaiord = newStats.getDiskReadIOs() - oldStats.getDiskReadIOs();
4901+
if (deltaiord > 0) {
4902+
metrics.setDiskReadIOs(deltaiord);
4903+
}
4904+
final double deltaiowr = newStats.getDiskWriteIOs() - oldStats.getDiskWriteIOs();
4905+
if (deltaiowr > 0) {
4906+
metrics.setDiskWriteIOs(deltaiowr);
4907+
}
4908+
final double deltabytesrd = newStats.getDiskReadKBs() - oldStats.getDiskReadKBs();
4909+
if (deltabytesrd > 0) {
4910+
metrics.setDiskReadKBs(deltabytesrd);
4911+
}
4912+
final double deltabyteswr = newStats.getDiskWriteKBs() - oldStats.getDiskWriteKBs();
4913+
if (deltabyteswr > 0) {
4914+
metrics.setDiskWriteKBs(deltabyteswr);
4915+
}
4916+
}
4917+
4918+
String metricsAsString = new ReflectionToStringBuilder(metrics, ToStringStyle.JSON_STYLE).setExcludeFieldNames("vmId", "vmUuid").toString();
4919+
LOGGER.debug("Calculated metrics for VM [{}]: [{}].", vmAsString, metricsAsString);
4920+
4921+
return metrics;
4922+
}
4923+
48574924
/**
48584925
* This method retrieves the memory statistics from the domain given as parameters.
48594926
* If no memory statistic is found, it will return {@link NumberUtils#LONG_MINUS_ONE} as the value of free memory in the domain.
@@ -4863,10 +4930,8 @@ public VmStatsEntry getVmStat(final Connect conn, final String vmName) throws Li
48634930
*/
48644931
protected long getMemoryFreeInKBs(Domain dm) throws LibvirtException {
48654932
MemoryStatistic[] memoryStats = dm.memoryStats(NUMMEMSTATS);
4866-
4867-
if(LOGGER.isTraceEnabled()){
4868-
LOGGER.trace(String.format("Retrieved memory statistics (information about tags can be found on the libvirt documentation):", ArrayUtils.toString(memoryStats)));
4869-
}
4933+
LOGGER.trace("Retrieved memory statistics (information about tags can be found on the libvirt documentation): {}.",
4934+
() -> Stream.of(memoryStats).map(stat -> stat.toString().trim().replace("\n", ",")).collect(Collectors.joining("},{", "[{", "}]")));
48704935

48714936
long freeMemory = NumberUtils.LONG_MINUS_ONE;
48724937

0 commit comments

Comments
 (0)