Examples with StopWatch alma.acs.util.StopWatch used on opensource projects

Example 11 with StopWatch

use of alma.acs.util.StopWatch in project ACS by ACS-Community.

the class EventSubscriberSmEngineTest method testTransitionPerformance.

/**
	 * Cycles 5.000 times between suspended and resumed state
	 * and asserts that the state machine overhead be less than 0.6 ms per event.
	 * This is done both with and without the check for allowed events.
	 */
@Test
public void testTransitionPerformance() throws Exception {
    // Configure logger "scxml@testTransitionPerformance" to higher than the INFO setting 
    // used in the other tests, because otherwise the SM is much too slow.
    configureLogging(AcsLogLevelDefinition.WARNING);
    final int cycles = 5000;
    engine.fireSignal(setUpEnvironment);
    engine.fireSignal(startReceivingEvents);
    StopWatch sw = new StopWatch();
    for (int i = 0; i < cycles; i++) {
        engine.fireSignal(suspend);
        engine.fireSignal(resume);
    }
    long elapsed = sw.getLapTimeMillis();
    logger.info("suspend/resume cycles: cycles = " + cycles + ", elapsed time ms = " + elapsed);
    // 5.000 cycles mean 10.000 signals/transitions, so 6000 ms max means <= 0.6 ms per transition.
    // Usually its around 1000 ms, but NRI machine te48 has gotten slow and reports failures regularly.
    assertThat("SM transitions too slow.", elapsed, lessThan(6000L));
    // Now do the same again, but including the check for applicable events
    // It seems that this second run is even faster, in spite of the additional check.
    // JIT optimization or some initial setup seem to distort the performance results.
    sw = new StopWatch();
    engine.getScxmlEngine();
    for (int i = 0; i < cycles; i++) {
        engine.fireSignalWithErrorFeedback(EventSubscriberSignal.suspend);
        engine.fireSignalWithErrorFeedback(EventSubscriberSignal.resume);
    }
    elapsed = sw.getLapTimeMillis();
    logger.info("suspend/resume cycles with event checks: cycles = " + cycles + ", elapsed time ms = " + elapsed);
    assertThat("SM transitions too slow.", elapsed, lessThan(6000L));
}

Example 12 with StopWatch

use of alma.acs.util.StopWatch in project ACS by ACS-Community.

the class AcsLogger method log.

/**
     * Logs the given <code>LogRecord</code>. 
     * The record can be modified or dropped by the optional filters provided in {@link #addLogRecordFilter(alma.acs.logging.AcsLogger.LogRecordFilter)}. 
     * <p>
     * Adding of context information:
     * <ul>
     * <li> If the LogRecord has a parameter that is a map which contains additional information 
     * about the line of code, thread, etc., the log record will be taken as provided, and no context
     * information will be added. This can be useful if
     *   <ul>
     *   <li> the log record was reconstructed from a remote error by the ACS error handling code
     *        (see <code>AcsJException</code>), or
     *   <li> if in very exceptional cases application code needs to manipulate such information by hand.
     *   </ul>
     * <li> otherwise, context information is inferred, similar to {@link LogRecord#inferCaller()},
     *   but additionally including thread name and line of code.
     * </ul>  
     * Note that by overloading this method, we intercept all logging activities of the base class.
     *  
     * @see java.util.logging.Logger#log(java.util.logging.LogRecord)
     */
public void log(LogRecord record) {
    // Both Level.OFF and AcsLogLevel.OFF use the same value INTEGER.max, but we anyway check for both.
    if (record.getLevel().intValue() == Level.OFF.intValue() || record.getLevel().intValue() == AcsLogLevel.OFF.intValue()) {
        throw new IllegalArgumentException("Level OFF must not be used for actual logging, but only for level filtering.");
    }
    StopWatch sw_all = null;
    if (PROFILE) {
        sw_all = new StopWatch(null);
    }
    // Level could be null and must then be inherited from the ancestor loggers, 
    // e.g. during JDK shutdown when the log level is nulled by the JDK LogManager 
    Logger loggerWithLevel = this;
    while (loggerWithLevel != null && loggerWithLevel.getLevel() == null && loggerWithLevel.getParent() != null) {
        loggerWithLevel = loggerWithLevel.getParent();
    }
    int levelValue = -1;
    if (loggerWithLevel.getLevel() == null) {
        // Just to be safe I add the necessary checks and warning message that improve over a NPE.
        if (!noLevelWarningPrinted) {
            System.out.println("Logger configuration error: no log level found for logger " + getLoggerName() + " or its ancestors. Will use Level.ALL instead.");
            noLevelWarningPrinted = true;
        }
        // @TODO: decide if resorting to ALL is desirable, or to use schema defaults, INFO, etc
        levelValue = Level.ALL.intValue();
    } else {
        // level is fine, reset the flag to print the error message again when log level is missing.
        noLevelWarningPrinted = false;
        levelValue = loggerWithLevel.getLevel().intValue();
    }
    // The same check will be repeated by the base class implementation of this method that gets called afterwards.
    if (record.getLevel().intValue() < levelValue || levelValue == offValue) {
        return;
    }
    // modify the logger name if necessary
    if (loggerName != null) {
        record.setLoggerName(loggerName);
    }
    // check if this record already has the context data attached which ACS needs but the JDK logging API does not provide
    LogParameterUtil paramUtil = new LogParameterUtil(record);
    Map<String, Object> specialProperties = paramUtil.extractSpecialPropertiesMap();
    if (specialProperties == null) {
        // we prepend the special properties map to the other parameters
        specialProperties = LogParameterUtil.createPropertiesMap();
        List<Object> paramList = paramUtil.getNonSpecialPropertiesMapParameters();
        paramList.add(0, specialProperties);
        record.setParameters(paramList.toArray());
        String threadName = Thread.currentThread().getName();
        specialProperties.put(LogParameterUtil.PARAM_THREAD_NAME, threadName);
        specialProperties.put(LogParameterUtil.PARAM_PROCESSNAME, this.processName);
        specialProperties.put(LogParameterUtil.PARAM_SOURCEOBJECT, this.sourceObject);
        // Get the stack trace
        StackTraceElement[] stack = (new Throwable()).getStackTrace();
        // search for the first frame before the "Logger" class.
        int ix = 0;
        boolean foundNonLogFrame = false;
        while (ix < stack.length) {
            StackTraceElement frame = stack[ix];
            String cname = frame.getClassName();
            if (!foundNonLogFrame && !loggerClassNames.contains(cname)) {
                // We've found the relevant frame.
                record.setSourceClassName(frame.getFileName());
                record.setSourceMethodName(frame.getMethodName());
                int lineNumber = frame.getLineNumber();
                specialProperties.put(LogParameterUtil.PARAM_LINE, Long.valueOf(lineNumber));
                foundNonLogFrame = true;
                if (this.callStacksToBeIgnored.isEmpty()) {
                    // performance optimization: avoid checking all "higher" stack frames
                    break;
                }
            }
            if (foundNonLogFrame) {
                if (callStacksToBeIgnored.contains(concatenateIgnoreLogData(cname, frame.getMethodName()))) {
                    //System.out.println("Won't log record with message " + record.getMessage());
                    return;
                }
            }
            ix++;
        }
    // We haven't found a suitable frame, so just punt. This is
    // OK as we are only committed to making a "best effort" here.
    }
    StopWatch sw_afterAcsLogger = null;
    if (PROFILE) {
        sw_afterAcsLogger = sw_all.createStopWatchForSubtask("afterAcsLogger");
        LogParameterUtil logParamUtil = new LogParameterUtil(record);
        logParamUtil.setStopWatch(sw_afterAcsLogger);
    }
    try {
        // Let the delegate or Logger base class handle the rest.
        if (delegate != null) {
            delegate.log(record);
        } else {
            super.log(record);
        }
        // Calculate statistics
        if (stats.getDisableStatistics() == false) {
            // Increment number of messages logged (only if log has succeded)
            stats.incrementNumberOfMessages();
            // Calculate time since last calculation of the logging statistics
            float timeElapsedSinceLastStatistics = (float) (System.currentTimeMillis() - stats.getLastStatisticsRepportTime()) / (float) (1000);
            // Determine if statistics are to be generated
            if (timeElapsedSinceLastStatistics >= (float) (stats.getStatisticsCalculationPeriod())) {
                // Calculate statistics
                stats.calculateLoggingStatistics();
                // Reset statistics
                stats.resetStatistics();
                // Print statistics logs
                AcsLogRecord logItem;
                Map<String, String> addedData = new HashMap<String, String>();
                addedData.put("StatisticsIdentification", stats.getStatisticsIdentification());
                addedData.put("LoggerId", getName());
                addedData.put("LastPeriodDuration", String.valueOf(stats.getActualStatisticsPeriod()));
                addedData.put("LastPeriodNumberOfMessages", String.valueOf(stats.getLastPeriodNumberOfMessages()));
                addedData.put("StatisticsGranularity", String.valueOf(stats.getStatisticsGranularity()));
                addedData.put("MessageStatistics", String.valueOf(stats.getMessageStatistics()));
                addedData.put("MessageIncrement", String.valueOf(stats.getMessageIncrement()));
                addedData.put("LastPeriodNumberOfErrorMessages", String.valueOf(stats.getLastPeriodNumberOfLogErrors()));
                addedData.put("ErrorMessageStatistics", String.valueOf(stats.getErrorStatistics()));
                addedData.put("ErrorMessageIncrement", String.valueOf(stats.getErrorIncrement()));
                logItem = createAcsLogRecord(Level.INFO, "LOGGING STATISTICS FOR: " + stats.getStatisticsIdentification() + "." + getName());
                logItem.setParameters(new Object[] { addedData });
                log(logItem);
            }
        }
    } catch (Exception e) {
        // Calculate statistics
        if (stats.getDisableStatistics() == false) {
            // Increment number of log errors (only if log has not succeded)
            stats.incrementNumberOfLogErrors();
            // Calculate time since last calculation of the logging statistics
            float timeElapsedSinceLastStatistics = (float) (System.currentTimeMillis() - stats.getLastStatisticsRepportTime()) / (float) (1000);
            // Determine if statistics are to be generated
            if (timeElapsedSinceLastStatistics >= (float) (stats.getStatisticsCalculationPeriod())) {
                // Calculate statistics
                stats.calculateLoggingStatistics();
                // Reset statistics
                stats.resetStatistics();
                // Print statistics logs
                AcsLogRecord logItem;
                Map<String, String> addedData = new HashMap<String, String>();
                addedData.put("StatisticsIdentification", stats.getStatisticsIdentification());
                addedData.put("LoggerId", getName());
                addedData.put("LastPeriodDuration", String.valueOf(stats.getActualStatisticsPeriod()));
                addedData.put("LastPeriodNumberOfMessages", String.valueOf(stats.getLastPeriodNumberOfMessages()));
                addedData.put("StatisticsGranularity", String.valueOf(stats.getStatisticsGranularity()));
                addedData.put("MessageStatistics", String.valueOf(stats.getMessageStatistics()));
                addedData.put("MessageIncrement", String.valueOf(stats.getMessageIncrement()));
                addedData.put("LastPeriodNumberOfErrorMessages", String.valueOf(stats.getLastPeriodNumberOfLogErrors()));
                addedData.put("ErrorMessageStatistics", String.valueOf(stats.getErrorStatistics()));
                addedData.put("ErrorMessageIncrement", String.valueOf(stats.getErrorIncrement()));
                logItem = createAcsLogRecord(Level.INFO, "LOGGING STATISTICS FOR: " + stats.getStatisticsIdentification() + "." + getName());
                logItem.setParameters(new Object[] { addedData });
                log(logItem);
            }
        }
        System.out.println("CRITICAL LOGGER FAILURE in " + getLoggerName());
    }
    if (PROFILE) {
        sw_afterAcsLogger.stop();
        sw_all.stop();
        long elapsedNanos = sw_all.getLapTimeNanos();
        if (profileSlowestCallStopWatch == null || profileSlowestCallStopWatch.getLapTimeNanos() < elapsedNanos) {
            profileSlowestCallStopWatch = sw_all;
        }
        profileLogTimeStats.addValue(elapsedNanos);
        if (profileLogTimeStats.getN() >= profileStatSize) {
            String msg = "Local logging times in ms for the last " + profileStatSize + " logs: ";
            msg += "mean=" + profileMillisecFormatter.format(profileLogTimeStats.getMean() * 1E-6);
            msg += ", median=" + profileMillisecFormatter.format(profileLogTimeStats.getPercentile(50) * 1E-6);
            msg += ", stdev=" + profileMillisecFormatter.format(profileLogTimeStats.getStandardDeviation() * 1E-6);
            msg += "; details of slowest log (from ";
            msg += IsoDateFormat.formatDate(profileSlowestCallStopWatch.getStartTime()) + "): ";
            msg += profileSlowestCallStopWatch.getSubtaskDetails();
            System.out.println(msg);
            profileSlowestCallStopWatch = null;
            profileLogTimeStats.clear();
        }
    }
}

Example 13 with StopWatch

use of alma.acs.util.StopWatch in project ACS by ACS-Community.

the class ServicesDaemonTest method testServicesBuilder.

public void testServicesBuilder() throws Exception {
    ServiceDefinitionBuilder sdb = daemon.create_service_definition_builder(instanceNumber);
    assertNotNull(sdb);
    assertEquals("ACS instance number must match the one provided to the factory", instanceNumber, sdb.acs_instance_number());
    // now we add services in an order that is not a legal startup order, to check re-ordering
    final String cdbPath = System.getProperty("user.dir");
    sdb.add_notification_service(systemNotificationServiceDefault.value, host);
    sdb.add_manager(host, "", true);
    sdb.add_notification_service(systemNotificationServiceLogging.value, host);
    // "" means that default name "Log" should be used
    sdb.add_logging_service(host, "");
    sdb.add_naming_service(host);
    sdb.add_xml_cdb(host, true, cdbPath);
    sdb.add_interface_repository(host, true, false);
    String xmlSrvDef = sdb.get_services_definition();
    sdb.close();
    System.out.println(xmlSrvDef);
    //System.getProperty("line.separator");
    String ls = "\n";
    String xmlExpected = "<acs_services_definition instance=\"" + instanceNumber + "\">" + ls + "<notification_service name=\"" + systemNotificationServiceDefault.value + "\" host=\"" + host + "\" />" + ls + "<manager host=\"" + host + "\" recovery=\"true\" />" + ls + "<notification_service name=\"" + systemNotificationServiceLogging.value + "\" host=\"" + host + "\" />" + ls + "<logging_service host=\"" + host + "\" />" + ls + "<naming_service host=\"" + host + "\" />" + ls + "<cdb host=\"" + host + "\" recovery=\"true\" cdb_xml_dir=\"" + cdbPath + "\" />" + ls + "<interface_repository host=\"" + host + "\" load=\"true\" wait_load=\"false\" />" + ls + "</acs_services_definition>" + ls;
    assertEquals(xmlExpected, xmlSrvDef);
    // Run these services
    DaemonSequenceCallbackImpl daemonSequenceCallbackImpl = new DaemonSequenceCallbackImpl(logger);
    DaemonSequenceCallback daemonSequenceCallback = activateDaemonSequenceCallback(daemonSequenceCallbackImpl);
    daemonSequenceCallbackImpl.prepareWaitForDone();
    StopWatch sw = new StopWatch(logger);
    daemon.start_services(xmlSrvDef, false, daemonSequenceCallback);
    assertTrue("The services did not start in 2 minutes", daemonSequenceCallbackImpl.waitForDone(2, TimeUnit.MINUTES));
    sw.logLapTime("call start_services");
    // Stop the services
    daemonSequenceCallbackImpl.prepareWaitForDone();
    sw = new StopWatch(logger);
    daemon.stop_services(xmlSrvDef, daemonSequenceCallback);
    assertTrue("The services did not stop in 2 minutes", daemonSequenceCallbackImpl.waitForDone(2, TimeUnit.MINUTES));
    sw.logLapTime("call stop_services");
}

Example 14 with StopWatch

use of alma.acs.util.StopWatch in project ACS by ACS-Community.

the class AcsContainerRunner method run.

/**
	 * Startup choreography: performs the various tasks in the correct order.
	 * <p>
	 * Note on the implementation: the steps involved are grouped as private methods
	 * that access the instance variables. The intent was to make the sequence clearer.
	 *   
	 * @param args  command line args as given to <code>main</code>.
	 * @throws AcsJContainerServicesEx  at the slightest provocation...
	 */
private void run(String[] args) throws AcsJContainerEx {
    StopWatch containerStartWatch = new StopWatch();
    // just a temp logger
    m_logger = ClientLogManager.getAcsLogManager().getLoggerForApplication("AcsContainerRunner", true);
    String argsString = "";
    for (String arg : args) {
        argsString += arg + " ";
    }
    m_logger.log(Level.INFO, "AcsContainerRunner#run with arguments " + argsString);
    setOptions(args);
    embeddedRunner = new AcsEmbeddedContainerRunner(false, m_recoveryModeOverride);
    embeddedRunner.setContainerName(m_containerName);
    embeddedRunner.setManagerLoc(m_managerLoc);
    checkReadyToRun();
    // now that embeddedRunner knows the container name, we can switch to the real logger  
    m_logger = embeddedRunner.getContainerLogger();
    m_acsCorba = new AcsCorba(m_logger);
    if (initialSleeptimeMillis > 0) {
        m_logger.fine("Container will sleep for " + initialSleeptimeMillis + " ms, e.g. to allow remote debuggers to attach at this early stage.");
        try {
            Thread.sleep(initialSleeptimeMillis);
        } catch (InterruptedException e) {
            m_logger.info("Woken up too early from initial-delay sleep.");
        }
    }
    m_acsCorba.initCorba(args, m_containerPort);
    m_acsCorba.runCorba();
    embeddedRunner.run(m_acsCorba);
    m_shutdownHook = new ShutdownHook(m_logger);
    Runtime.getRuntime().addShutdownHook(m_shutdownHook);
    m_shutdownHook.setAcsContainer(embeddedRunner.getContainer());
    initAcsLogging(embeddedRunner.getManagerProxy());
    m_logger.fine("entering orb loop");
    containerStartWatch.setLogger(m_logger);
    containerStartWatch.logLapTime("start the container");
    // here we hang for the life time of the container...
    m_acsCorba.blockOnORB();
    m_logger.fine("orb loop over.");
    m_logger.exiting(AcsContainerRunner.class.getName(), "run");
    m_shutdownHook.setRegularShutdownExpected();
}

Example 15 with StopWatch

use of alma.acs.util.StopWatch in project ACS by ACS-Community.

the class DynamicProxyFactory method checkMethodMatching.

/**
	 * Checks if all methods in <code>facade</code> can be mapped to a corresponding method 
	 * in <code>delegate</code> using the various mappers for argument translation.
	 * <p>
	 * TODO: make this check optional (property etc.) since it's not needed for stable
	 * and already verified interfaces. Perhaps move from runtime to buildtime?
	 * 
	 * @param facade  the interface that is presented to the client 
	 * 			(serverside: the container; clientside: the client application).
	 * @param invHandler  the invocation handler that can delegate the facade method calls
	 * 			(serverside: to the component implementation; clientside: to the CORBA stub).
	 * @return  true if all parameters can be mapped automatically both ways.
	 *           false if at least one pair of parameters requires manual mapping.
	 * @throws DynWrapperException if <code>delegate</code> does not provide 
	 *          a peer method for at least one method in <code>facade</code>.
	 *          Currently two methods are considered peers if they have the same name and the same
	 *          number of parameters. 
	 */
@SuppressWarnings("unchecked")
private boolean checkMethodMatching(Class facade, ComponentInvocationHandler invHandler) throws DynWrapperException {
    StopWatch methodMatchCheckTimer = new StopWatch(m_logger);
    boolean autonomousMapping = true;
    Method[] facadeMethods = facade.getMethods();
    for (int i = 0; i < facadeMethods.length; i++) {
        Method delegateMethod = invHandler.findDelegateMethod(facadeMethods[i]);
        Class[] facadeParams = facadeMethods[i].getParameterTypes();
        Class[] delegParams = delegateMethod.getParameterTypes();
        // number of parameters must be equal
        if (facadeParams.length != delegParams.length) {
            String msg = "unmatching numbers of parameters in method " + delegateMethod.getName();
            throw new DynWrapperException(msg);
        }
        // check calling parameters
        for (int pIndex = 0; pIndex < facadeParams.length; pIndex++) {
            // todo: use in/inout/out info from IR for more specific check; currently assumes worst case 'inout'
            if (!invHandler.canTranslate(facadeParams[pIndex], delegParams[pIndex]) || !invHandler.canTranslate(delegParams[pIndex], facadeParams[pIndex])) {
                String msg = "unable to map automatically between parameter type '" + facadeParams[pIndex].getName() + "' and '" + delegParams[pIndex].getName() + "' in method '" + facadeMethods[i].getName() + "'. This functionality must therefore be provided " + " by the component's associated " + ComponentHelper.class.getName() + " class.";
                m_logger.info(msg);
                autonomousMapping = false;
            }
        }
        // check return value
        Class delegateRet = delegateMethod.getReturnType();
        Class facadeRet = facadeMethods[i].getReturnType();
        if (!invHandler.canTranslate(delegateRet, facadeRet)) {
            String msg = "unable to map automatically from return type '" + delegateRet.getName() + "' to type '" + facadeRet.getName() + "' in method '" + facadeMethods[i].getName() + "'.";
            m_logger.info(msg);
            autonomousMapping = false;
        }
    }
    methodMatchCheckTimer.logLapTime("verify automatic translation for methods in " + facade.getName());
    return autonomousMapping;
}