[CLOUDSTACK-9094] Multiple threads are being used to collect the stats from the same VR

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 4.6.0
• Fix Version/s: Future
• Component/s: Management Server, Virtual Router
• Security Level: Public (Anyone can view this level - this is the default.)
• Assignee: Harikrishna Patnala
• Reporter: Harikrishna Patnala
• Created: 30/Nov/15 06:33
• Updated: 19/Dec/17 08:03
• Resolved: 19/Dec/17 08:03

Description

From the logs we can see that the management server is sending the networkusagecommand to a VR twice within a very short interval. This doesn't have any impact on the network usage being reported, however it seems to consume direct agent threads unnecessarily.

See the below snippet from the logs where networkusage command was sent to the same VR at the same time

2014-03-04 00:02:07,178 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-113:null) Seq 10-1242718973: Executing request
2014-03-04 00:02:07,482 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-113:null) Seq 10-1242718973: Response Received:
2014-03-04 00:02:07,482 DEBUG [agent.transport.Request] (DirectAgent-113:null) Seq 10-1242718973: Processing: { Ans: , MgmtId: 144027776315500, via: 10, Ver: v1, Flags: 10, [{"com.cloud.agent.api.NetworkUsageAnswer":{"routerName":"r-59-VM","bytesSent":2937782,"bytesReceived":114175352,"result":true,"details":"","wait":0}}] }
2014-03-04 00:02:07,482 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 10-1242718973: Received: { Ans: , MgmtId: 144027776315500, via: 10, Ver: v1, Flags: 10,

{ NetworkUsageAnswer } }
2014-03-04 00:02:07,482 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand:

2014-03-04 00:02:07,198 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-244:null) Seq 10-1242718974: Executing request
2014-03-04 00:02:07,510 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-244:null) Seq 10-1242718974: Response Received:
2014-03-04 00:02:07,510 DEBUG [agent.transport.Request] (DirectAgent-244:null) Seq 10-1242718974: Processing: { Ans: , MgmtId: 144027776315500, via: 10, Ver: v1, Flags: 10, [{"com.cloud.agent.api.NetworkUsageAnswer":{"routerName":"r-59-VM","bytesSent":2937782,"bytesReceived":114175352,"result":true,"details":"","wait":0}}] }
2014-03-04 00:02:07,510 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 10-1242718974: Received: { Ans: , MgmtId: 144027776315500, via: 10, Ver: v1, Flags: 10, { NetworkUsageAnswer }

}
2014-03-04 00:02:07,510 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand:
2014-03-04 00:02:07,513 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Router stats changed from the time NetworkUsageCommand was sent. Ignoring current answer. Router: r-59-VM Rcvd: 114175352Sent: 2937782
2014-03-04 00:02:07,514 DEBUG [db.Transaction.Transaction] (RouterMonitor-1:null) Rolling back the transaction: Time = 2 Name = -VirtualNetworkApplianceManagerImpl$NetworkUsageTask.run:900-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRunAndReset:351-FutureTask.runAndReset:178-ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201:165-ScheduledThreadPoolExecutor$ScheduledFutureTask.run:267-ThreadPoolExecutor.runWorker:1146-ThreadPoolExecutor$Worker.run:615-Thread.run:701; called by -Transaction.rollback:897-Transaction.removeUpTo:840-Transaction.close:664-VirtualNetworkApplianceManagerImpl$NetworkUsageTask.run:955-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRunAndReset:351-FutureTask.runAndReset:178-ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201:165-ScheduledThreadPoolExecutor$ScheduledFutureTask.run:267-ThreadPoolExecutor.runWorker:1146-ThreadPoolExecutor$Worker.run:615-Thread.run:701