[GENIUS-236] Excessive toString in OvsdbNodeListener.getOvsdbTepInfo() Created: 12/Nov/18 Updated: 15/Nov/18 Resolved: 15/Nov/18 |
|
| Status: | Resolved |
| Project: | genius |
| Component/s: | ITM |
| Affects Version/s: | Oxygen-SR3 |
| Fix Version/s: | Oxygen-SR4 |
| Type: | Bug | Priority: | Medium |
| Reporter: | Michael Vorburger | Assignee: | TARUN THAKUR |
| Resolution: | Done | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Description |
|
I'm looking at a Java Flight Recording obtained from (internal) scale lab testing, and see extensive "TLAB Allocations" due to what appears to be a clear mistake causing excessive toString() usage in ITM's OvsdbNodeListener.getOvsdbTepInfo(): char[] java.util.Arrays.copyOf(char[], int) 321 void java.lang.AbstractStringBuilder.ensureCapacityInternal(int) 321 AbstractStringBuilder java.lang.AbstractStringBuilder.append(boolean) 243 StringBuilder java.lang.StringBuilder.append(boolean) 243 String org.opendaylight.genius.itm.commons.OvsdbTepInfo.toString() 243 OvsdbTepInfo org.opendaylight.genius.itm.listeners.OvsdbNodeListener.getOvsdbTepInfo(OvsdbNodeAugmentation) 243 void org.opendaylight.genius.itm.listeners.OvsdbNodeListener.update(Node, Node) 243 void org.opendaylight.genius.itm.listeners.OvsdbNodeListener.update(DataObject, DataObject) 243 void org.opendaylight.serviceutils.tools.mdsal.listener.DataTreeChangeListenerActions.update(InstanceIdentifier, DataObject, DataObject) 243 void org.opendaylight.serviceutils.tools.mdsal.listener.DataTreeChangeListenerActions.onDataTreeChanged(Collection, DataStoreMetrics) 243 void org.opendaylight.serviceutils.tools.mdsal.listener.AbstractSyncDataTreeChangeListener.onDataTreeChanged(Collection) 243 void org.opendaylight.controller.md.sal.binding.impl.BindingDOMDataTreeChangeListenerAdapter.onDataTreeChanged(Collection) 243 void org.opendaylight.controller.cluster.datastore.DataTreeChangeListenerActor.dataChanged(DataTreeChanged) 243 void org.opendaylight.controller.cluster.datastore.DataTreeChangeListenerActor.handleReceive(Object) 243 void org.opendaylight.controller.cluster.common.actor.AbstractUntypedActor.onReceive(Object) 243 Object akka.actor.UntypedActor$$anonfun$receive$1.applyOrElse(Object, Function1) 243 void akka.actor.Actor.aroundReceive(PartialFunction, Object) 243 void akka.actor.Actor.aroundReceive$(Actor, PartialFunction, Object) 243 void akka.actor.UntypedActor.aroundReceive(PartialFunction, Object) 243 void akka.actor.ActorCell.receiveMessage(Object) 243 void akka.actor.ActorCell.invoke(Envelope) 243 void akka.dispatch.Mailbox.processMailbox(int, long) 243 void akka.dispatch.Mailbox.run() 243 boolean akka.dispatch.Mailbox.exec() 243 int akka.dispatch.forkjoin.ForkJoinTask.doExec() 243 void akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinTask) 243 void akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool$WorkQueue) 243 void akka.dispatch.forkjoin.ForkJoinWorkerThread.run() 243 |
| Comments |
| Comment by Tarun Thakur [ 15/Nov/18 ] |
|
Michael, I hope above issue is pointing to line "LOG.trace("ovsdbTepInfo retrieved {}", ovsdbTepInfoObj);" in OvsdbNodeListener.getOvsdbTepInfo() This is right that above method will be invoked every few seconds via update() method of OvsdbNodeListener that is why it may cause frequent TLAB allocation due to toString() calling on the object ovsdbTepInfoObj in the log message. As a solution, we may remove this log message because required paramters of ovsdbTepInfoObj are being printed at places where they are being used for performing TEP operations like add/remove in the ITM config DS. Please share your suggestion if it seems fine to you.
|
| Comment by Tarun Thakur [ 15/Nov/18 ] |
|
Even, log message can be covered under if condition like below: if (LOG.isTraceEnabled()) { This can also solve problem as it is done at many places in Genius code. But, I feel that trace log message can be removed. |
| Comment by Michael Vorburger [ 15/Nov/18 ] |
|
Tarun, if we look carefully at the exact stack trace above, we note:
String org.opendaylight.genius.itm.commons.OvsdbTepInfo.toString() 243
OvsdbTepInfo org.opendaylight.genius.itm.listeners.OvsdbNodeListener.getOvsdbTepInfo(OvsdbNodeAugmentation) 243
This has Affects Version Oxygen, and indeed in Oxygen (only; already fixed in Fluorine & Neon) we had:
LOG.trace("{}", ovsdbTepInfoObj.toString());
which is very bad and what caused this; I've just fixed it in c/77850. FYI there is normally no need to use isTraceEnabled(), because LOG.trace() is already fast enough, and only does the toString() on arguments if that level is emabled. That is unless in the LOG statement you do something that has some cost to calculate (i.e. don't just pass an object reference), then you need isXXXEnabled. The linked Wiki page explains this more; hope that helps. |