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.support.ServiceSupport;
029import org.apache.camel.util.AsyncProcessorHelper;
030import org.apache.camel.util.CamelLogger;
031import org.apache.camel.util.ObjectHelper;
032import org.slf4j.Logger;
033import org.slf4j.LoggerFactory;
034
035/**
036 * A logger for logging message throughput.
037 *
038 * @version 
039 */
040public class ThroughputLogger extends ServiceSupport implements AsyncProcessor {
041    private static final Logger LOG = LoggerFactory.getLogger(ThroughputLogger.class);
042
043    private final AtomicInteger receivedCounter = new AtomicInteger();
044    private NumberFormat numberFormat = NumberFormat.getNumberInstance();
045    private long groupReceivedCount;
046    private boolean groupActiveOnly;
047    private Integer groupSize;
048    private long groupDelay = 1000;
049    private Long groupInterval;
050    private long startTime;
051    private long groupStartTime;
052    private String action = "Received";
053    private CamelContext camelContext;
054    private ScheduledExecutorService logSchedulerService;
055    private CamelLogger log;
056    private String lastLogMessage;
057    private double rate;
058    private double average;
059
060    public ThroughputLogger(CamelLogger log) {
061        this.log = log;
062    }
063
064    public ThroughputLogger(CamelLogger log, Integer groupSize) {
065        this(log);
066        setGroupSize(groupSize);
067    }
068
069    public ThroughputLogger(CamelLogger log, CamelContext camelContext, Long groupInterval, Long groupDelay, Boolean groupActiveOnly) {
070        this(log);
071        this.camelContext = camelContext;
072        setGroupInterval(groupInterval);
073        setGroupActiveOnly(groupActiveOnly);
074        if (groupDelay != null) {
075            setGroupDelay(groupDelay);
076        }
077    }
078
079    public void process(Exchange exchange) throws Exception {
080        AsyncProcessorHelper.process(this, exchange);
081    }
082
083    public boolean process(Exchange exchange, AsyncCallback callback) {
084        if (startTime == 0) {
085            startTime = System.currentTimeMillis();
086        }
087        int receivedCount = receivedCounter.incrementAndGet();
088
089        //only process if groupSize is set...otherwise we're in groupInterval mode
090        if (groupSize != null) {
091            if (receivedCount % groupSize == 0) {
092                lastLogMessage = createLogMessage(exchange, receivedCount);
093                log.log(lastLogMessage);
094            }
095        }
096
097        callback.done(true);
098        return true;
099    }
100
101    public Integer getGroupSize() {
102        return groupSize;
103    }
104
105    public void setGroupSize(Integer groupSize) {
106        if (groupSize == null || groupSize <= 0) {
107            throw new IllegalArgumentException("groupSize must be positive, was: " + groupSize);
108        }
109        this.groupSize = groupSize;
110    }
111
112    public Long getGroupInterval() {
113        return groupInterval;
114    }
115
116    public void setGroupInterval(Long groupInterval) {
117        if (groupInterval == null || groupInterval <= 0) {
118            throw new IllegalArgumentException("groupInterval must be positive, was: " + groupInterval);
119        }
120        this.groupInterval = groupInterval;
121    }
122
123    public long getGroupDelay() {
124        return groupDelay;
125    }
126
127    public void setGroupDelay(long groupDelay) {
128        this.groupDelay = groupDelay;
129    }
130
131    public boolean getGroupActiveOnly() {
132        return groupActiveOnly;
133    }
134
135    private void setGroupActiveOnly(boolean groupActiveOnly) {
136        this.groupActiveOnly = groupActiveOnly;
137    }
138
139    public NumberFormat getNumberFormat() {
140        return numberFormat;
141    }
142
143    public void setNumberFormat(NumberFormat numberFormat) {
144        this.numberFormat = numberFormat;
145    }
146
147    public String getAction() {
148        return action;
149    }
150
151    public void setAction(String action) {
152        this.action = action;
153    }
154
155    public void reset() {
156        startTime = 0;
157        receivedCounter.set(0);
158        groupStartTime = 0;
159        groupReceivedCount = 0;
160        average = 0.0d;
161        rate = 0.0d;
162        lastLogMessage = null;
163    }
164
165    public double getRate() {
166        return rate;
167    }
168
169    public double getAverage() {
170        return average;
171    }
172
173    public int getReceivedCounter() {
174        return receivedCounter.get();
175    }
176
177    public String getLastLogMessage() {
178        return lastLogMessage;
179    }
180
181    @Override
182    public void doStart() throws Exception {
183        // if an interval was specified, create a background thread
184        if (groupInterval != null) {
185            ObjectHelper.notNull(camelContext, "CamelContext", this);
186
187            logSchedulerService = camelContext.getExecutorServiceManager().newScheduledThreadPool(this, "ThroughputLogger", 1);
188            Runnable scheduledLogTask = new ScheduledLogTask();
189            LOG.info("Scheduling throughput log to run every " + groupInterval + " millis.");
190            // must use fixed rate to have it trigger at every X interval
191            logSchedulerService.scheduleAtFixedRate(scheduledLogTask, groupDelay, groupInterval, TimeUnit.MILLISECONDS);
192        }
193    }
194
195    @Override
196    public void doStop() throws Exception {
197        if (logSchedulerService != null) {
198            camelContext.getExecutorServiceManager().shutdown(logSchedulerService);
199            logSchedulerService = null;
200        }
201    }
202
203    protected String createLogMessage(Exchange exchange, int receivedCount) {
204        long time = System.currentTimeMillis();
205        if (groupStartTime == 0) {
206            groupStartTime = startTime;
207        }
208
209        rate = messagesPerSecond(groupSize, groupStartTime, time);
210        average = messagesPerSecond(receivedCount, startTime, time);
211
212        long duration = time - groupStartTime;
213        groupStartTime = time;
214
215        return getAction() + ": " + receivedCount + " messages so far. Last group took: " + duration
216                + " millis which is: " + numberFormat.format(rate)
217                + " messages per second. average: " + numberFormat.format(average);
218    }
219
220    /**
221     * Background task that logs throughput stats.
222     */
223    private final class ScheduledLogTask implements Runnable {
224
225        public void run() {
226            // only run if CamelContext has been fully started
227            if (!camelContext.getStatus().isStarted()) {
228                LOG.trace("ThroughputLogger cannot start because CamelContext({}) has not been started yet", camelContext.getName());
229                return;
230            }
231
232            createGroupIntervalLogMessage();
233        }
234    }
235
236    protected void createGroupIntervalLogMessage() {
237        
238        // this indicates that no messages have been received yet...don't log yet
239        if (startTime == 0) {
240            return;
241        }
242        
243        int receivedCount = receivedCounter.get();
244
245        // if configured, hide log messages when no new messages have been received
246        if (groupActiveOnly && receivedCount == groupReceivedCount) {
247            return;
248        }
249
250        long time = System.currentTimeMillis();
251        if (groupStartTime == 0) {
252            groupStartTime = startTime;
253        }
254
255        long duration = time - groupStartTime;
256        long currentCount = receivedCount - groupReceivedCount;
257        rate = messagesPerSecond(currentCount, groupStartTime, time);
258        average = messagesPerSecond(receivedCount, startTime, time);
259
260        groupStartTime = time;
261        groupReceivedCount = receivedCount;
262
263        lastLogMessage = getAction() + ": " + currentCount + " new messages, with total " + receivedCount + " so far. Last group took: " + duration
264                + " millis which is: " + numberFormat.format(rate)
265                + " messages per second. average: " + numberFormat.format(average);
266        log.log(lastLogMessage);
267    }
268
269    protected double messagesPerSecond(long messageCount, long startTime, long endTime) {
270        // timeOneMessage = elapsed / messageCount
271        // messagePerSend = 1000 / timeOneMessage
272        double rate = messageCount * 1000.0;
273        rate /= endTime - startTime;
274        return rate;
275    }
276
277}