View Javadoc
1   //
2   //  ========================================================================
3   //  Copyright (c) 1995-2016 Mort Bay Consulting Pty. Ltd.
4   //  ------------------------------------------------------------------------
5   //  All rights reserved. This program and the accompanying materials
6   //  are made available under the terms of the Eclipse Public License v1.0
7   //  and Apache License v2.0 which accompanies this distribution.
8   //
9   //      The Eclipse Public License is available at
10  //      http://www.eclipse.org/legal/epl-v10.html
11  //
12  //      The Apache License v2.0 is available at
13  //      http://www.opensource.org/licenses/apache2.0.php
14  //
15  //  You may elect to redistribute this code under either of these licenses.
16  //  ========================================================================
17  //
18  
19  package org.eclipse.jetty.server.handler;
20  
21  import java.io.IOException;
22  import java.util.concurrent.Future;
23  import java.util.concurrent.TimeoutException;
24  import java.util.concurrent.atomic.AtomicBoolean;
25  import java.util.concurrent.atomic.AtomicLong;
26  import java.util.concurrent.atomic.AtomicReference;
27  import java.util.concurrent.atomic.LongAdder;
28  
29  import javax.servlet.AsyncEvent;
30  import javax.servlet.AsyncListener;
31  import javax.servlet.ServletException;
32  import javax.servlet.http.HttpServletRequest;
33  import javax.servlet.http.HttpServletResponse;
34  
35  import org.eclipse.jetty.http.HttpStatus;
36  import org.eclipse.jetty.server.AsyncContextEvent;
37  import org.eclipse.jetty.server.Handler;
38  import org.eclipse.jetty.server.HttpChannelState;
39  import org.eclipse.jetty.server.Request;
40  import org.eclipse.jetty.server.Response;
41  import org.eclipse.jetty.util.FutureCallback;
42  import org.eclipse.jetty.util.annotation.ManagedAttribute;
43  import org.eclipse.jetty.util.annotation.ManagedObject;
44  import org.eclipse.jetty.util.annotation.ManagedOperation;
45  import org.eclipse.jetty.util.component.Graceful;
46  import org.eclipse.jetty.util.log.Log;
47  import org.eclipse.jetty.util.log.Logger;
48  import org.eclipse.jetty.util.statistic.CounterStatistic;
49  import org.eclipse.jetty.util.statistic.SampleStatistic;
50  
51  @ManagedObject("Request Statistics Gathering")
52  public class StatisticsHandler extends HandlerWrapper implements Graceful
53  {
54      private static final Logger LOG = Log.getLogger(StatisticsHandler.class);
55      private final AtomicLong _statsStartedAt = new AtomicLong();
56  
57      private final CounterStatistic _requestStats = new CounterStatistic();
58      private final SampleStatistic _requestTimeStats = new SampleStatistic();
59      private final CounterStatistic _dispatchedStats = new CounterStatistic();
60      private final SampleStatistic _dispatchedTimeStats = new SampleStatistic();
61      private final CounterStatistic _asyncWaitStats = new CounterStatistic();
62  
63      private final LongAdder _asyncDispatches = new LongAdder();
64      private final LongAdder _expires = new LongAdder();
65  
66      private final LongAdder _responses1xx = new LongAdder();
67      private final LongAdder _responses2xx = new LongAdder();
68      private final LongAdder _responses3xx = new LongAdder();
69      private final LongAdder _responses4xx = new LongAdder();
70      private final LongAdder _responses5xx = new LongAdder();
71      private final LongAdder _responsesTotalBytes = new LongAdder();
72  
73      private final AtomicReference<FutureCallback> _shutdown=new AtomicReference<>();
74      
75      private final AtomicBoolean _wrapWarning = new AtomicBoolean();
76      
77      private final AsyncListener _onCompletion = new AsyncListener()
78      {
79          @Override
80          public void onTimeout(AsyncEvent event) throws IOException
81          {
82              _expires.increment();
83          }
84          
85          @Override
86          public void onStartAsync(AsyncEvent event) throws IOException
87          {
88              event.getAsyncContext().addListener(this);
89          }
90          
91          @Override
92          public void onError(AsyncEvent event) throws IOException
93          {
94          }
95  
96          @Override
97          public void onComplete(AsyncEvent event) throws IOException
98          {
99              HttpChannelState state = ((AsyncContextEvent)event).getHttpChannelState();
100 
101             Request request = state.getBaseRequest();
102             final long elapsed = System.currentTimeMillis()-request.getTimeStamp();
103 
104             long d=_requestStats.decrement();
105             _requestTimeStats.set(elapsed);
106 
107             updateResponse(request);
108 
109             _asyncWaitStats.decrement();
110             
111             // If we have no more dispatches, should we signal shutdown?
112             if (d==0)
113             {
114                 FutureCallback shutdown = _shutdown.get();
115                 if (shutdown!=null)
116                     shutdown.succeeded();
117             }   
118         }
119     };
120 
121     /**
122      * Resets the current request statistics.
123      */
124     @ManagedOperation(value="resets statistics", impact="ACTION")
125     public void statsReset()
126     {
127         _statsStartedAt.set(System.currentTimeMillis());
128 
129         _requestStats.reset();
130         _requestTimeStats.reset();
131         _dispatchedStats.reset();
132         _dispatchedTimeStats.reset();
133         _asyncWaitStats.reset();
134 
135         _asyncDispatches.reset();
136         _expires.reset();
137         _responses1xx.reset();
138         _responses2xx.reset();
139         _responses3xx.reset();
140         _responses4xx.reset();
141         _responses5xx.reset();
142         _responsesTotalBytes.reset();
143     }
144 
145     @Override
146     public void handle(String path, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException
147     {
148         _dispatchedStats.increment();
149 
150         final long start;
151         HttpChannelState state = baseRequest.getHttpChannelState();
152         if (state.isInitial())
153         {
154             // new request
155             _requestStats.increment();
156             start = baseRequest.getTimeStamp();
157         }
158         else
159         {
160             // resumed request
161             start = System.currentTimeMillis();
162             _asyncDispatches.increment();
163         }
164 
165         try
166         {
167             Handler handler = getHandler();
168             if (handler!=null && _shutdown.get()==null && isStarted())
169                 handler.handle(path, baseRequest, request, response);
170             else if (baseRequest.isHandled())
171             {
172                 if (_wrapWarning.compareAndSet(false,true))
173                     LOG.warn("Bad statistics configuration. Latencies will be incorrect in {}",this);
174             }
175             else
176             {
177                 baseRequest.setHandled(true);
178                 response.sendError(HttpStatus.SERVICE_UNAVAILABLE_503);
179             }
180         }
181         finally
182         {
183             final long now = System.currentTimeMillis();
184             final long dispatched=now-start;
185 
186             _dispatchedStats.decrement();
187             _dispatchedTimeStats.set(dispatched);
188 
189             if (state.isSuspended())
190             {
191                 if (state.isInitial())
192                 {
193                     state.addListener(_onCompletion);
194                     _asyncWaitStats.increment();
195                 }
196             }
197             else if (state.isInitial())
198             {
199                 long d=_requestStats.decrement();
200                 _requestTimeStats.set(dispatched);
201                 updateResponse(baseRequest);
202                 
203                 // If we have no more dispatches, should we signal shutdown?
204                 FutureCallback shutdown = _shutdown.get();
205                 if (shutdown!=null)
206                 {
207                     response.flushBuffer();
208                     if (d==0)
209                         shutdown.succeeded();
210                 }   
211             }
212             // else onCompletion will handle it.
213         }
214     }
215 
216     protected void updateResponse(Request request)
217     {
218         Response response = request.getResponse();
219         if (request.isHandled())
220         {
221             switch (response.getStatus() / 100)
222             {
223                 case 1:
224                     _responses1xx.increment();
225                     break;
226                 case 2:
227                     _responses2xx.increment();
228                     break;
229                 case 3:
230                     _responses3xx.increment();
231                     break;
232                 case 4:
233                     _responses4xx.increment();
234                     break;
235                 case 5:
236                     _responses5xx.increment();
237                     break;
238                 default:
239                     break;
240             }
241         }
242         else
243             // will fall through to not found handler
244             _responses4xx.increment();
245         _responsesTotalBytes.add(response.getContentCount());
246     }
247 
248     @Override
249     protected void doStart() throws Exception
250     {
251         _shutdown.set(null);
252         super.doStart();
253         statsReset();
254     }
255     
256 
257     @Override
258     protected void doStop() throws Exception
259     {
260         super.doStop();
261         FutureCallback shutdown = _shutdown.get();
262         if (shutdown!=null && !shutdown.isDone())
263             shutdown.failed(new TimeoutException());
264     }
265 
266     /**
267      * @return the number of requests handled by this handler
268      * since {@link #statsReset()} was last called, excluding
269      * active requests
270      * @see #getAsyncDispatches()
271      */
272     @ManagedAttribute("number of requests")
273     public int getRequests()
274     {
275         return (int)_requestStats.getTotal();
276     }
277 
278     /**
279      * @return the number of requests currently active.
280      * since {@link #statsReset()} was last called.
281      */
282     @ManagedAttribute("number of requests currently active")
283     public int getRequestsActive()
284     {
285         return (int)_requestStats.getCurrent();
286     }
287 
288     /**
289      * @return the maximum number of active requests
290      * since {@link #statsReset()} was last called.
291      */
292     @ManagedAttribute("maximum number of active requests")
293     public int getRequestsActiveMax()
294     {
295         return (int)_requestStats.getMax();
296     }
297 
298     /**
299      * @return the maximum time (in milliseconds) of request handling
300      * since {@link #statsReset()} was last called.
301      */
302     @ManagedAttribute("maximum time spend handling requests (in ms)")
303     public long getRequestTimeMax()
304     {
305         return _requestTimeStats.getMax();
306     }
307 
308     /**
309      * @return the total time (in milliseconds) of requests handling
310      * since {@link #statsReset()} was last called.
311      */
312     @ManagedAttribute("total time spend in all request handling (in ms)")
313     public long getRequestTimeTotal()
314     {
315         return _requestTimeStats.getTotal();
316     }
317 
318     /**
319      * @return the mean time (in milliseconds) of request handling
320      * since {@link #statsReset()} was last called.
321      * @see #getRequestTimeTotal()
322      * @see #getRequests()
323      */
324     @ManagedAttribute("mean time spent handling requests (in ms)")
325     public double getRequestTimeMean()
326     {
327         return _requestTimeStats.getMean();
328     }
329 
330     /**
331      * @return the standard deviation of time (in milliseconds) of request handling
332      * since {@link #statsReset()} was last called.
333      * @see #getRequestTimeTotal()
334      * @see #getRequests()
335      */
336     @ManagedAttribute("standard deviation for request handling (in ms)")
337     public double getRequestTimeStdDev()
338     {
339         return _requestTimeStats.getStdDev();
340     }
341 
342     /**
343      * @return the number of dispatches seen by this handler
344      * since {@link #statsReset()} was last called, excluding
345      * active dispatches
346      */
347     @ManagedAttribute("number of dispatches")
348     public int getDispatched()
349     {
350         return (int)_dispatchedStats.getTotal();
351     }
352 
353     /**
354      * @return the number of dispatches currently in this handler
355      * since {@link #statsReset()} was last called, including
356      * resumed requests
357      */
358     @ManagedAttribute("number of dispatches currently active")
359     public int getDispatchedActive()
360     {
361         return (int)_dispatchedStats.getCurrent();
362     }
363 
364     /**
365      * @return the max number of dispatches currently in this handler
366      * since {@link #statsReset()} was last called, including
367      * resumed requests
368      */
369     @ManagedAttribute("maximum number of active dispatches being handled")
370     public int getDispatchedActiveMax()
371     {
372         return (int)_dispatchedStats.getMax();
373     }
374 
375     /**
376      * @return the maximum time (in milliseconds) of request dispatch
377      * since {@link #statsReset()} was last called.
378      */
379     @ManagedAttribute("maximum time spend in dispatch handling")
380     public long getDispatchedTimeMax()
381     {
382         return _dispatchedTimeStats.getMax();
383     }
384 
385     /**
386      * @return the total time (in milliseconds) of requests handling
387      * since {@link #statsReset()} was last called.
388      */
389     @ManagedAttribute("total time spent in dispatch handling (in ms)")
390     public long getDispatchedTimeTotal()
391     {
392         return _dispatchedTimeStats.getTotal();
393     }
394 
395     /**
396      * @return the mean time (in milliseconds) of request handling
397      * since {@link #statsReset()} was last called.
398      * @see #getRequestTimeTotal()
399      * @see #getRequests()
400      */
401     @ManagedAttribute("mean time spent in dispatch handling (in ms)")
402     public double getDispatchedTimeMean()
403     {
404         return _dispatchedTimeStats.getMean();
405     }
406 
407     /**
408      * @return the standard deviation of time (in milliseconds) of request handling
409      * since {@link #statsReset()} was last called.
410      * @see #getRequestTimeTotal()
411      * @see #getRequests()
412      */
413     @ManagedAttribute("standard deviation for dispatch handling (in ms)")
414     public double getDispatchedTimeStdDev()
415     {
416         return _dispatchedTimeStats.getStdDev();
417     }
418 
419     /**
420      * @return the number of requests handled by this handler
421      * since {@link #statsReset()} was last called, including
422      * resumed requests
423      * @see #getAsyncDispatches()
424      */
425     @ManagedAttribute("total number of async requests")
426     public int getAsyncRequests()
427     {
428         return (int)_asyncWaitStats.getTotal();
429     }
430 
431     /**
432      * @return the number of requests currently suspended.
433      * since {@link #statsReset()} was last called.
434      */
435     @ManagedAttribute("currently waiting async requests")
436     public int getAsyncRequestsWaiting()
437     {
438         return (int)_asyncWaitStats.getCurrent();
439     }
440 
441     /**
442      * @return the maximum number of current suspended requests
443      * since {@link #statsReset()} was last called.
444      */
445     @ManagedAttribute("maximum number of waiting async requests")
446     public int getAsyncRequestsWaitingMax()
447     {
448         return (int)_asyncWaitStats.getMax();
449     }
450 
451     /**
452      * @return the number of requests that have been asynchronously dispatched
453      */
454     @ManagedAttribute("number of requested that have been asynchronously dispatched")
455     public int getAsyncDispatches()
456     {
457         return _asyncDispatches.intValue();
458     }
459 
460     /**
461      * @return the number of requests that expired while suspended.
462      * @see #getAsyncDispatches()
463      */
464     @ManagedAttribute("number of async requests requests that have expired")
465     public int getExpires()
466     {
467         return _expires.intValue();
468     }
469 
470     /**
471      * @return the number of responses with a 1xx status returned by this context
472      * since {@link #statsReset()} was last called.
473      */
474     @ManagedAttribute("number of requests with 1xx response status")
475     public int getResponses1xx()
476     {
477         return _responses1xx.intValue();
478     }
479 
480     /**
481      * @return the number of responses with a 2xx status returned by this context
482      * since {@link #statsReset()} was last called.
483      */
484     @ManagedAttribute("number of requests with 2xx response status")
485     public int getResponses2xx()
486     {
487         return _responses2xx.intValue();
488     }
489 
490     /**
491      * @return the number of responses with a 3xx status returned by this context
492      * since {@link #statsReset()} was last called.
493      */
494     @ManagedAttribute("number of requests with 3xx response status")
495     public int getResponses3xx()
496     {
497         return _responses3xx.intValue();
498     }
499 
500     /**
501      * @return the number of responses with a 4xx status returned by this context
502      * since {@link #statsReset()} was last called.
503      */
504     @ManagedAttribute("number of requests with 4xx response status")
505     public int getResponses4xx()
506     {
507         return _responses4xx.intValue();
508     }
509 
510     /**
511      * @return the number of responses with a 5xx status returned by this context
512      * since {@link #statsReset()} was last called.
513      */
514     @ManagedAttribute("number of requests with 5xx response status")
515     public int getResponses5xx()
516     {
517         return _responses5xx.intValue();
518     }
519 
520     /**
521      * @return the milliseconds since the statistics were started with {@link #statsReset()}.
522      */
523     @ManagedAttribute("time in milliseconds stats have been collected for")
524     public long getStatsOnMs()
525     {
526         return System.currentTimeMillis() - _statsStartedAt.get();
527     }
528 
529     /**
530      * @return the total bytes of content sent in responses
531      */
532     @ManagedAttribute("total number of bytes across all responses")
533     public long getResponsesBytesTotal()
534     {
535         return _responsesTotalBytes.longValue();
536     }
537 
538     public String toStatsHTML()
539     {
540         StringBuilder sb = new StringBuilder();
541 
542         sb.append("<h1>Statistics:</h1>\n");
543         sb.append("Statistics gathering started ").append(getStatsOnMs()).append("ms ago").append("<br />\n");
544 
545         sb.append("<h2>Requests:</h2>\n");
546         sb.append("Total requests: ").append(getRequests()).append("<br />\n");
547         sb.append("Active requests: ").append(getRequestsActive()).append("<br />\n");
548         sb.append("Max active requests: ").append(getRequestsActiveMax()).append("<br />\n");
549         sb.append("Total requests time: ").append(getRequestTimeTotal()).append("<br />\n");
550         sb.append("Mean request time: ").append(getRequestTimeMean()).append("<br />\n");
551         sb.append("Max request time: ").append(getRequestTimeMax()).append("<br />\n");
552         sb.append("Request time standard deviation: ").append(getRequestTimeStdDev()).append("<br />\n");
553 
554 
555         sb.append("<h2>Dispatches:</h2>\n");
556         sb.append("Total dispatched: ").append(getDispatched()).append("<br />\n");
557         sb.append("Active dispatched: ").append(getDispatchedActive()).append("<br />\n");
558         sb.append("Max active dispatched: ").append(getDispatchedActiveMax()).append("<br />\n");
559         sb.append("Total dispatched time: ").append(getDispatchedTimeTotal()).append("<br />\n");
560         sb.append("Mean dispatched time: ").append(getDispatchedTimeMean()).append("<br />\n");
561         sb.append("Max dispatched time: ").append(getDispatchedTimeMax()).append("<br />\n");
562         sb.append("Dispatched time standard deviation: ").append(getDispatchedTimeStdDev()).append("<br />\n");
563 
564 
565         sb.append("Total requests suspended: ").append(getAsyncRequests()).append("<br />\n");
566         sb.append("Total requests expired: ").append(getExpires()).append("<br />\n");
567         sb.append("Total requests resumed: ").append(getAsyncDispatches()).append("<br />\n");
568 
569         sb.append("<h2>Responses:</h2>\n");
570         sb.append("1xx responses: ").append(getResponses1xx()).append("<br />\n");
571         sb.append("2xx responses: ").append(getResponses2xx()).append("<br />\n");
572         sb.append("3xx responses: ").append(getResponses3xx()).append("<br />\n");
573         sb.append("4xx responses: ").append(getResponses4xx()).append("<br />\n");
574         sb.append("5xx responses: ").append(getResponses5xx()).append("<br />\n");
575         sb.append("Bytes sent total: ").append(getResponsesBytesTotal()).append("<br />\n");
576 
577         return sb.toString();
578 
579     }
580 
581     @Override
582     public Future<Void> shutdown()
583     {
584         FutureCallback shutdown=new FutureCallback(false);
585         _shutdown.compareAndSet(null,shutdown);
586         shutdown=_shutdown.get();
587         if (_dispatchedStats.getCurrent()==0)
588             shutdown.succeeded();
589         return shutdown;
590     }
591 }