Measuring Time in Multi-threaded Application Using "System.currentTimeMillis()"

[Bon Truong]

Hello,

Recently, I have found out an interesting problem in measuring the time in a multi-threaded application. What the application does is that it creates multiple threads each of which performs HTTP POST a constant number of times. The problem is that each of the threads reports the average time that increases from one thread to another. This problem does not exist with one thread in which the average time is measured. I have observed this problem with JDK v1.4.2 and JDK v1.5.0 on MS Windows 2000. I have not had any chance to run the same code on other operating systems, i.e. Linux or AIX. For some reason, "System.currentTimeMillis()" does not seem to work correctly on MS Windows 2000.

Has anyone of you ever observed this behavior on MS Windows 2000 before? If yes, is there a solution/work-around for this problem?

BTW, attached is the source code of the custom thread below.

Thanks

Regards

Bon

========================================================================


import org.apache.commons.httpclient.HttpClient;
import org.apache.commons.httpclient.methods.InputStreamRequestEntity;
import org.apache.commons.httpclient.methods.PostMethod;
import org.apache.commons.httpclient.methods.StringRequestEntity;
import org.apache.commons.httpclient.Header;

public class Worker extends Thread
{
private String soapMessage = null;
private int numberOfInvocations = 0;
private int thinkTime = 0;
private double totalTime = 0;
private String errorMessage = null;
private String soapAction = null;
private String url = null;
private HttpClient httpClient = null;
private PostMethod postMethod = null;

public HttpClientThreadWorker(String soapMessage, int numberOfInvocations, int thinkTime, String soapAction, String url)
{
this.soapMessage = soapMessage;
this.numberOfInvocations = numberOfInvocations;
this.thinkTime = thinkTime;
this.soapAction = soapAction;
this.url = url;
}

public void run()
{
int result = -1;
totalTime = 0;

try
{
httpClient = new HttpClient();
postMethod = new PostMethod(url);

if(soapAction != null)
{
postMethod.setRequestHeader(new Header("SOAPAction", soapAction));
}

postMethod.setRequestEntity(new StringRequestEntity(soapMessage));
postMethod.setRequestHeader("Content-type", "text/xml; charset=ISO-8859-1");

long startTime = System.currentTimeMillis();

for(int i = 0; i < numberOfInvocations; i++)
{
result = httpClient.executeMethod(postMethod);
if(thinkTime > 0)
{
sleep(((long)thinkTime * 1000));
}
}

long endTime = System.currentTimeMillis();
totalTime = (double)(endTime - startTime);
System.out.println("Total time per thread (s): " + (totalTime/(double)1000));
System.out.println("Average time per invocation (s): " + totalTime/((double)1000 * numberOfInvocations));
}
catch(Exception ex)
{
ex.printStackTrace();
errorMessage = ex.toString();
}
finally
{
if(postMethod != null)
{
postMethod.releaseConnection();
postMethod = null;
}
httpClient = null;
}

}

/**
*
*This method retuns the total time.
*
*@return the total time
*/
public double getTotalTime()
{
return totalTime;
}

/**
*
*This method retuns the error message.
*
*@return the error message
*/
public String getErrorMessage()
{
return errorMessage;
}
}

[Ken Blair]

Originally posted by Bon Truong:
The problem is that each of the threads reports the average time that increases from one thread to another. This problem does not exist with one thread in which the average time is measured.

I don't understand what the problem is. How is it reporting time incorrectly? It's going to increase as you spawn more Threads because there's more competition for the resources. You do understand that 10 Threads on one processor can't do more work than 1 Thread on one processor unless there's a resource bottleneck (such as I/O) somewhere right?

[Scott Selikoff]

Originally posted by Bon Truong:
Hello,
The problem is that each of the threads reports the average time that increases from one thread to another. This problem does not exist with one thread in which the average time is measured.

There's absolutely nothing to guarentee which thread will get executed when, so one thread may take the CPU for a huge chunk of time and block all other threads or they could constantly switch back and forth between threads. The CPU scheduler will *TRY* to balance time between threads especially if the thread does not need the CPU, but the behavior can be extremely unpredictable especially in java threads, since there are JVM issues as well.