How to measure elapsed time with Apache Camel

Question

I need to measure how much time it takes to process external service response in Apache Camel.

I've search the web for solutions and surprisingly there was no acceptable one.

Using an EventNotifier feels too heavy weight and more framework level performance measurement tool.

So I've made my own simple solution, but I'm hoping for something better out there I've missed or at least a constructive feedback.

A solution attempt below.

You should probably go to [Code Review](http://codereview.stackexchange.com/) for that kind of question since you already have an answer. — Olivier Grégoire, Feb 23 '15 at 09:56
@OlivierGrégoire We on Code Review need the code to be reviewed to be present in the question. In its current state this question would be off topic. Please see our [help center](http://codereview.stackexchange.com/help) — Heslacher, Feb 23 '15 at 10:00
CodeReview is for working, existing, self-maintained code. Which is what this question seems to be about, so that's good! This question would work, provided it merged the question and answer as a question on CodeReview. I don't think that'd be easy to do for a mod, so probably the OP would have to post it themselves... — Pimgd, Feb 23 '15 at 10:00
Actually I'm interested in input from other Camel users or developers on how to do it better or if this approach is legit. — Paweł Prażak, Feb 23 '15 at 10:02

score 5 · Answer 1 · answered Feb 26 '15 at 09:36

5

I think that camel do this by default.

Available as of Camel 2.12 Message History is enabled by default from Camel 2.12. During routing Camel captures how the Exchange is routed, as a org.apache.camel.MessageHistory entity that is stored on the Exchange. On the org.apache.camel.MessageHistory there is information abut the route id, processor id, timestamp, and elapsed time it took to process the Exchange by the processor.

Only that you have to do is get the MessageHistory in your "doFinally" code:

List<MessageHistory> list = exchange.getProperty(Exchange.MESSAGE_HISTORY,List.class);

There you can get the the elapsed time for each route

answered Feb 26 '15 at 09:36

Panchitoboy

810
9
18

Yes, but the thing is it produces different results than Guava's Stopwatch and honestly I believe more in Guava than Camel accuracy. Also I don't want my feature to be dependent on this particular Camel feature, because we might decide to turn it of at some point for performance reasons. – Paweł Prażak Feb 26 '15 at 12:50
Its impossible to have the same results, because camel do Stopwatch before it call the bean(stopwatch, "stop"). But the difference is big? – Panchitoboy Feb 26 '15 at 12:59
1

Yes, it's order of magnitude, so probably there are some other processing costs involved, that accounts for the difference. In a quick test it was 40 ms vs >300 ms, IIRC – Paweł Prażak Feb 26 '15 at 13:03
I've just checked on another example and it seam to be the same within 1 ms. – Paweł Prażak Feb 26 '15 at 13:19
I've edited my response, and now I'm really puzzled, looks like I'm missing something simple, or Guava's Stopwatch is broken (very unlikely). – Paweł Prażak Feb 26 '15 at 13:33
2

I cant comment in your answer, that camel dont take the exception handling into account. If you need that you have to use something like your solution but if you dont, camel is the way – Panchitoboy Feb 27 '15 at 10:36
1

I've ended up using `MessageHistory` and ignoring the exception handling. Thanks for your input :) – Paweł Prażak Mar 24 '15 at 11:08

Paweł Prażak · Answer 2 · 2015-02-26T15:45:21.237

This is how my business logic looks like:

from(incomingUri).routeId(ROUTE_ID)
            ...
            .doTry()
                .bean(stopwatch, "start")
                .to(externalService)
            .doCatch(NoHttpResponseException.class, ProtocolException.class, IOException.class)
                .process(externalServiceExceptionProcessor(ERROR_MESSAGE_SERVICE_NOT_RESPONDING))
            .doFinally()
                .bean(stopwatch, "stop")
            .end()
            ...

The Stopwatch bean instantition:

StopWatchBean stopwatch = new StopWatchBean(new ExchangeConsumer<Stopwatch>() {
        @Override
        public void accept(Exchange exchange, Stopwatch stopwatch) {
            Long taken = stopwatch.elapsed(MILLISECONDS);
            exchange.setProperty(RESPONSE_TIME, constant(taken));
        }
});

and class definition:

public class StopWatchBean {

    private final Stopwatch stopwatch;
    private final ExchangeConsumer<Stopwatch> onStopFunction;

    public StopWatchBean(ExchangeConsumer<Stopwatch> onStopFunction) {
        this.stopwatch = Stopwatch.createUnstarted();
        this.onStopFunction = onStopFunction;
    }

    public void stop(Exchange exchange) {
        if (!stopwatch.isRunning()) {
            return;
        }
        stopwatch.stop();
        onStopFunction.accept(exchange, stopwatch);
    }

    public void start(Exchange unused) {
        stopwatch.start();
    }

    public void reset(Exchange unused) {
        stopwatch.reset();
    }

}

The Stopwatch is from Guava and the Consumer is just a custom functional interface.

Waiting for comments.

EDIT: I've added some simple code, like:

started = System.currentTimeMillis();
...
stopped = System.currentTimeMillis();

elapsed = stopped - started;

and made some measurements, on normal case looks good:

[xxxxxxxxxProxy    ] [stopWatchStart    ] [bean[StopWatchBean{elapsed=100, stopwatch=100.8 ms}]                          ] [         1]
[xxxxxxxxxProxy    ] [toXxxxxxxxxx      ] [https://127.0.0.1:5680/xxxxxxxxx?throwExceptionOnFailure=false&bridgeEndpoint=] [       100]
[xxxxxxxxxProxy    ] [stopWatchStop     ] [bean[StopWatchBean{elapsed=100, stopwatch=100.8 ms}]                          ] [         3]

and on error/exception is different:

[xxxxxxxxxProxy    ] [stopWatchStart    ] [bean[StopWatchBean{elapsed=38, stopwatch=344.1 ms}]                           ] [         1]
[xxxxxxxxxProxy    ] [toXxxxxxxxxx      ] [https://127.0.0.1:5680/xxxxxxxxx?throwExceptionOnFailure=false&bridgeEndpoint=] [        37]
[xxxxxxxxxProxy    ] [stopWatchStop     ] [bean[StopWatchBean{elapsed=38, stopwatch=344.1 ms}]                           ] [         1]

I'm puzzled, why the difference, 38 vs 344, could it be due to Camel not taking Exception handling into account?

How to measure elapsed time with Apache Camel

2 Answers2