Cloud Usage consume loads of system resource in 4.20.1

[levindecaro]

problem

After upgrading from 4.19.1 to 4.20.1, the cloud usage service and database continuously consume a significant amount of resources. The cloud usage consumes approximately 1 virtual CPU, 1.2 GB of memory, and database consumes 1 virtual CPU with 3.2 GB of memory. They never went down, additionally, the database bin log grows by 5 GB every day.

versions

ACS: 4.20.1
OS: OL9 x86_64
hypervisors: KVM
storage: NFS(SharedMountPoint)
network: vxlan

The steps to reproduce the bug

1. Upgrade from 4.19.1 to 4.20.1
2. Observe system resource usage

What to do about it?

Need to find a way to optimize the system usage.

[DaanHoogland]

Any story to tell about this @levindecaro ?

[levindecaro]

@DaanHoogland I seems found something about duplicate db entry from usage.log, i’m trying to clear all error before reopening this issue, stay tune.

2025-07-03 07:55:43,070 ERROR [cloud.usage.UsageManagerImpl_EnhancerByCloudStack_10d8ae6e] (Usage-Job-1:[]) (logid:) Exception in usage manager com.cloud.utils.exception.CloudRuntimeException: Duplicate entry '98-10-3003-643-1751414399999' for key 'PRIMARY'
        at com.cloud.usage.dao.UsageNetworkDaoImpl.saveUsageNetworks(UsageNetworkDaoImpl.java:128)
        at com.cloud.usage.dao.UsageNetworkDaoImpl_EnhancerByCloudStack_cbc98d7d.CGLIB$saveUsageNetworks$2(<generated>)
        at com.cloud.usage.dao.UsageNetworkDaoImpl_EnhancerByCloudStack_cbc98d7d_FastClassByCloudStack_113c6676.invoke(<generated>)
        at net.sf.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:228)
        at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:123)
        at com.cloud.usage.dao.UsageNetworkDaoImpl_EnhancerByCloudStack_cbc98d7d.saveUsageNetworks(<generated>)
        at com.cloud.usage.UsageManagerImpl.parse(UsageManagerImpl.java:778)
        at com.cloud.usage.UsageManagerImpl.runInContextInternal(UsageManagerImpl.java:442)
        at com.cloud.usage.UsageManagerImpl$1.runInContext(UsageManagerImpl.java:379)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
        at com.cloud.usage.UsageManagerImpl.run(UsageManagerImpl.java:381)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at java.base/java.lang.Thread.run(Thread.java:840)

[levindecaro]

@DaanHoogland is it safe to truncate all table in cloud_usage db?

[DaanHoogland]

all table in cloud_usage db?

why all? it would re-generate everything which could take a long time. I would not do that unless you first found the usage_event that caused the duplicate.

[levindecaro]

@DaanHoogland just gave a try on truncate all tables, it has been ran for 3 days and the cpu went up once i got this error

2025-07-07 08:24:47,835 ERROR [cloud.usage.UsageManagerImpl_EnhancerByCloudStack_10d8ae6e] (Usage-Job-1:[]) (logid:) found entries for a vm running with id: 3419, which are not stopped. Ending them all...
2025-07-07 08:24:47,846 ERROR [usage.dao.UsageVMInstanceDaoImpl_EnhancerByCloudStack_2cbdde2b] (Usage-Job-1:[]) (logid:) DB Exception on: HikariProxyPreparedStatement@416132582 wrapping com.mysql.cj.jdbc.ServerPreparedStatement[8719]: INSERT INTO usage_vm_instance (usage_vm_instance.usage_type, usage_vm_instance.zone_id, usage_vm_instance.account_id, usage_vm_instance.vm_instance_id, usage_vm_instance.vm_name, usage_vm_instance.service_offering_id, usage_vm_instance.cpu_cores, usage_vm_instance.memory, usage_vm_instance.cpu_speed, usage_vm_instance.template_id, usage_vm_instance.hypervisor_type, usage_vm_instance.start_date, usage_vm_instance.end_date) VALUES (1, 10, 137, 3419, x'4353434d', 23, NULL, NULL, NULL, 477, x'4b564d', '2024-03-18 02:58:28', NULL) java.sql.SQLIntegrityConstraintViolationException: Duplicate entry '3419-1-2024-03-18 02:58:28' for key 'vm_instance_id'
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:118)
        at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122)
        at com.mysql.cj.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:555)
        at com.mysql.cj.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:339)
        at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1061)
        at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1009)
        at com.mysql.cj.jdbc.ClientPreparedStatement.executeLargeUpdate(ClientPreparedStatement.java:1320)
        at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdate(ClientPreparedStatement.java:994)
        at jdk.internal.reflect.GeneratedMethodAccessor48.invoke(Unknown Source)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:569)
        at com.mysql.cj.jdbc.ha.MultiHostConnectionProxy$JdbcInterfaceProxy.invoke(MultiHostConnectionProxy.java:107)
        at com.mysql.cj.jdbc.ha.FailoverConnectionProxy$FailoverJdbcInterfaceProxy.invoke(FailoverConnectionProxy.java:98)
        at jdk.proxy2/jdk.proxy2.$Proxy50.executeUpdate(Unknown Source)
        at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61)
        at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java)
        at com.cloud.utils.db.GenericDaoBase.persist(GenericDaoBase.java:1625)
        at com.cloud.usage.dao.UsageVMInstanceDaoImpl_EnhancerByCloudStack_2cbdde2b.CGLIB$persist$70(<generated>)
        at com.cloud.usage.dao.UsageVMInstanceDaoImpl_EnhancerByCloudStack_2cbdde2b_FastClassByCloudStack_a7ffbe4a.invoke(<generated>)
        at net.sf.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:228)
        at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:123)
        at com.cloud.usage.dao.UsageVMInstanceDaoImpl_EnhancerByCloudStack_2cbdde2b.persist(<generated>)
        at com.cloud.usage.UsageManagerImpl.populateDynamicComputeOfferingDetailsAndPersist(UsageManagerImpl.java:1395)
        at com.cloud.usage.UsageManagerImpl.createVMHelperEvent(UsageManagerImpl.java:1252)
        at com.cloud.usage.UsageManagerImpl.createHelperRecord(UsageManagerImpl.java:1072)
        at com.cloud.usage.UsageManagerImpl.parse(UsageManagerImpl.java:726)
        at com.cloud.usage.UsageManagerImpl.runInContextInternal(UsageManagerImpl.java:442)
        at com.cloud.usage.UsageManagerImpl$1.runInContext(UsageManagerImpl.java:379)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
        at com.cloud.usage.UsageManagerImpl.run(UsageManagerImpl.java:381)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at java.base/java.lang.Thread.run(Thread.java:840)

2025-07-07 08:24:49,333 ERROR [cloud.usage.UsageManagerImpl_EnhancerByCloudStack_10d8ae6e] (Usage-Job-1:[]) (logid:) Error saving usage instance for vm: 3419 javax.persistence.EntityExistsException: Entity already exists 
        at com.cloud.utils.db.GenericDaoBase.handleEntityExistsException(GenericDaoBase.java:891)
        at com.cloud.utils.db.GenericDaoBase.persist(GenericDaoBase.java:1664)
        at com.cloud.usage.dao.UsageVMInstanceDaoImpl_EnhancerByCloudStack_2cbdde2b.CGLIB$persist$70(<generated>)
        at com.cloud.usage.dao.UsageVMInstanceDaoImpl_EnhancerByCloudStack_2cbdde2b_FastClassByCloudStack_a7ffbe4a.invoke(<generated>)
        at net.sf.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:228)
        at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:123)
        at com.cloud.usage.dao.UsageVMInstanceDaoImpl_EnhancerByCloudStack_2cbdde2b.persist(<generated>)
        at com.cloud.usage.UsageManagerImpl.populateDynamicComputeOfferingDetailsAndPersist(UsageManagerImpl.java:1395)
        at com.cloud.usage.UsageManagerImpl.createVMHelperEvent(UsageManagerImpl.java:1252)
        at com.cloud.usage.UsageManagerImpl.createHelperRecord(UsageManagerImpl.java:1072)
        at com.cloud.usage.UsageManagerImpl.parse(UsageManagerImpl.java:726)
        at com.cloud.usage.UsageManagerImpl.runInContextInternal(UsageManagerImpl.java:442)
        at com.cloud.usage.UsageManagerImpl$1.runInContext(UsageManagerImpl.java:379)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
        at com.cloud.usage.UsageManagerImpl.run(UsageManagerImpl.java:381)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at java.base/java.lang.Thread.run(Thread.java:840)
Caused by: java.sql.SQLIntegrityConstraintViolationException: Duplicate entry '3419-1-2024-03-18 02:58:28' for key 'vm_instance_id'
        at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:118)
        at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122)
        at com.mysql.cj.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:555)
        at com.mysql.cj.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:339)
        at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1061)
        at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1009)
        at com.mysql.cj.jdbc.ClientPreparedStatement.executeLargeUpdate(ClientPreparedStatement.java:1320)
        at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdate(ClientPreparedStatement.java:994)
        at jdk.internal.reflect.GeneratedMethodAccessor48.invoke(Unknown Source)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:569)
        at com.mysql.cj.jdbc.ha.MultiHostConnectionProxy$JdbcInterfaceProxy.invoke(MultiHostConnectionProxy.java:107)
        at com.mysql.cj.jdbc.ha.FailoverConnectionProxy$FailoverJdbcInterfaceProxy.invoke(FailoverConnectionProxy.java:98)
        at jdk.proxy2/jdk.proxy2.$Proxy50.executeUpdate(Unknown Source)
        at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61)
        at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java)
        at com.cloud.utils.db.GenericDaoBase.persist(GenericDaoBase.java:1625)
        ... 23 more

[DaanHoogland]

"3419-1-2024-03-18 02:58:28” this is the event that would have a duplicate. You would find it in cloud.usage_events. It would be a START event, type 1. VM id 3419, and start time "2024-03-18 02:58:28”.