Forum Discussion

sbeauvais's avatar
sbeauvais
Contributor
11 years ago

[Reg] schema load affects first request SLA

Hello.

I am using SoapUI Pro 4.6.4 and have some testsuites running through "SoapUI Pro 4.6.2 Maven2 TestCase Runner". (This reproduces with the 4.6.4 plugin.)

I noticed that the Response SLA for the first testcase that runs in every project/testsuite is excessive (500 to 1500ms higher than expected).

Looking at the execution log, I see a bunch of "[SchemaUtils] Added default schema from file..." log items between the request/response and the assertions of the first testcase. See attached file.

I suspect that these schema loads are affecting the calculation of the Response SLA. I would consider this a bug. Is there a way to work around this?

Currently I have to artificially increase the expected SLA for the first testcase, which is not acceptable.

Please let me know if I am doing something wrong, or how to work around this.

Sincerely,
Severin Beauvais

18 Replies

Show More
  • SmartBear_Suppo's avatar
    SmartBear_Suppo
    Icon for Alumni rankAlumni
    11 years ago
    Hi,

    A few things I've noticed looking at your testrunner.txt file.

    1. Extra logging going such as DEBUG statements. Do you have some extra log setting turned on?
    2. You are using a maintenance build which could have some unforseen change in it. Can you try with SoapUI Pro 4.6.4 version and see if "[SchemaUtils] Added default schema from" doesn't appear ?
    3. Please check your File -> Preferences -> WSDL Settings. Attached is a screen shot of what mine looks like, and I don't get the default s"added default schema " messages in the log file.



    Regards,
    Marcus
    SmartBear Support
  • sbeauvais's avatar
    sbeauvais
    Contributor
    11 years ago
    Hello,

    Thanks for the help.

    1. I don't think I have configured extra logging... How can I check?

    2. The attachment in my original post shows logging using 4.6.2 (released, not maintenance). I have also reinstalled 4.6.4 Pro and tried again. See attachment. The problem is still there.

    3. Here is the screenshot for my WSDL Settings page. It's almost the same as yours.




    SB
  • sbeauvais's avatar
    sbeauvais
    Contributor
    11 years ago
    I created a new workspace and a new project.

    I loaded the WSDL and created a new testsuite and testcase.

    I saved everything.

    I ran the the tests from the command-line. The results are identical to before:

    SoapUI Pro 4.6.4 TestCase Runner
    Configuring log4j from [C:\Program Files\SmartBear\SoapUI-Pro-4.6.4\bin\soapui-log4j.xml]
    13:01:26,640 INFO [DefaultSoapUICore] initialized soapui-settings from [h:\pcss-testing\soapui-settings.xml]
    13:01:27,030 INFO [SoapUIProGroovyScriptEngineFactory] Setting Script Library to [C:\Program Files\SmartBear\SoapUI-Pro-4.6.4\bin\scripts]
    13:01:27,030 INFO [DefaultSoapUICore] Adding listeners from [C:\Program Files\SmartBear\SoapUI-Pro-4.6.4\bin\listeners\demo-listeners.xml]
    13:01:28,842 INFO [WsdlProject] Loaded project from [file:/h:/pcss-testing/new-soapui-project.xml]
    13:01:29,342 INFO [SoapUIProTestCaseRunner] Running SoapUI tests in project [new]
    13:01:29,342 INFO [SoapUIProTestCaseRunner] Running Project [new], runType = SEQUENTIAL
    13:01:29,358 INFO [SoapUIProTestCaseRunner] Running SoapUI testcase [GetAppearanceCivil]
    13:01:29,374 INFO [SoapUIProTestCaseRunner] running step [Request 1]
    13:01:30,311 DEBUG [HttpClientSupport$SoapUIHttpClient] Attempt 1 to execute request
    13:01:30,327 DEBUG [SoapUIMultiThreadedHttpConnectionManager$SoapUIDefaultClientConnection] Sending request: POST /courts/pcssCivil HTTP/1.1
    13:01:30,795 DEBUG [SoapUIMultiThreadedHttpConnectionManager$SoapUIDefaultClientConnection] Receiving response: HTTP/1.1 200 OK
    13:01:30,811 DEBUG [HttpClientSupport$SoapUIHttpClient] Connection can be kept alive indefinitely
    Progress: 1 - Loading Definition from cache
    13:01:30,998 DEBUG [AbstractDefinitionContext] Loading Definition...
    13:01:31,014 DEBUG [WsdlInterfaceDefinition] Loading WSDL: file:\H:\pcss-testing\PCSS%20Civil\PCSSCivil.wsdl
    13:01:31,014 DEBUG [AbstractWsdlDefinitionLoader] Returning baseInputSource [file:\H:\pcss-testing\PCSS%20Civil\PCSSCivil.wsdl]
    Retrieving document at 'file:\H:\pcss-testing\PCSS%20Civil\PCSSCivil.wsdl'.
    13:01:31,623 INFO [SchemaUtils] Added default schema from file:/C:/Program%20Files/SmartBear/SoapUI-Pro-4.6.4/lib/soapui-4.6.4.jar!/com/eviware/soapui/resources/xsds/xop.xsd with targetNamespace http://www.w3.org/2004/08/xop/include
    13:01:31,670 INFO [SchemaUtils] Added default schema from file:/C:/Program%20Files/SmartBear/SoapUI-Pro-4.6.4/lib/soapui-4.6.4.jar!/com/eviware/soapui/resources/xsds/XMLSchema.xsd with targetNamespace http://www.w3.org/2001/XMLSchema
    13:01:31,764 INFO [SchemaUtils] Added default schema from file:/C:/Program%20Files/SmartBear/SoapUI-Pro-4.6.4/lib/soapui-4.6.4.jar!/com/eviware/soapui/resources/xsds/xml.xsd with targetNamespace http://www.w3.org/XML/1998/namespace
    13:01:31,764 INFO [SchemaUtils] Added default schema from file:/C:/Program%20Files/SmartBear/SoapUI-Pro-4.6.4/lib/soapui-4.6.4.jar!/com/eviware/soapui/resources/xsds/swaref.xsd with targetNamespace http://ws-i.org/profiles/basic/1.1/xsd
    13:01:31,764 INFO [SchemaUtils] Added default schema from file:/C:/Program%20Files/SmartBear/SoapUI-Pro-4.6.4/lib/soapui-4.6.4.jar!/com/eviware/soapui/resources/xsds/xmime200505.xsd with targetNamespace http://www.w3.org/2005/05/xmlmime
    13:01:31,779 INFO [SchemaUtils] Added default schema from file:/C:/Program%20Files/SmartBear/SoapUI-Pro-4.6.4/lib/soapui-4.6.4.jar!/com/eviware/soapui/resources/xsds/xmime200411.xsd with targetNamespace http://www.w3.org/2004/11/xmlmime
    13:01:31,779 INFO [SchemaUtils] Added default schema from file:/C:/Program%20Files/SmartBear/SoapUI-Pro-4.6.4/lib/soapui-4.6.4.jar!/com/eviware/soapui/resources/xsds/soapEnvelope.xsd with targetNamespace http://schemas.xmlsoap.org/soap/envelope/
    13:01:31,795 INFO [SchemaUtils] Added default schema from file:/C:/Program%20Files/SmartBear/SoapUI-Pro-4.6.4/lib/soapui-4.6.4.jar!/com/eviware/soapui/resources/xsds/soapEncoding.xsd with targetNamespace http://schemas.xmlsoap.org/soap/encoding/
    13:01:31,795 INFO [SchemaUtils] Added default schema from file:/C:/Program%20Files/SmartBear/SoapUI-Pro-4.6.4/lib/soapui-4.6.4.jar!/com/eviware/soapui/resources/xsds/soapEnvelope12.xsd with targetNamespace http://www.w3.org/2003/05/soap-envelope
    13:01:31,795 INFO [SchemaUtils] Added default schema from file:/C:/Program%20Files/SmartBear/SoapUI-Pro-4.6.4/lib/soapui-4.6.4.jar!/com/eviware/soapui/resources/xsds/soapEncoding12.xsd with targetNamespace http://www.w3.org/2003/05/soap-encoding
    13:01:31,811 INFO [SchemaUtils] Loading schema types from [file:\H:\pcss-testing\PCSS%20Civil\PCSSCivil.wsdl]
    13:01:31,811 INFO [SchemaUtils] Getting schema file:\H:\pcss-testing\PCSS%20Civil\PCSSCivil.wsdl
    13:01:32,420 DEBUG [AbstractDefinitionContext] Loaded Definition: ok
    13:01:32,467 INFO [SoapUIProTestCaseRunner] Assertion [SOAP Response] has status VALID
    13:01:32,467 INFO [SoapUIProTestCaseRunner] Assertion [Schema Compliance] has status VALID
    13:01:32,467 INFO [SoapUIProTestCaseRunner] Assertion [Not SOAP Fault] has status VALID
    13:01:32,467 INFO [SoapUIProTestCaseRunner] Assertion [Response SLA] has status FAILED
    13:01:32,467 ERROR [SoapUIProTestCaseRunner] ASSERTION FAILED -> Response did not meet SLA 1360/1000
    13:01:32,482 ERROR [SoapUIProTestCaseRunner] Request 1 failed, exporting to [h:\pcss-testing\TestSuite-GetAppearanceCivil-Request_1-0-FAILED.txt]
    13:01:32,498 INFO [SoapUIProTestCaseRunner] Finished running SoapUI testcase [GetAppearanceCivil], time taken: 3083ms, status: FAILED
    13:01:32,498 INFO [SoapUIProTestCaseRunner] Project [new] finished with status [FAILED] in 3156ms


    Normally, that first request takes ~500 ms to return.

    SB
  • sbeauvais's avatar
    sbeauvais
    Contributor
    11 years ago
    SmartBear Support wrote:
    Hi,

    Are you able to share your project, so I can try locally?

    Regards,
    Marcus
    SmartBear Support


    Sent to you by email (Case #00026762).
  • SmartBear_Suppo's avatar
    SmartBear_Suppo
    Icon for Alumni rankAlumni
    11 years ago
    Hi,

    Thanks for the project file. We have managed to reproduce the behavior of the first request being slower, although the delay is smaller than what you seem to be experiencing. We get a delay of about 60 ms for the first request.

    From what we can see when trying to figure out the root cause is not the loading of the schema, but rather some internal HttpClient code. A workaround you could try is to add a dummy HTTP Test Request as the first step of your test case just to circumvent extra time being added to the first real request.

    We have a logged an issue (SOAP-1576) in our internal bug tracking system for figuring out what is actually causing this and fixing this. Thank you for reporting this issue.

    Regards
    Joel Jonsson
    SmartBear Sweden
  • sbeauvais's avatar
    sbeauvais
    Contributor
    11 years ago
    I guess the delay must depend on how complex the WSDL is.

    This may be the same root cause: when I load a project in SoapUI (app) and first open a request, a "Loading Definitions" popup window displays for a second or 2 before the request tab actually displays. This is unexpected since the WSDL is embedded in the project file...


    SB
  • sbeauvais's avatar
    sbeauvais
    Contributor
    11 years ago
    sbeauvais wrote:
    This may be the same root cause: when I load a project in SoapUI (app) and first open a request, a "Loading Definitions" popup window displays for a second or 2 before the request tab actually displays. This is unexpected since the WSDL is embedded in the project file...


    Small correction: it appears that the WSDL is "loaded from cache"... no WSDL is required on disk; the WSDL embedded in the project file is sufficient to load/run the project.

    However, it still takes a few seconds to load the cached WSDL when the request is first opened...

    SB