How to time portions of an apache camel route?

Question

I have a camel application that has many routes defined in a route builder. One of the routes has an xslt pipeline I would like to log the performance of in splunk. The format of the log needs to be:

PerformanceDetailResultMs=<numberOfMsTheXsltsTook>

I have tried doing the following which does not work because the result of System.currentTimeMillis() is held onto by spring and thus when the routeBuilder class executes whatever values were extracted at that time are held onto:

from(direct:somewhere)
    //... other things
    .setProperty(START_TIME, simple(Long.toString(System.currentTimeMillis()), Long.class))
    .to("xslt:templates/bop1.xslt?saxon=true")
    .to("xslt:templates/bop2.xslt?saxon=true")
    .to("xslt:templates/bop3.xslt?saxon=true")
    .to("xslt:templates/bop4.xslt?saxon=true")
    .to("xslt:templates/bop7.xslt?saxon=true")
    .to("xslt:templates/bop8.xslt?saxon=true")
    .to("xslt:templates/bop9.xslt?saxon=true")
    .to("xslt:templates/premGen1.xslt?saxon=true")
    .to("xslt:templates/premGen2.xslt?saxon=true")
    .setProperty(END_TIME, simple(Long.toString(System.currentTimeMillis()), Long.class))
    .log("PerformanceDetailResultMs=${exchangeProperty." + END_TIME + "} - ${exchangeProperty." + START_TIME + "}")
    //... other things

The START_TIME and END_TIME variables are just private static strings in hopes they could be re-used. This code does not work because the START_TIME and END_TIME are set on routeBuilder instantiation and held onto statically by spring. You do not get new timestamps every time through the route.

What is the proper "camel way" of timing a subset of operations such that I can output a log statement like:

PerformanceDetailResultMs=489234

Answer 1

If you're after statistics, look at the Camel Metrics component. You can setup a timer metric like so:

from("direct:somewhere")
    .to("metrics:timer:your.time?action=start")
    .to("xslt:templates/bop1.xslt?saxon=true")
    .to("metrics:timer:your.timer?action=stop");

Splunk can parse Json, so to pull out metrics, you can setup the timer to print in Json format:

MetricsRoutePolicyFactory factory = new MetricsRoutePolicyFactory();
factory.setPrettyPrint(true);
context.addRoutePolicyFactory(factory);

By default, this prints out metrics every 60 seconds, but you can change this.

If you do however require individual logs for each message, then as @Sagar suggests, you could set the property in a lambda function.

Answer 2

Simple thing that comes to my mind is

.process(exchange->exchange.setProperty(START_TIME,System.currentTimeMillis()))