https://github.com/Netflix/Hystrix: hystrix-core
  • Netflix Open Source Development 
Copyright 2012 Netflix, Inc.
Licensed under the Apache License, Version 2.0 (the "License");
you may not use this file except in compliance with the License.
You may obtain a copy of the License at
http://www.apache.org/licenses/LICENSE-2.0
Unless required by applicable law or agreed to in writing, software
distributed under the License is distributed on an "AS IS" BASIS,
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
See the License for the specific language governing permissions and
limitations under the License.

/**
 * Copyright 2012 Netflix, Inc.
 * 
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
 * You may obtain a copy of the License at
 * 
 * http://www.apache.org/licenses/LICENSE-2.0
 * 
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */
package com.netflix.hystrix;

import com.netflix.hystrix.metric.HystrixRequestEventsStream;
import com.netflix.hystrix.strategy.HystrixPlugins;
import com.netflix.hystrix.strategy.concurrency.HystrixConcurrencyStrategy;
import com.netflix.hystrix.strategy.concurrency.HystrixRequestContext;
import com.netflix.hystrix.strategy.concurrency.HystrixRequestVariableHolder;
import com.netflix.hystrix.strategy.concurrency.HystrixRequestVariableLifecycle;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import java.util.ArrayList;
import java.util.Collection;
import java.util.Collections;
import java.util.HashMap;
import java.util.LinkedHashMap;
import java.util.List;
import java.util.Map;
import java.util.concurrent.LinkedBlockingQueue;


Log of HystrixCommand executions and events during the current request. 
/**
 * Log of {@link HystrixCommand} executions and events during the current request.
 */
public class HystrixRequestLog {
    private static final Logger logger = LoggerFactory.getLogger(HystrixRequestLog.class);

    
RequestLog: Reduce Chance of Memory Leak
https://github.com/Netflix/Hystrix/issues/53
Upper limit on RequestLog before ignoring further additions and logging warnings.
Intended to help prevent memory leaks when someone isn't aware of the
HystrixRequestContext lifecycle or enabling/disabling RequestLog.

/**
     * RequestLog: Reduce Chance of Memory Leak
     * https://github.com/Netflix/Hystrix/issues/53
     * 
     * Upper limit on RequestLog before ignoring further additions and logging warnings.
     * 
     * Intended to help prevent memory leaks when someone isn't aware of the
     * HystrixRequestContext lifecycle or enabling/disabling RequestLog.
     */
    /* package */static final int MAX_STORAGE = 1000;

    private static final HystrixRequestVariableHolder<HystrixRequestLog> currentRequestLog = new HystrixRequestVariableHolder<HystrixRequestLog>(new HystrixRequestVariableLifecycle<HystrixRequestLog>() {
        @Override
        public HystrixRequestLog initialValue() {
            return new HystrixRequestLog();
        }

        public void shutdown(HystrixRequestLog value) {
            //write this value to the Request stream
            HystrixRequestEventsStream.getInstance().write(value.getAllExecutedCommands());
        }
    });

    
History of HystrixCommand executed in this request. 
/**
     * History of {@link HystrixCommand} executed in this request.
     */
    private LinkedBlockingQueue<HystrixCommand<?>> executedCommands = new LinkedBlockingQueue<HystrixCommand<?>>(MAX_STORAGE);

    
History of HystrixInvokableInfo executed in this request. 
/**
     * History of {@link HystrixInvokableInfo} executed in this request.
     */
    private LinkedBlockingQueue<HystrixInvokableInfo<?>> allExecutedCommands = new LinkedBlockingQueue<HystrixInvokableInfo<?>>(MAX_STORAGE);

    // prevent public instantiation
    private HystrixRequestLog() {
    }

    
HystrixRequestLog for current request as defined by HystrixRequestContext. 
Returns:HystrixRequestLog
/**
     * {@link HystrixRequestLog} for current request as defined by {@link HystrixRequestContext}.
     * 
     * @return {@link HystrixRequestLog}
     */
    public static HystrixRequestLog getCurrentRequest(HystrixConcurrencyStrategy concurrencyStrategy) {
        return currentRequestLog.get(concurrencyStrategy);
    }

    
HystrixRequestLog for current request as defined by HystrixRequestContext. 
 NOTE: This uses the default HystrixConcurrencyStrategy or global override. If an injected strategy is being used by commands you must instead use getCurrentRequest(HystrixConcurrencyStrategy). 
Returns:HystrixRequestLog
/**
     * {@link HystrixRequestLog} for current request as defined by {@link HystrixRequestContext}.
     * <p>
     * NOTE: This uses the default {@link HystrixConcurrencyStrategy} or global override. If an injected strategy is being used by commands you must instead use
     * {@link #getCurrentRequest(HystrixConcurrencyStrategy)}.
     * 
     * @return {@link HystrixRequestLog}
     */
    public static HystrixRequestLog getCurrentRequest() {
        return currentRequestLog.get(HystrixPlugins.getInstance().getConcurrencyStrategy());
    }

    
Retrieve HystrixCommand instances that were executed during this HystrixRequestContext. 
Returns:Collection<HystrixCommand<?>>
/**
     * Retrieve {@link HystrixCommand} instances that were executed during this {@link HystrixRequestContext}.
     * 
     * @return {@code Collection<HystrixCommand<?>>}
     */
    @Deprecated
    public Collection<HystrixCommand<?>> getExecutedCommands() {
        return Collections.unmodifiableCollection(executedCommands);
    }

    
Retrieve HystrixCommand instances that were executed during this HystrixRequestContext. 
Returns:Collection<HystrixCommand<?>>
/**
     * Retrieve {@link HystrixCommand} instances that were executed during this {@link HystrixRequestContext}.
     * 
     * @return {@code Collection<HystrixCommand<?>>}
     */
    public Collection<HystrixInvokableInfo<?>> getAllExecutedCommands() {
        return Collections.unmodifiableCollection(allExecutedCommands);
    }

    
Add HystrixCommand instance to the request log. 
Params:
  • command –  HystrixCommand<?>
/**
     * Add {@link HystrixCommand} instance to the request log.
     * 
     * @param command
     *            {@code HystrixCommand<?>}
     */
    /* package */void addExecutedCommand(HystrixInvokableInfo<?> command) {
        if (!allExecutedCommands.offer(command)) {
            // see RequestLog: Reduce Chance of Memory Leak https://github.com/Netflix/Hystrix/issues/53
            logger.warn("RequestLog ignoring command after reaching limit of " + MAX_STORAGE + ". See https://github.com/Netflix/Hystrix/issues/53 for more information.");
        }

        // TODO remove this when deprecation completed
        if (command instanceof HystrixCommand) {
            @SuppressWarnings("rawtypes")
            HystrixCommand<?> _c = (HystrixCommand) command;
            if (!executedCommands.offer(_c)) {
                // see RequestLog: Reduce Chance of Memory Leak https://github.com/Netflix/Hystrix/issues/53
                logger.warn("RequestLog ignoring command after reaching limit of " + MAX_STORAGE + ". See https://github.com/Netflix/Hystrix/issues/53 for more information.");
            }
        }
    }

    
Formats the log of executed commands into a string usable for logging purposes.


Examples:

    

  • TestCommand[SUCCESS][1ms]
    • 

  • TestCommand[SUCCESS][1ms], TestCommand[SUCCESS, RESPONSE_FROM_CACHE][1ms]x4
    • 

  • TestCommand[TIMEOUT][1ms]
    • 

  • TestCommand[FAILURE][1ms]
    • 

  • TestCommand[THREAD_POOL_REJECTED][1ms]
    • 

  • TestCommand[THREAD_POOL_REJECTED, FALLBACK_SUCCESS][1ms]
    • 

  • TestCommand[EMIT, SUCCESS][1ms]
    • 

  • TestCommand[EMITx5, SUCCESS][1ms]
    • 

  • TestCommand[EMITx5, FAILURE, FALLBACK_EMITx6, FALLBACK_FAILURE][100ms]
    • 

  • TestCommand[FAILURE, FALLBACK_SUCCESS][1ms], TestCommand[FAILURE, FALLBACK_SUCCESS, RESPONSE_FROM_CACHE][1ms]x4
    • 

  • GetData[SUCCESS][1ms], PutData[SUCCESS][1ms], GetValues[SUCCESS][1ms], GetValues[SUCCESS, RESPONSE_FROM_CACHE][1ms], TestCommand[FAILURE, FALLBACK_FAILURE][1ms], TestCommand[FAILURE,
FALLBACK_FAILURE, RESPONSE_FROM_CACHE][1ms]
    • 




If a command has a multiplier such as x4, that means this command was executed 4 times with the same events. The time in milliseconds is the sum of the 4 executions.


For example, TestCommand[SUCCESS][15ms]x4 represents TestCommand being executed 4 times and the sum of those 4 executions was 15ms. These 4 each executed the run() method since
RESPONSE_FROM_CACHE was not present as an event.
If an EMIT or FALLBACK_EMIT has a multiplier such as x5, that means a HystrixObservableCommand was used and it emitted that number of OnNexts.


For example, TestCommand[EMITx5, FAILURE, FALLBACK_EMITx6, FALLBACK_FAILURE][100ms] represents TestCommand executing observably, emitted 5 OnNexts, then an OnError.
This command also has an Observable fallback, and it emits 6 OnNexts, then an OnCompleted.

Returns:String request log or "Unknown" if unable to instead of throwing an exception.
/**
     * Formats the log of executed commands into a string usable for logging purposes.
     * <p>
     * Examples:
     * <ul>
     * <li>TestCommand[SUCCESS][1ms]</li>
     * <li>TestCommand[SUCCESS][1ms], TestCommand[SUCCESS, RESPONSE_FROM_CACHE][1ms]x4</li>
     * <li>TestCommand[TIMEOUT][1ms]</li>
     * <li>TestCommand[FAILURE][1ms]</li>
     * <li>TestCommand[THREAD_POOL_REJECTED][1ms]</li>
     * <li>TestCommand[THREAD_POOL_REJECTED, FALLBACK_SUCCESS][1ms]</li>
     * <li>TestCommand[EMIT, SUCCESS][1ms]</li>
     * <li>TestCommand[EMITx5, SUCCESS][1ms]</li>
     * <li>TestCommand[EMITx5, FAILURE, FALLBACK_EMITx6, FALLBACK_FAILURE][100ms]</li>
     * <li>TestCommand[FAILURE, FALLBACK_SUCCESS][1ms], TestCommand[FAILURE, FALLBACK_SUCCESS, RESPONSE_FROM_CACHE][1ms]x4</li>
     * <li>GetData[SUCCESS][1ms], PutData[SUCCESS][1ms], GetValues[SUCCESS][1ms], GetValues[SUCCESS, RESPONSE_FROM_CACHE][1ms], TestCommand[FAILURE, FALLBACK_FAILURE][1ms], TestCommand[FAILURE,
     * FALLBACK_FAILURE, RESPONSE_FROM_CACHE][1ms]</li>
     * </ul>
     * <p>
     * If a command has a multiplier such as <code>x4</code>, that means this command was executed 4 times with the same events. The time in milliseconds is the sum of the 4 executions.
     * <p>
     * For example, <code>TestCommand[SUCCESS][15ms]x4</code> represents TestCommand being executed 4 times and the sum of those 4 executions was 15ms. These 4 each executed the run() method since
     * <code>RESPONSE_FROM_CACHE</code> was not present as an event.
     *
     * If an EMIT or FALLBACK_EMIT has a multiplier such as <code>x5</code>, that means a <code>HystrixObservableCommand</code> was used and it emitted that number of <code>OnNext</code>s.
     * <p>
     * For example, <code>TestCommand[EMITx5, FAILURE, FALLBACK_EMITx6, FALLBACK_FAILURE][100ms]</code> represents TestCommand executing observably, emitted 5 <code>OnNext</code>s, then an <code>OnError</code>.
     * This command also has an Observable fallback, and it emits 6 <code>OnNext</code>s, then an <code>OnCompleted</code>.
     *
     * @return String request log or "Unknown" if unable to instead of throwing an exception.
     */
    public String getExecutedCommandsAsString() {
        try {
            LinkedHashMap<String, Integer> aggregatedCommandsExecuted = new LinkedHashMap<String, Integer>();
            Map<String, Integer> aggregatedCommandExecutionTime = new HashMap<String, Integer>();

            StringBuilder builder = new StringBuilder();
            int estimatedLength = 0;
            for (HystrixInvokableInfo<?> command : allExecutedCommands) {
                builder.setLength(0);
                builder.append(command.getCommandKey().name());

                List<HystrixEventType> events = new ArrayList<HystrixEventType>(command.getExecutionEvents());
                if (events.size() > 0) {
                    Collections.sort(events);
                    //replicate functionality of Arrays.toString(events.toArray()) to append directly to existing StringBuilder
                    builder.append("[");
                    for (HystrixEventType event : events) {
                        switch (event) {
                            case EMIT:
                                int numEmissions = command.getNumberEmissions();
                                if (numEmissions > 1) {
                                    builder.append(event).append("x").append(numEmissions).append(", ");
                                } else {
                                    builder.append(event).append(", ");
                                }
                                break;
                            case FALLBACK_EMIT:
                                int numFallbackEmissions = command.getNumberFallbackEmissions();
                                if (numFallbackEmissions > 1) {
                                    builder.append(event).append("x").append(numFallbackEmissions).append(", ");
                                } else {
                                    builder.append(event).append(", ");
                                }
                                break;
                            default:
                                builder.append(event).append(", ");
                        }
                    }
                    builder.setCharAt(builder.length() - 2, ']');
                    builder.setLength(builder.length() - 1);
                } else {
                    builder.append("[Executed]");
                }

                String display = builder.toString();
                estimatedLength += display.length() + 12; //add 12 chars to display length for appending totalExecutionTime and count below
                Integer counter = aggregatedCommandsExecuted.get(display);
                if( counter != null){
                    aggregatedCommandsExecuted.put(display, counter + 1);
                } else {
                    // add it
                    aggregatedCommandsExecuted.put(display, 1);
                }                

                int executionTime = command.getExecutionTimeInMilliseconds();
                if (executionTime < 0) {
                    // do this so we don't create negative values or subtract values
                    executionTime = 0;
                }
                counter = aggregatedCommandExecutionTime.get(display);
                if( counter != null && executionTime > 0){
                    // add to the existing executionTime (sum of executionTimes for duplicate command displayNames)
                    aggregatedCommandExecutionTime.put(display, aggregatedCommandExecutionTime.get(display) + executionTime);
                } else {
                    // add it
                    aggregatedCommandExecutionTime.put(display, executionTime);
                }

            }

            builder.setLength(0);
            builder.ensureCapacity(estimatedLength);
            for (String displayString : aggregatedCommandsExecuted.keySet()) {
                if (builder.length() > 0) {
                    builder.append(", ");
                }
                builder.append(displayString);

                int totalExecutionTime = aggregatedCommandExecutionTime.get(displayString);
                builder.append("[").append(totalExecutionTime).append("ms]");

                int count = aggregatedCommandsExecuted.get(displayString);
                if (count > 1) {
                    builder.append("x").append(count);
                }
            }
            return builder.toString();
        } catch (Exception e) {
            logger.error("Failed to create HystrixRequestLog response header string.", e);
            // don't let this cause the entire app to fail so just return "Unknown"
            return "Unknown";
        }
    }

}