== Why there is a huge jump in the time used? ==

[J.J.]

Hi,

I've a quetion which has bugged me for quite a while.

I wrote a C#/.NET Web service which is hosted by IIS 5.1 on a Windows XP SP2
machine. This Web service just get the content of the specified txt file and
send the content back to the client. The processing time on the server side
was logged by IIS.
The file sizes and results are listed below (in millisecond):

FileSize: 1K 2K 4K 8K 16K 32K 64K 128K
256K
TimeUsed: 10.0 10.5 10.5 12.0 14.5 116.0 140.5 141
151

As you can seen, the weird thing is, when the file size changes from 16K to
32K, there is big jump in the processing time on the server side. Actually
the jump is between 30K and 31K: when file size is 30K, the time used on the
server side is about 15ms, when file size is 31K, it jumps to about 150ms
(this is the average value. In one of ten, the value is still very small,
like 10-20ms, but most of them are about 150-200ms).

And here is the code I used to implement the Web service:

public string GetLocalFile(string fileName)
{
string returnString = "";

string filePath = @"C:\Inetpub\wwwroot\Files\";

string fullName = filePath + fileName;

StreamReader fs = File.OpenText(fullName);

returnString = fs.ReadToEnd();

fs.Close();

return returnString;
}

I am using the following code on the client side to get files:

private void SendWsFileRequestOut()
{

long startTime, endTime, elapseTime;

startTime = DateTime.Now.Ticks;

//Call Web service for the specified file
fileFetcher.GetLocalFile(fileName);

endTime = DateTime.Now.Ticks;

elapseTime = endTime - startTime;

}


Can anyone help me figure out what the reason could be? Thanks a lot!

J.J.

 

[Randy A. Ynchausti]

J.J,

The file sizes and results are listed below (in millisecond):

FileSize: 1K 2K 4K 8K 16K 32K 64K 128K
256K
TimeUsed: 10.0 10.5 10.5 12.0 14.5 116.0 140.5 141
151

FYI, the profiles that I did (running a local incantation of the code you
posted) showed these times:

File Size Time Spent in SendWsFileRequestOut
(kb) (milliseconds)
====== ========================
262 70
554 80
1108 95

Regards,

Randy

 

[J.J.]

Hello Randy,

For the times you measured, are they logged in IIS log file, or you use some
kind of profiler to get them? Also, are you using XP sp2 too?

I think your results should be the normal ones. I just don't know why this
happened on my computer.

Actually I tried to install the Web service on another clean XP sp2 machine,
and request files from the same client machine. I still got the same jump
between 16K and 32K.

 

[J.J.]

Hello Randy,

I saw your another answer to my problem in another discussion group. Thank
you so much for your help.

For the "automatic growth" problem, why it doesn't happen in your system?

Thank you and best wishes,

J.J.

 

[Randy A. Ynchausti]

J.J.,

For the times you measured, are they logged in IIS log file, or you use
some
kind of profiler to get them? Also, are you using XP sp2 too?

To get an off-the-cuff understanding of the code, I created a Console
Application and pasted your code into it with minor changes. I ran the
DevPartner Profiler free community edition to accumulate the statistics I
noted previously. I am running Windows XP SP2 on an 2.8GHz Pentinum 4
machine. Here is part of the profiler output:

Method Name % in Method % with Children Called Average
[Program Start] 0 99.6 0 0
FileReader.Class1.Main 1 25.5 1 3.3
FileReader.Class1.SendWsFileRequestOut 0.8 24.3 1 2.4
System.Security.SecurityManager.ResolvePolicy 0.6 23.7 2 1
FileReader.Class1.GetLocalFile 0.3 23.2 1 0.9
System.Security.SecurityManager.ResolvePolicy 0.9 22.6 2 1.4
System.Reflection.Assembly.CreateSecurityIdentity 0.9 13.8 2 1.5
System.Security.PolicyManager.Resolve 1.8 12.9 2 2.9
System.IO.File.OpenText 0.3 12.8 1 0.9
System.AppDomain.SetupDomain 6.3 12.4 1 19.7
System.IO.StreamReader..ctor 1.2 11.9 1 3.6
System.Security.Policy.Url..ctor 0.1 11.6 2 0.2
System.Security.Util.URLString..ctor 1.6 11.4 2 2.5
System.Security.SecurityManager..cctor 0.1 11.2 1 0.3
System.Security.SecurityManager.Init 0.1 11.1 1 0.4
System.Security.SecurityManager.DoInitSecurity 0.2 11 1 0.7
System.Security.CodeAccessSecurityEngine..ctor 5.5 10.5 1 17.4
System.IO.StreamReader..ctor 0.5 10.1 1 1.5
System.Security.Util.URLString.ParseString 1.5 9.6 2 2.4
System.IO.StreamReader.ReadToEnd 0.5 9.2 1 1.4
System.IO.FileStream..ctor 2.5 9 1 8
System.Security.SecurityManager.InitPolicy 0.1 7.8 2 0.1
System.Security.PolicyManager..ctor 0.7 7.7 1 2.2
System.Security.Policy.PolicyLevel.Resolve 0.3 7.1 6 0.1
System.Security.PolicyManager.InitData 1.4 6.8 1 4.4
System.Security.Policy.PolicyLevel.CheckCache 0.3 6.7 6 0.2
System.IO.StreamReader.Read 0.2 6.1 555 0
System.IO.FileStream..ctor 1 5.9 1 3.3
System.IO.StreamReader.ReadBuffer 0.9 5.9 555 0

I think your results should be the normal ones. I just don't know why this
happened on my computer.

Profiling will probably help you understand what is going on.

Actually I tried to install the Web service on another clean XP sp2
machine,
and request files from the same client machine. I still got the same jump
between 16K and 32K.

Interesting. Sounds like fun figuring it out.

Regards,

Randy

 

[J.J.]

Hi Randy,

Seems you were testing it as a console application instead of a Web service?
Also, seems to me the client and the service were on the same machine, right?

Actually when I test on the same machine, I can also get quite normal
result. But, if I test the Web service by initiating requests from another
machine, the results will be the ones I described before.

Also, I am trying DevPartner free community edition. Since an IE window will
be opened for the Web service, what I get are all for the IE session while
not for the Webmethod of the Web service.

Any thoughts?

Thank you and best wishes,

J.J.

J.J.,

For the times you measured, are they logged in IIS log file, or you use
some
kind of profiler to get them? Also, are you using XP sp2 too?

To get an off-the-cuff understanding of the code, I created a Console
Application and pasted your code into it with minor changes. I ran the
DevPartner Profiler free community edition to accumulate the statistics I
noted previously. I am running Windows XP SP2 on an 2.8GHz Pentinum 4
machine. Here is part of the profiler output:

Method Name % in Method % with Children Called Average
[Program Start] 0 99.6 0 0
FileReader.Class1.Main 1 25.5 1 3.3
FileReader.Class1.SendWsFileRequestOut 0.8 24.3 1 2.4
System.Security.SecurityManager.ResolvePolicy 0.6 23.7 2 1
FileReader.Class1.GetLocalFile 0.3 23.2 1 0.9
System.Security.SecurityManager.ResolvePolicy 0.9 22.6 2 1.4
System.Reflection.Assembly.CreateSecurityIdentity 0.9 13.8 2 1.5
System.Security.PolicyManager.Resolve 1.8 12.9 2 2.9
System.IO.File.OpenText 0.3 12.8 1 0.9
System.AppDomain.SetupDomain 6.3 12.4 1 19.7
System.IO.StreamReader..ctor 1.2 11.9 1 3.6
System.Security.Policy.Url..ctor 0.1 11.6 2 0.2
System.Security.Util.URLString..ctor 1.6 11.4 2 2.5
System.Security.SecurityManager..cctor 0.1 11.2 1 0.3
System.Security.SecurityManager.Init 0.1 11.1 1 0.4
System.Security.SecurityManager.DoInitSecurity 0.2 11 1 0.7
System.Security.CodeAccessSecurityEngine..ctor 5.5 10.5 1 17.4
System.IO.StreamReader..ctor 0.5 10.1 1 1.5
System.Security.Util.URLString.ParseString 1.5 9.6 2 2.4
System.IO.StreamReader.ReadToEnd 0.5 9.2 1 1.4
System.IO.FileStream..ctor 2.5 9 1 8
System.Security.SecurityManager.InitPolicy 0.1 7.8 2 0.1
System.Security.PolicyManager..ctor 0.7 7.7 1 2.2
System.Security.Policy.PolicyLevel.Resolve 0.3 7.1 6 0.1
System.Security.PolicyManager.InitData 1.4 6.8 1 4.4
System.Security.Policy.PolicyLevel.CheckCache 0.3 6.7 6 0.2
System.IO.StreamReader.Read 0.2 6.1 555 0
System.IO.FileStream..ctor 1 5.9 1 3.3
System.IO.StreamReader.ReadBuffer 0.9 5.9 555 0

I think your results should be the normal ones. I just don't know why this
happened on my computer.

Profiling will probably help you understand what is going on.

Actually I tried to install the Web service on another clean XP sp2
machine,
and request files from the same client machine. I still got the same jump
between 16K and 32K.

Interesting. Sounds like fun figuring it out.

Regards,

Randy