Forum Discussion

garethshackel's avatar
garethshackel
New Contributor
14 years ago

nanoseconds and milliseconds timing results different?

Hi

I have a very confusing issue with SOAP UI. The SOAP UI result time is wrong on my computer - its returning results that are clearly not accurate. I believe the cause is that the System.nanoTime() function is not returning the correct results. The System.currentTimeMillis() is returning the correct results though which is very wierd.

I have written the following groovy script to illustrate the problem:

import com.eviware.soapui.impl.wsdl.testcase.WsdlTestCaseRunner
import java.util.date.*

def time1
def time1n
def time2
def time2n

def testcase = testRunner.testCase.testSuite.project.testSuites["WSExport_PropertySearch_PropertyServiceHttpBinding TestSuite"].getTestCaseByName("Pre_Prod: QueryPropertySummaryByPropertyAddress_5_4")
WsdlTestCaseRunner runner1 = new WsdlTestCaseRunner(testcase, null)

time1 = System.currentTimeMillis()
time1n = System.nanoTime()
testresult = runner1.runTestStepByName("300 Queen Street")
time2n = System.nanoTime()
time2 = System.currentTimeMillis()

log.info "finished request"
log.info "time taken according to soapui:" + testresult.getTimeTaken()
log.info "time taken according to clock: (ms)" + ((time2 - time1))
log.info "time taken according to clock (ns):" + ((time2n - time1n)/1000000)

Results:
Tue Mar 29 14:06:33 NZDT 2011:INFO:finished request
Tue Mar 29 14:06:33 NZDT 2011:INFO:time taken according to soapui:12122
Tue Mar 29 14:06:33 NZDT 2011:INFO:time taken according to clock: (ms)60536
Tue Mar 29 14:06:33 NZDT 2011:INFO:time taken according to clock (ns):12122.346868

From the example above results the millisecond time recorded was accurate. I am running soapUI 3.6.1 and its using the 1.6.0_21 JRE.

Does anyone have any idea what is causing this problem?
  • billneff's avatar
    billneff
    New Contributor
    14 years ago
    Re: nanoseconds and milliseconds timing results different?

    Postby billneff » 05 Jan 2012 17:13
    I'm having a similar issue. I have other external tools measuring the response time (Introscope as well as some database inserts) of an http soap request, and the response time reported by soapUI isn't even close, relatively speaking, to the response time reported by Introscope and the database records, which are consistently similar to each other.

    For example, we have the following setup: soapUI makes the http request to the server. When the request hits the server Introscope starts its timer. The application picks up the message and a timestamped database record is written after the objects are deserialized. The message is processed by the application, another timestamped record is written to the database, the response is serialized, Introscope stops its timer, soapUI receives the message. So the timing should look something like this: (soapUI start (Introscope start (database start, database stop) Introscope stop) soapUI stop). If each measurement was accurate you would expect the database time delta to be a little less than Introscope, which should be a little less than soapUI. In reality, I got the following, in one real world example:

    database: 1523 ms
    Introscope: 1794 ms
    soapUI: 666 ms

    The soapUI duration, which should be the longest, was half as short as the others.

    Given this, I can't effectively use soapUI to test the SLA of my services for even one request, let alone under a load. I've tried this in both soapUI 3.6.1 and soapUI 4.0.1.

    FYI - I cross posted this on the soapUI Bugs forum.