001/**
002 * Licensed to the Apache Software Foundation (ASF) under one or more
003 * contributor license agreements.  See the NOTICE file distributed with
004 * this work for additional information regarding copyright ownership.
005 * The ASF licenses this file to You under the Apache License, Version 2.0
006 * (the "License"); you may not use this file except in compliance with
007 * the License.  You may obtain a copy of the License at
008 *
009 *      http://www.apache.org/licenses/LICENSE-2.0
010 *
011 * Unless required by applicable law or agreed to in writing, software
012 * distributed under the License is distributed on an "AS IS" BASIS,
013 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
014 * See the License for the specific language governing permissions and
015 * limitations under the License.
016 */
017package org.apache.camel.processor;
018
019import java.text.NumberFormat;
020import java.util.concurrent.ScheduledExecutorService;
021import java.util.concurrent.TimeUnit;
022import java.util.concurrent.atomic.AtomicInteger;
023
024import org.apache.camel.AsyncCallback;
025import org.apache.camel.AsyncProcessor;
026import org.apache.camel.CamelContext;
027import org.apache.camel.Exchange;
028import org.apache.camel.spi.IdAware;
029import org.apache.camel.support.ServiceSupport;
030import org.apache.camel.util.AsyncProcessorHelper;
031import org.apache.camel.util.CamelLogger;
032import org.apache.camel.util.ObjectHelper;
033import org.slf4j.Logger;
034import org.slf4j.LoggerFactory;
035
036/**
037 * A logger for logging message throughput.
038 *
039 * @version 
040 */
041public class ThroughputLogger extends ServiceSupport implements AsyncProcessor, IdAware {
042    private static final Logger LOG = LoggerFactory.getLogger(ThroughputLogger.class);
043
044    private String id;
045    private final AtomicInteger receivedCounter = new AtomicInteger();
046    private NumberFormat numberFormat = NumberFormat.getNumberInstance();
047    private long groupReceivedCount;
048    private boolean groupActiveOnly;
049    private Integer groupSize;
050    private long groupDelay = 1000;
051    private Long groupInterval;
052    private long startTime;
053    private long groupStartTime;
054    private String action = "Received";
055    private CamelContext camelContext;
056    private ScheduledExecutorService logSchedulerService;
057    private CamelLogger log;
058    private String lastLogMessage;
059    private double rate;
060    private double average;
061
062    public ThroughputLogger(CamelLogger log) {
063        this.log = log;
064    }
065
066    public ThroughputLogger(CamelLogger log, Integer groupSize) {
067        this(log);
068        setGroupSize(groupSize);
069    }
070
071    public ThroughputLogger(CamelLogger log, CamelContext camelContext, Long groupInterval, Long groupDelay, Boolean groupActiveOnly) {
072        this(log);
073        this.camelContext = camelContext;
074        setGroupInterval(groupInterval);
075        setGroupActiveOnly(groupActiveOnly);
076        if (groupDelay != null) {
077            setGroupDelay(groupDelay);
078        }
079    }
080
081    public String getId() {
082        return id;
083    }
084
085    public void setId(String id) {
086        this.id = id;
087    }
088
089    public void process(Exchange exchange) throws Exception {
090        AsyncProcessorHelper.process(this, exchange);
091    }
092
093    public boolean process(Exchange exchange, AsyncCallback callback) {
094        if (startTime == 0) {
095            startTime = System.currentTimeMillis();
096        }
097        int receivedCount = receivedCounter.incrementAndGet();
098
099        //only process if groupSize is set...otherwise we're in groupInterval mode
100        if (groupSize != null) {
101            if (receivedCount % groupSize == 0) {
102                lastLogMessage = createLogMessage(exchange, receivedCount);
103                log.log(lastLogMessage);
104            }
105        }
106
107        callback.done(true);
108        return true;
109    }
110
111    public Integer getGroupSize() {
112        return groupSize;
113    }
114
115    public void setGroupSize(Integer groupSize) {
116        if (groupSize == null || groupSize <= 0) {
117            throw new IllegalArgumentException("groupSize must be positive, was: " + groupSize);
118        }
119        this.groupSize = groupSize;
120    }
121
122    public Long getGroupInterval() {
123        return groupInterval;
124    }
125
126    public void setGroupInterval(Long groupInterval) {
127        if (groupInterval == null || groupInterval <= 0) {
128            throw new IllegalArgumentException("groupInterval must be positive, was: " + groupInterval);
129        }
130        this.groupInterval = groupInterval;
131    }
132
133    public long getGroupDelay() {
134        return groupDelay;
135    }
136
137    public void setGroupDelay(long groupDelay) {
138        this.groupDelay = groupDelay;
139    }
140
141    public boolean getGroupActiveOnly() {
142        return groupActiveOnly;
143    }
144
145    private void setGroupActiveOnly(boolean groupActiveOnly) {
146        this.groupActiveOnly = groupActiveOnly;
147    }
148
149    public NumberFormat getNumberFormat() {
150        return numberFormat;
151    }
152
153    public void setNumberFormat(NumberFormat numberFormat) {
154        this.numberFormat = numberFormat;
155    }
156
157    public String getAction() {
158        return action;
159    }
160
161    public void setAction(String action) {
162        this.action = action;
163    }
164
165    public void reset() {
166        startTime = 0;
167        receivedCounter.set(0);
168        groupStartTime = 0;
169        groupReceivedCount = 0;
170        average = 0.0d;
171        rate = 0.0d;
172        lastLogMessage = null;
173    }
174
175    public double getRate() {
176        return rate;
177    }
178
179    public double getAverage() {
180        return average;
181    }
182
183    public int getReceivedCounter() {
184        return receivedCounter.get();
185    }
186
187    public String getLastLogMessage() {
188        return lastLogMessage;
189    }
190
191    @Override
192    public void doStart() throws Exception {
193        // if an interval was specified, create a background thread
194        if (groupInterval != null) {
195            ObjectHelper.notNull(camelContext, "CamelContext", this);
196
197            logSchedulerService = camelContext.getExecutorServiceManager().newSingleThreadScheduledExecutor(this, "ThroughputLogger");
198            Runnable scheduledLogTask = new ScheduledLogTask();
199            LOG.info("Scheduling throughput log to run every {} millis.", groupInterval);
200            // must use fixed rate to have it trigger at every X interval
201            logSchedulerService.scheduleAtFixedRate(scheduledLogTask, groupDelay, groupInterval, TimeUnit.MILLISECONDS);
202        }
203    }
204
205    @Override
206    public void doStop() throws Exception {
207        if (logSchedulerService != null) {
208            camelContext.getExecutorServiceManager().shutdown(logSchedulerService);
209            logSchedulerService = null;
210        }
211    }
212
213    protected String createLogMessage(Exchange exchange, int receivedCount) {
214        long time = System.currentTimeMillis();
215        if (groupStartTime == 0) {
216            groupStartTime = startTime;
217        }
218
219        rate = messagesPerSecond(groupSize, groupStartTime, time);
220        average = messagesPerSecond(receivedCount, startTime, time);
221
222        long duration = time - groupStartTime;
223        groupStartTime = time;
224
225        return getAction() + ": " + receivedCount + " messages so far. Last group took: " + duration
226                + " millis which is: " + numberFormat.format(rate)
227                + " messages per second. average: " + numberFormat.format(average);
228    }
229
230    /**
231     * Background task that logs throughput stats.
232     */
233    private final class ScheduledLogTask implements Runnable {
234
235        public void run() {
236            // only run if CamelContext has been fully started
237            if (!camelContext.getStatus().isStarted()) {
238                LOG.trace("ThroughputLogger cannot start because CamelContext({}) has not been started yet", camelContext.getName());
239                return;
240            }
241
242            createGroupIntervalLogMessage();
243        }
244    }
245
246    protected void createGroupIntervalLogMessage() {
247        
248        // this indicates that no messages have been received yet...don't log yet
249        if (startTime == 0) {
250            return;
251        }
252        
253        int receivedCount = receivedCounter.get();
254
255        // if configured, hide log messages when no new messages have been received
256        if (groupActiveOnly && receivedCount == groupReceivedCount) {
257            return;
258        }
259
260        long time = System.currentTimeMillis();
261        if (groupStartTime == 0) {
262            groupStartTime = startTime;
263        }
264
265        long duration = time - groupStartTime;
266        long currentCount = receivedCount - groupReceivedCount;
267        rate = messagesPerSecond(currentCount, groupStartTime, time);
268        average = messagesPerSecond(receivedCount, startTime, time);
269
270        groupStartTime = time;
271        groupReceivedCount = receivedCount;
272
273        lastLogMessage = getAction() + ": " + currentCount + " new messages, with total " + receivedCount + " so far. Last group took: " + duration
274                + " millis which is: " + numberFormat.format(rate)
275                + " messages per second. average: " + numberFormat.format(average);
276        log.log(lastLogMessage);
277    }
278
279    protected double messagesPerSecond(long messageCount, long startTime, long endTime) {
280        // timeOneMessage = elapsed / messageCount
281        // messagePerSend = 1000 / timeOneMessage
282        double rate = messageCount * 1000.0;
283        rate /= endTime - startTime;
284        return rate;
285    }
286
287}