7

I developed a web application following the technology.

  1. Spring boot(undertow starter) : 1.4.2
  2. Java 7
  3. OS : Centos
  4. Servlet Filter : org.spring.web.filter.OncePerRequestFilter

in step 4 the filter is used to print http request/response info log. This data includes :

  • (a)http url
  • (b)Request body
  • (c)Response Body
  • (d)Response time.

Problem arised with (d) response time. However, Most of the response time is ok. But for few http request and respone i found log with negative response time(e.g -1024ms).

Here i calculated the http response time manually inside Servlet Filter

protected void doFilterInternal(...){

  long startTime = System.currentTimeMillis();
  ..
  some code
  filterChain.doFilter(httpRequest,httpResonse);
  ...
  long endTime = System.currentTimeMillis();
  long responseTime = endTime  - startTime
  log.debug(responseTIme); [SLF4J logger,logback.xml]

}
Nishan Norun Nobi
  • 71
  • 5
  • 1
    Does the code sample you posted differ in any way from the _actual_ code doing the calculation? Specifically, are `startTime` and `endTime` member variables in the "real" code, instead of locals? Is the host real hardware or a virtual machine? Is it running an NTP daemon that is syncing to an external time server? In theory the clock should never jump backwards, but ntpd is capable of a discontinuous time jump (as opposed to adjusting clock frequency) if it gets convinced it really needs to. – Jim Garrison Jul 31 '18 at 05:32
  • Check the ntpd log for time discontinuities and if you find any, see if they match log entries with negative response times. – Jim Garrison Jul 31 '18 at 05:34
  • Thanks @JimGarrison for quick response. Answer to the some of your queries (1). its actual code (2). Running in production server with real hardware. (3). startTime and endTime are local variable. not member variable. (4). about NTP deamon. I will be checking, will try to response soon. Nevertheless, Why this time jump occurs? Its kind of wired and i am still confused. – Nishan Norun Nobi Jul 31 '18 at 05:44
  • "This discussion might help you [basic links]https://stackoverflow.com/questions/12921034/calculating-response-time-in-java-filter"- Simmant. This url is not helpful in this context. My issue is related to backward time jump problem of application's system environment. Thanks @Simmant – Nishan Norun Nobi Jul 31 '18 at 06:20
  • use System.nanoTime() instead of System.currentTimeMillis(). Reason is here https://stackoverflow.com/questions/1770010/how-do-i-measure-time-elapsed-in-java – flopcoder Jul 31 '18 at 08:12
  • thanks @flopcoder, it worked fine with System.nanotime – Nishan Norun Nobi Aug 06 '18 at 08:00

1 Answers1

0

I used StopWatch api of google guava library, that use System.nanoTime() , java time api.

https://github.com/google/guava/blob/master/guava/src/com/google/common/base/Stopwatch.java

import com.google.common.base.Stopwatch;
import java.util.concurrent.TimeUnit;


Stopwatch stopwatch = new Stopwatch();
stopwatch.start();

... 
do some code
....

stopwatch.stop();
long value = stopwatch.elapsedTime(TimeUnit.MICROSECONDS);

It helps me to solve the problem

Thanks @flopcodder @Jim Garrison

Nishan Norun Nobi
  • 71
  • 5