rukiman
asked on
System.currentTimeMillis() not giving correct results when measuring network latency
Here is a fragment of my code:
// POP server logon code here
for(i=0;i<10;i++)
{
startTimer = System.currentTimeMillis() ;
os.write("list\r\n".getByt es()); // send LIST command to POP server
bytesRead = is.read(inputBuffer, 0, bufferSize); // read data sent from POP server
stopTimer = System.currentTimeMillis() ;
}
I am basically try to measure the amount of time it takes to do a LIST and for the server to return the result. The first time the loop runs, I get a reasonable time difference (stopTimer - startTimer) about 150ms. However for all the other 9 loops I get 0.
Why is this the case?
// POP server logon code here
for(i=0;i<10;i++)
{
startTimer = System.currentTimeMillis()
os.write("list\r\n".getByt
bytesRead = is.read(inputBuffer, 0, bufferSize); // read data sent from POP server
stopTimer = System.currentTimeMillis()
}
I am basically try to measure the amount of time it takes to do a LIST and for the server to return the result. The first time the loop runs, I get a reasonable time difference (stopTimer - startTimer) about 150ms. However for all the other 9 loops I get 0.
Why is this the case?
> startTimer = System.currentTimeMillis() ;
> os.write("list\r\n".getByt es()); // send LIST command to POP server
> bytesRead = is.read(inputBuffer, 0, bufferSize); // read data sent
> from POP server
> stopTimer = System.currentTimeMillis() ;
If there is any error, you might get false numbers. Try changing the code to:
startTimer = System.currentTimeMillis() ;
try {
os.write("list\r\n".getByt es()); // send LIST command to POP server
bytesRead = is.read(inputBuffer, 0, bufferSize); // read data sent from POP server
}finally{
stopTimer = System.currentTimeMillis() ;
}
> os.write("list\r\n".getByt
> bytesRead = is.read(inputBuffer, 0, bufferSize); // read data sent
> from POP server
> stopTimer = System.currentTimeMillis()
If there is any error, you might get false numbers. Try changing the code to:
startTimer = System.currentTimeMillis()
try {
os.write("list\r\n".getByt
bytesRead = is.read(inputBuffer, 0, bufferSize); // read data sent from POP server
}finally{
stopTimer = System.currentTimeMillis()
}
where you are calculating "stopTimer - startTimer"?
it should be immdtly after you get stopTimer or before you get startTimer!
it should be immdtly after you get stopTimer or before you get startTimer!
Perhaps the first time it tries to write to the output-stream/ read from the input-stream it takes some time, and thereafter it manages to do it faster - I don't see this as an issue. The result you are getting is probably correct in the milli-second range.
rukiman,
> Why is this the case?
Maybe the compiler optimizes some part of the byte code with a JIT compiler and it makes it run faster.
> Why is this the case?
Maybe the compiler optimizes some part of the byte code with a JIT compiler and it makes it run faster.
ASKER CERTIFIED SOLUTION
membership
This solution is only available to members.
To access this solution, you must be a member of Experts Exchange.
Try changing that to
os.write("list\r\n".getByt es()); // send LIST command to POP server
os.flush();
os.write("list\r\n".getByt
os.flush();
Option 1. It could be that the server you are connecting to caches the information. So, the first time around, it has to go and find the info before returning it taking 150ms.
Subsequently, it already has the information and can simply return it which is much quicker. Zero is surprising though.
Option 2. It could be that the server has closed the socket. So, when you do bytesRead = is.read(inputBuffer, 0, bufferSize); what is the value of bytesRead? It could be -1 indicating that end of file has been reached.
You should always check for this.
In either case, you are not comparing like with like (i.e. the first request differes from subsequent). The loop needs to go around the outer code that establishes the connection and gets the streams.
Subsequently, it already has the information and can simply return it which is much quicker. Zero is surprising though.
Option 2. It could be that the server has closed the socket. So, when you do bytesRead = is.read(inputBuffer, 0, bufferSize); what is the value of bytesRead? It could be -1 indicating that end of file has been reached.
You should always check for this.
In either case, you are not comparing like with like (i.e. the first request differes from subsequent). The loop needs to go around the outer code that establishes the connection and gets the streams.
startTimer and stopTimer must be "long" not "integer"
ASKER
I found the problem....it was because I was out of sync and there was data already buffered to be read. I forgot that the server returned a response when I first connect to it and I wasn't reading this data.
If the call takes less time than its accurate to then it could well show 0