[Minor] Log duration of state changes in components

This commit is contained in:
Robert von Burg 2017-06-07 15:53:10 +02:00
parent 8ef9e3ac92
commit 0badb0fc01
2 changed files with 63 additions and 21 deletions

View File

@ -15,6 +15,8 @@
*/
package li.strolch.agent.impl;
import static li.strolch.utils.helper.StringHelper.formatNanoDuration;
import java.lang.reflect.Constructor;
import java.lang.reflect.InvocationTargetException;
import java.text.MessageFormat;
@ -180,6 +182,8 @@ public class ComponentContainerImpl implements ComponentContainer {
public void setup(StrolchConfiguration strolchConfiguration) {
this.state.validateStateChange(ComponentState.SETUP, "agent");
long start = System.nanoTime();
// set the application locale
Locale.setDefault(strolchConfiguration.getRuntimeConfiguration().getLocale());
String msg = "Application {0}:{1} is using locale {2}"; //$NON-NLS-1$
@ -215,13 +219,17 @@ public class ComponentContainerImpl implements ComponentContainer {
this.state = ComponentState.SETUP;
msg = "{0}:{1} Strolch Container setup with {2} components."; //$NON-NLS-1$
logger.info(MessageFormat.format(msg, applicationName, environment, this.componentMap.size()));
long took = System.nanoTime() - start;
msg = "{0}:{1} Strolch Container setup with {2} components. Took {3}"; //$NON-NLS-1$
logger.info(MessageFormat.format(msg, applicationName, environment, this.componentMap.size(),
formatNanoDuration(took)));
}
public void initialize(StrolchConfiguration strolchConfiguration) {
this.state.validateStateChange(ComponentState.INITIALIZED, "agent");
long start = System.nanoTime();
// now we can initialize the components
String msg = "{0}:{1} Initializing {2} Strolch Components..."; //$NON-NLS-1$
String environment = getEnvironment();
@ -233,13 +241,17 @@ public class ComponentContainerImpl implements ComponentContainer {
this.state = ComponentState.INITIALIZED;
msg = "{0}:{1} All {2} Strolch Components have been initialized."; //$NON-NLS-1$
logger.info(MessageFormat.format(msg, applicationName, environment, this.controllerMap.size()));
long took = System.nanoTime() - start;
msg = "{0}:{1} All {2} Strolch Components have been initialized. Took {3}"; //$NON-NLS-1$
logger.info(MessageFormat.format(msg, applicationName, environment, this.controllerMap.size(),
formatNanoDuration(took)));
}
public void start() {
this.state.validateStateChange(ComponentState.STARTED, "agent");
long start = System.nanoTime();
String msg = "{0}:{1} Starting {2} Strolch Components..."; //$NON-NLS-1$
String environment = getEnvironment();
String applicationName = getApplicationName();
@ -250,8 +262,10 @@ public class ComponentContainerImpl implements ComponentContainer {
this.state = ComponentState.STARTED;
msg = "{0}:{1} All {2} Strolch Components started. Strolch is now ready to be used. Have fun =))"; //$NON-NLS-1$
logger.info(MessageFormat.format(msg, applicationName, environment, this.controllerMap.size()));
long took = System.nanoTime() - start;
msg = "{0}:{1} All {2} Strolch Components started. Took {3}. Strolch is now ready to be used. Have fun =))"; //$NON-NLS-1$
logger.info(MessageFormat.format(msg, applicationName, environment, this.controllerMap.size(),
formatNanoDuration(took)));
logger.info(MessageFormat.format("System: {0}", SystemHelper.asString())); //$NON-NLS-1$
logger.info(MessageFormat.format("Memory: {0}", SystemHelper.getMemorySummary())); //$NON-NLS-1$
}
@ -259,6 +273,8 @@ public class ComponentContainerImpl implements ComponentContainer {
public void stop() {
this.state.validateStateChange(ComponentState.STOPPED, "agent");
long start = System.nanoTime();
String msg = "{0}:{1} Stopping {2} Strolch Components..."; //$NON-NLS-1$
String environment = getEnvironment();
String applicationName = getApplicationName();
@ -270,8 +286,10 @@ public class ComponentContainerImpl implements ComponentContainer {
Set<ComponentController> rootUpstreamComponents = this.dependencyAnalyzer.findRootDownstreamComponents();
containerStateHandler.stop(rootUpstreamComponents);
msg = "{0}:{1} All {2} Strolch Components have been stopped."; //$NON-NLS-1$
logger.info(MessageFormat.format(msg, applicationName, environment, this.controllerMap.size()));
long took = System.nanoTime() - start;
msg = "{0}:{1} All {2} Strolch Components have been stopped. Took {3}"; //$NON-NLS-1$
logger.info(MessageFormat.format(msg, applicationName, environment, this.controllerMap.size(),
formatNanoDuration(took)));
}
this.state = ComponentState.STOPPED;
@ -280,6 +298,8 @@ public class ComponentContainerImpl implements ComponentContainer {
public void destroy() {
this.state.validateStateChange(ComponentState.DESTROYED, "agent");
long start = System.nanoTime();
String msg = "{0}:{1} Destroying {2} Strolch Components..."; //$NON-NLS-1$
String environment = getEnvironment();
String applicationName = getApplicationName();
@ -291,8 +311,10 @@ public class ComponentContainerImpl implements ComponentContainer {
Set<ComponentController> rootUpstreamComponents = this.dependencyAnalyzer.findRootDownstreamComponents();
containerStateHandler.destroy(rootUpstreamComponents);
msg = "{0}:{1} All {2} Strolch Components have been destroyed!"; //$NON-NLS-1$
logger.info(MessageFormat.format(msg, applicationName, environment, this.controllerMap.size()));
long took = System.nanoTime() - start;
msg = "{0}:{1} All {2} Strolch Components have been destroyed! Took {3}"; //$NON-NLS-1$
logger.info(MessageFormat.format(msg, applicationName, environment, this.controllerMap.size(),
formatNanoDuration(took)));
this.controllerMap.clear();
this.componentMap.clear();
}

View File

@ -15,6 +15,8 @@
*/
package li.strolch.agent.impl;
import static li.strolch.utils.helper.StringHelper.formatNanoDuration;
import java.text.MessageFormat;
import java.util.Set;
@ -49,18 +51,24 @@ public class ComponentContainerStateHandler {
if (controller.getState() == ComponentState.INITIALIZED)
continue;
long start = System.nanoTime();
StrolchComponent component = controller.getComponent();
String componentName = component.getName();
ComponentConfiguration componentConfiguration = this.strolchConfiguration
.getComponentConfiguration(componentName);
String msg = "Initializing component {0}..."; //$NON-NLS-1$
logger.info(MessageFormat.format(msg, componentName));
try {
component.initialize(componentConfiguration);
} catch (Exception e) {
throw new StrolchException(MessageFormat.format("Failed to initialize component {0}", componentName), e);
throw new StrolchException(MessageFormat.format("Failed to initialize component {0}", componentName),
e);
}
long took = System.nanoTime() - start;
String msg = "Initialized component {0}. Took {1}"; //$NON-NLS-1$
logger.info(MessageFormat.format(msg, componentName, formatNanoDuration(took)));
}
// initialize direct downstream components
@ -77,15 +85,19 @@ public class ComponentContainerStateHandler {
if (controller.getState() == ComponentState.STARTED)
continue;
long start = System.nanoTime();
StrolchComponent component = controller.getComponent();
String msg = "Starting component {0}..."; //$NON-NLS-1$
String componentName = component.getName();
logger.info(MessageFormat.format(msg, componentName));
try {
component.start();
} catch (Exception e) {
throw new StrolchException(MessageFormat.format("Failed to start component {0}", componentName), e);
}
long took = System.nanoTime() - start;
String msg = "Started component {0}. Took {1}"; //$NON-NLS-1$
logger.info(MessageFormat.format(msg, componentName, formatNanoDuration(took)));
}
// Start direct downstream components
@ -102,17 +114,21 @@ public class ComponentContainerStateHandler {
if (controller.getState() == ComponentState.STOPPED)
continue;
long start = System.nanoTime();
StrolchComponent component = controller.getComponent();
String msg = "Stopping component {0}..."; //$NON-NLS-1$
String componentName = component.getName();
logger.info(MessageFormat.format(msg, componentName));
try {
component.stop();
} catch (Exception e) {
msg = "Failed to stop component {0} due to {1}"; //$NON-NLS-1$
String msg = "Failed to stop component {0} due to {1}"; //$NON-NLS-1$
msg = MessageFormat.format(msg, componentName, e.getMessage());
logger.error(msg, e);
}
long took = System.nanoTime() - start;
String msg = "Stopped component {0}. Took {1}"; //$NON-NLS-1$
logger.info(MessageFormat.format(msg, componentName, formatNanoDuration(took)));
}
// Stop direct upstream components
@ -128,17 +144,21 @@ public class ComponentContainerStateHandler {
if (controller.getState() == ComponentState.DESTROYED)
continue;
long start = System.nanoTime();
StrolchComponent component = controller.getComponent();
String msg = "Destroying component {0}..."; //$NON-NLS-1$
String componentName = component.getName();
logger.info(MessageFormat.format(msg, componentName));
try {
component.destroy();
} catch (Exception e) {
msg = "Failed to destroy component {0} due to {1}"; //$NON-NLS-1$
String msg = "Failed to destroy component {0} due to {1}"; //$NON-NLS-1$
msg = MessageFormat.format(msg, componentName, e.getMessage());
logger.error(msg, e);
}
long took = System.nanoTime() - start;
String msg = "Destroyed component {0}. Took {1}"; //$NON-NLS-1$
logger.info(MessageFormat.format(msg, componentName, formatNanoDuration(took)));
}
// Destroy direct upstream components