locked
Performance measurements - Initial delay RRS feed

  • Question

  • Hi,

     

    I have been doing some communication throughput tests on DSSP. I have observed some strange behaviour during the tests. The first few operations (1 to 3) involving update, Get, Query takes more time than the consecutive operations. My tests are designed as follows:-

    • Two Services on dofferent PCs. Service1 will issue requests (GET, UPDATE, QUERY) to Service2 and wait for response. After receiving the response Service1 will calculate elapsed time from the time it issued the request.
    • The Service2State is as follows

    Code Snippet

    Service2State

    {

    // Will contain 1000 Values & will be initialized

    //in the Service2 Constructor

    bool []_value;

    [DataMember]

    public []bool Value

    {

    //Getter and Setter

    }

    }

     

    • Service1 will start a stopWatch.Start()
    • Issue a GET request to Service2 and wait for response using Choice Arbiter
    • Stop the stopWatch and calculate stopWatch.ElapsedMiliSeconds as the Arbiter receives the response from the Service2.
    • Run the same operation in a loop for 100 times

    Following are the observations:

    • The first 1-3 GET takes huge time (~400ms) to GET the State , while the Next Successive GET takes very less time (~2 ms)
    • This behaviour is observed in UPDATE and QUERY as well.

    I guessed that the initial proxy loading was delaying the first few operations, however I tried to perform a GET operation after an UPDATE, this too leads similar behaviour i.e each operation (GET,UPDATE,QUERY) takes more time on the first call regardless of other calls being made already. This shows that initial proxy loading is not the cause of the problem.

     

    If anybody has any insight on what might be causing this initial delay, please let me know.

     

    Cheers

     

    Monday, April 21, 2008 4:15 AM

Answers

  • Hi, the way you measure time can be simplified. Using Stopwatch, just do this

     

    sw.Stop();

    Sw.Elapsed.TotalSeconds

     

    thats it it. TotalSeconds is a double that goes down to nanosecond accuracy.

     

    Now i cant explain the delay you see. DNS resolution (even on a local host) might take a few millisecond son the first request and TCP connection establishment a few more, but nothing even sloe to a second. Any request after that should be in the micro seconds and single millisecond range for large transfers.

     

    So we do expect the very first request to rake a bit longer, until the path "warms up" but it should not be in the order of a second, unless DNS resilution really takes that long in your system due to proxy configuration (do you have proxy disabled for local addresses? Do you use our dss host config file ot mae sure CLR bypasses proxy?) or due to multiple net interfaces.

     

    so right now i would look for DNS resolution related configuration

     

     

     

     

    Tuesday, May 6, 2008 10:53 PM

All replies

  • The issue is the time it takes the CLR to create the XML serializer assemblies for a type. So the first time a given type is request to be serialized, the delay will show up. Any time after that, its much faster.

     

    You will NOT see any delay if you use the TCP transport between two nodes and issue requests to the dssp.tcp URI of the service. Our binary serializers are pre-compiled.

     

    thanx

    g

    Tuesday, April 29, 2008 2:39 AM
  •  

    Thank you George for your reply.

     

    But, I am using TCP transport only. Because if I understand correct, current DSS implementation uses TCP as transport if you issue an DSSP GET and on the other node handle the message using DSSP GET handler. I have also check the same using Netmon (whether the data has been transferred using TCP, or it is a layer above, i.e http ).

     

    I am putting the main sections from the code, may be it will help,-

     

    Service2State:

     

    Code Snippet

    public class Service2State

    {

    private bool[] _boolValues;

     

    [DataMember]

    public int[] BoolValues

    {

    get { return _boolValues; }

    set { _boolValues = value; }

    }

    private int[] _intValues;

     

    [DataMember]

    public int[] IntValues

    {

    get { return _intValues; }

    set { _intValues = value; }

    }

    }

     

     

    Service2OperationPort (MainPort) :

     

    Code Snippet

    public class Service2Operations : PortSet<DsspDefaultLookup, DsspDefaultDrop,

    Get, QueryBool, QueryInt,UpdateBool, UpdateInt>

    {

    }

     

    public class QueryInt : Query<QueryRequestBodyInt, PortSet<FilteredStateQueryInt, Fault>>

    {

    public QueryInt(QueryRequestBodyInt body, PortSet<FilteredStateQueryInt, Fault> responseport)

    : base(body, responseport)

    {

    }

    public QueryInt(QueryRequestBodyInt body)

    : base(body)

    {

    }

    public QueryInt()

    {

    }

    }

     

    [DataContract]

    public class QueryRequestBodyInt

    {

    private int _num;

    [DataMember]

    public int TotalValues

    {

    get { return _num; }

    set { _num = value; }

    }

    }

     

     

     

    Service2 Handlers:

     

    Code Snippet

    [ServiceHandler(ServiceHandlerBehavior.Concurrent)]

    public IEnumerator<ITask> QueryHandlerInt(QueryInt query)

    {

    QueryRequestBodyInt request = query.Body;

    FilteredStateQueryInt fs = new FilteredStateQueryInt();

    fs.Data = new int[request.TotalValue];

    for (int i = 0; i

    {

    fs.Data[i]= _state.IntValues[i];

    }

    query.ResponsePort.Post(fs);

    yield break;

    }

     

    [DataContract] // Defined in ServiceTypes

    public class FilteredStateInt

    {

    private int[] _data;

     

    [DataMember]

    public int[] Data

    {

    get { return _data; }

    set { _data = value; }

    }

    }

     

    ------------------------------------------------------------------x--------------------x-------------------------------------------------------------------

    Now, In service1, which actually issues request from the Other Node and measures time, works as below,-

     

    Code Snippet

    private IEnumerator<ITask> ReadTimeTest()

    {

    s2.QueryRequestBodyInt body = new s2.QueryRequestBodyInt();

    populateQueryInt(NumberOfValues, body); // Tested from 1 -1000, specifies how many element to read

                          // On Service2, I have set it to fix 1000, so that i can choose

                          // from 1-1000 

    s2.FilteredStateQueryInt fs;

    Stopwatch sw = new Stopwatch();

    double elapsed =0;

    for (int counter =0; counter < 100; counter++)

    {

    fs = null;

    sw.Start();

    yield return Arbiter.Choice(

    _remotePort.QueryInt(body),

    delegate(rs2.FilteredStateQueryInt response)

    {

    sw.Stop();

    // Error Checking for Null State

    // If error exit or proced

    //

    if (sw.ElapsedMilliseconds == 0)

    {

    double elapsedMiliSecondInPrecision = ((double)(sw.ElapsedTicks * 1000L)) / Stopwatch.Frequency;

    elapsed =  elapsedMiliSecondInPrecision;

    }else

    {

    elapsed = sw.ElapsedMilliseconds ;

    }

    sw.Reset();

    },

    delegate(Fault fault)

    {

    LogError(null, "Unable to Query state from Service2", fault);

    }

    );

    }

    }

     

    Now, the issues are as follows:-

    1. The first few (1-3) requests takes more time than the Next Successive requests.
    2. The above case is true even if we issue GET request after a QUERY request.

    Am I missing something? Please need your help on this regard.

    Or the way i am Querying and calculating time is wrong (I do not feel so)?

    Monday, May 5, 2008 6:13 PM
  • Sorry, I forgot to mention the URI, i am using to access service2.

     

    It is as shown below and defined in the Service1 manifest file.

     

    Code Snippet

    <dssp:PartnerList>

    <dssp:Partner>

    <dssp:Service>dssp.tcp://machine_name:40001/service2</dssp:Service>

    <dssp:Name>rc:s2</dssp:Name>

    </dssp:Partner>

    </dssp:PartnerList>

     

     

    Also, the machine name is defined in the etc/host file and the network is quite (also static).

     

    Monday, May 5, 2008 6:20 PM
  • Hi, the way you measure time can be simplified. Using Stopwatch, just do this

     

    sw.Stop();

    Sw.Elapsed.TotalSeconds

     

    thats it it. TotalSeconds is a double that goes down to nanosecond accuracy.

     

    Now i cant explain the delay you see. DNS resolution (even on a local host) might take a few millisecond son the first request and TCP connection establishment a few more, but nothing even sloe to a second. Any request after that should be in the micro seconds and single millisecond range for large transfers.

     

    So we do expect the very first request to rake a bit longer, until the path "warms up" but it should not be in the order of a second, unless DNS resilution really takes that long in your system due to proxy configuration (do you have proxy disabled for local addresses? Do you use our dss host config file ot mae sure CLR bypasses proxy?) or due to multiple net interfaces.

     

    so right now i would look for DNS resolution related configuration

     

     

     

     

    Tuesday, May 6, 2008 10:53 PM
  • Thank you George for your reply.

    >> DNS resolution (even on a local host) might take a few millisecond son the first request and TCP connection >>establishment a few more, but nothing even sloe to a second

    --- Does the a DSSP UPADE after a DSSP GET uses different TCP connection.  I mean, it does not utilizes the first TCP connection it has already established in UPDATE?

     

    >>Any request after that should be in the micro seconds and single millisecond range for large transfers

    --- Yes, I agree. The next requests accomplishes in the order of Micro or Millisecond

     

    >>unless DNS resilution really takes that long in your system due to proxy configuration (do you have proxy disabled for >>local addresses

    --- I have performed an nslookup + ping to reduce the ARP request and DNS query, which reduces time upto some amount but not to normal. I have not enabled any proxy.

    Thursday, May 8, 2008 5:57 PM
  • we re-use TCP connections so after the first request all other requests will use the same connection. To make sure TCP is used start both nodes with only the TCP port specified (dont supply an http port)

     

    Friday, May 9, 2008 5:42 AM