locked
string.(IndexOf LastIndexOf StartsWith) slow in 4.0!! RRS feed

All replies

  • Can you give us a repro? (Ideally using MeasureIt tool to avoid unrelated side-effects)

    -Karel

    Friday, April 30, 2010 12:15 AM
    Moderator
  • hi, Karel:

    Here is my report, I have test this program in many different PC, and different platform, 4.0 is always slow than any other version.

    MeasureIt Performance Results

    Data was collected on a Pre-Vista machine. MeasureIt does NOT automatically set the CPU to a high performance power policy. This means the CPU might be throttled to save power and can lead to incorrect and inconsistant benchmark measurements.

    Below are the results of running a series of benchmarks. Use the MeasureIt /usersGuide for more details on exactly what the benchmarks do.

    It is very easy for benchmark results to be wrong or misleading. You should read the guidance in the MeasureIt /usersGuide before making important decisions based on this data.

    To improve the stability of the measurements, a may be cloned several times and this cloned code is then run in a loop. If the benchmark was cloned the 'scale' attribute represents the number of times it was cloned, and the count represents the number of times the cloned code was run in a loop before the measurement was made. The reported number divides by both of these values, so it represents a single instance of the operation being measured.

    The benchmarks data can vary from run to run, so the benchmark is run several times and the statistics are displayed. If we assume a normal distribution, you can expect 68% of all measureuments to fall within 1 StdDev of the Mean. You can expect over 95% of all measurements to fall witin 2 StdDev of the Mean. Thus 2 StdDev is a good error bound. Keep in mind, however that it is not uncommon for the statistics to be quite stable during a run and yet very widely across different runs. See the users guide for more.

    Generally the mean is a better measurment if you use the number to compute an aggregate throughput for a large number of items. The median is a better guess if you want to best guess of a typical sample. The median is also more stable if the sample is noisy (eg has outliers).

    Data collected

    Scaled where EmptyStaticFunction = 1.0 (2.5 nsec = 1.0 units)

    Name Median Mean StdDev Min Max Samples
    NOTHING [count=1000] 0.000 0.071 0.212 0.000 0.707 10
    MethodCalls: EmptyStaticFunction() [count=1000 scale=10.0] 1.000 1.095 0.225 0.919 1.619 10
    Loop 1K times [count=1000] 233.222 237.458 10.611 227.741 258.389 10
    MethodCalls: EmptyStaticFunction(arg1,...arg5) [count=1000 scale=10.0] 1.597 1.641 0.139 1.509 1.878 10
    MethodCalls: aClass.EmptyInstanceFunction() [count=1000 scale=10.0] 1.399 1.410 0.032 1.399 1.505 10
    MethodCalls: aClass.Interface() [count=1000 scale=10.0] 1.576 1.595 0.058 1.576 1.768 10
    MethodCalls: aSealedClass.Interface() (inlined) [count=1000 scale=10.0] 0.196 0.207 0.031 0.196 0.299 10
    MethodCalls: aStructWithInterface.Interface() (inlined) [count=1000 scale=10.0] 0.000 0.014 0.041 0.000 0.138 10
    MethodCalls: aClass.VirtualMethod() [count=1000 scale=10.0] 0.939 0.952 0.040 0.939 1.073 10
    MethodCalls: Class.ReturnsValueType() [count=1000 scale=10.0] 2.409 2.392 0.037 2.318 2.420 10
    FieldAccess: aStaticInt++ [count=1000 scale=10.0] 1.092 1.138 0.098 1.092 1.407 10
    FieldAccess: aClass.aInstanceInt++ [count=1000 scale=10.0] 1.136 1.145 0.027 1.136 1.226 10
    FieldAccess: aClass.aIntstanceString = "hi" [count=1000 scale=10.0] 1.595 1.606 0.031 1.595 1.697 10
    FieldAccess: aStaticString = aString [count=1000 scale=10.0] 1.595 1.631 0.080 1.595 1.855 10
    ObjectOps: (aObjectString is String) [count=1000 scale=10.0] 0.589 0.601 0.034 0.589 0.703 10
    ObjectOps: (aObjectString as String) [count=1000 scale=10.0] 0.676 0.784 0.287 0.676 1.639 10
    ObjectOps: (string) aObjectString) [count=1000 scale=10.0] 0.939 0.953 0.041 0.939 1.077 10
    ObjectOps: new Class() [count=1000 scale=10.0] 5.240 9.780 9.106 3.697 34.495 10
    ObjectOps: new FinalizableClass() [count=1000 scale=10.0] 78.305 148.816 137.529 69.965 515.835 10
    ObjectOps: Activator.CreateInstance<Class>() [count=1000 scale=10.0] 654.218 687.749 93.702 650.373 967.945 10
    ObjectOps: (Class) Activator.CreateInstance(classType) [count=1000 scale=10.0] 91.401 93.751 5.269 89.191 107.301 10
    ObjectOps: (Class) classInstance.MemberWiseClone() [count=1000 scale=10.0] 58.982 60.350 3.906 56.118 69.548 10
    Arrays: aIntArray[i] = 1 [count=1000 scale=10.0] 0.633 0.675 0.092 0.633 0.923 10
    Arrays: localIntPtr[i] = 1 [count=1000 scale=10.0] 0.527 0.538 0.034 0.527 0.640 10
    Arrays: aIntPtr[i] = 1 [count=1000 scale=10.0] 0.550 0.560 0.034 0.546 0.660 10
    Arrays: string[i] = aString [count=1000 scale=10.0] 2.978 3.014 0.082 2.978 3.246 10
    Arrays: aInterfaceArray[i] = aClass [count=1000 scale=10.0] 2.955 2.991 0.081 2.955 3.218 10
    Arrays: 1 for...Length aIntArray[i] = 1 [count=1000] 8.527 8.904 0.825 8.527 11.159 10
    Arrays: 1 for...10 aIntArray[i] = 1 [count=1000] 6.130 6.236 0.318 6.130 7.191 10
    Arrays: 1 for...Length aStringArray[i] = 1 [count=1000] 33.045 33.591 1.333 33.045 37.485 10
    Arrays: 1 for...Length aInterfaceArray[i] = 1 [count=1000] 33.045 33.485 0.984 33.045 36.228 10
    Delegates: new MyDelegate(aClass.EmptyInstanceFunction) [count=1000 scale=10.0] 11.872 11.000 3.174 7.422 17.418 10
    Delegates: new MyDelegate(Class.StaticFunction) [count=1000 scale=10.0] 11.043 10.251 2.513 6.216 14.656 10
    Delegates: aInstanceDelegate() [count=1000 scale=10.0] 1.246 1.261 0.045 1.246 1.395 10
    Delegates: aStaticDelegate() [count=1000 scale=10.0] 1.642 1.680 0.113 1.642 2.020 10
    Events: Fire Events [count=1000 scale=10.0] 1.092 1.108 0.046 1.092 1.246 10
    GenericsOnValueType: aGenericClassWithInt.aGenericInstanceFieldT = aInt [count=1000 scale=10.0] 0.436 0.443 0.030 0.409 0.530 10
    GenericsOnValueType: GenericClass<int>.aGenericStaticFieldT = aInt [count=1000 scale=10.0] 0.259 0.270 0.029 0.259 0.358 10
    GenericsOnValueType: aGenericClassWithInt.ClassGenericInstanceMethod() [count=1000 scale=10.0] 1.293 1.303 0.036 1.289 1.411 10
    GenericsOnValueType: GenericClass<int>.ClassGenericStaticMethod() [count=1000 scale=10.0] 1.253 1.268 0.042 1.253 1.395 10
    GenericsOnValueType: Class.GenericMethod<int>() [count=1000 scale=10.0] 0.919 0.976 0.137 0.919 1.375 10
    GenericsOnReferenceType: aGenericClassWithString.aGenericInstanceFieldT = aString [count=1000 scale=10.0] 1.183 1.194 0.034 1.183 1.297 10
    GenericsOnReferenceType: GenericClass<string>.aGenericStaticFieldT = aString [count=1000 scale=10.0] 1.159 1.169 0.031 1.159 1.261 10
    GenericsOnReferenceType: aGenericClassWithString.ClassGenericInstanceMethod() [count=1000 scale=10.0] 1.291 1.319 0.085 1.289 1.576 10
    GenericsOnReferenceType: GenericClass<string>.ClassGenericStaticMethod() [count=1000 scale=10.0] 6.306 6.406 0.201 6.306 6.892 10
    GenericsOnReferenceType: Class.GenericMethod<string>() [count=1000 scale=10.0] 1.000 1.013 0.049 0.974 1.155 10
    Iteration: sum numbers 1-20 [count=1000] 8.291 8.440 0.448 8.291 9.784 10
    Iteration: sum numbers 1-100 [count=1000] 42.908 43.281 0.837 42.908 45.619 10
    Iteration: foreach over List<String> (100 elems) [count=1000] 250.491 250.448 2.059 248.330 255.796 10
    Iteration: for over List<String> (100 elems) [count=1000] 205.933 205.466 1.179 204.086 207.112 10
    Iteration: foreach over List<int> (100 elems) [count=1000] 119.352 120.008 1.024 119.332 121.847 10
    Iteration: for over List<int> (100 elems) [count=1000] 159.902 160.142 1.543 158.743 163.379 10
    Iteration: for with check int[] (100 elems) [count=1000] 67.662 68.703 1.773 67.662 72.220 10
    Iteration: for with bound Optimization int[] (100 elems) [count=1000] 47.741 48.130 0.850 47.741 50.452 10
    Iteration: foreach over ValueType[] (100 elems) [count=1000] 49.470 49.851 0.829 49.470 52.102 10
    Iteration: Foreach method over ValueType[] (100 elems) [count=1000] 213.163 213.210 2.273 210.098 218.075 10
    TypeReflection: anObject.GetType() [count=1000 scale=10.0] 4.468 4.507 0.084 4.468 4.727 10
    TypeReflection: anArray.GetType() [count=1000 scale=10.0] 218.083 220.992 6.292 214.177 232.024 10
    TypeReflection: typeof(string[]) [count=1000 scale=10.0] 10.120 10.225 0.455 9.851 11.532 10
    TypeReflection: typeof(string) [count=1000 scale=10.0] 2.232 2.272 0.085 2.232 2.491 10
    TypeReflection: typeof(string).TypeHandle [count=1000 scale=10.0] 0.185 0.198 0.034 0.177 0.299 10
    TypeReflection: anObject.GetType() == type [count=1000 scale=10.0] 3.194 4.127 2.757 3.194 12.397 10
    TypeReflection: anObject.GetType() == typeof(string) [count=1000 scale=10.0] 0.330 0.377 0.102 0.326 0.656 10
    TypeReflection: anObject is string [count=1000 scale=10.0] 0.853 0.865 0.038 0.853 0.978 10
    MethodReflection: Non-reflection EmptyStaticFunction() [count=1000 scale=10.0] 0.923 0.938 0.048 0.904 1.081 10
    MethodReflection: Non-reflection EmptyStaticFunction5Arg() [count=1000 scale=10.0] 1.576 1.633 0.139 1.568 2.039 10
    MethodReflection: Method.Invoke EmptyStaticFunction() [count=1000 scale=10.0] 417.401 419.406 6.851 412.652 433.077 10
    MethodReflection: Method.Invoke EmptyStaticFunction5Arg() [count=1000 scale=10.0] 980.240 988.639 18.236 968.428 1024.872 10
    FieldReflection: aClassInstance.aInstanceInt++ [count=1000 scale=10.0] 1.136 1.147 0.035 1.136 1.253 10
    FieldReflection: (int) aInstanceIntField.GetValue(aClassInstance) [count=1000 scale=10.0] 13.202 13.297 0.401 12.853 14.326 10
    FieldReflection: aInstanceIntField.SetValue(aClassInstance, intValue) [count=1000 scale=10.0] 15.857 15.995 0.603 15.505 17.697 10
    CustomAttributes: GetCustomAttribute() failure [count=1000] 1253.615 1262.605 28.279 1243.890 1346.247 10
    CustomAttributes: GetCustomAttribute() success [count=1000] 4052.240 4088.849 81.805 4018.153 4267.348 10
    PInvoke: FullTrustCall() [count=1000] 10.413 10.849 0.935 10.413 13.438 10
    PInvoke: FullTrustCall() (2 call average) [count=1000 scale=2.0] 8.772 8.843 0.158 8.762 9.293 10
    PInvoke: 10 FullTrustCall() (10 call average) [count=1000 scale=10.0] 8.039 8.132 0.138 8.028 8.432 10
    PInvoke: 1 PartialTrustCall [count=1000] 29.862 30.397 1.137 29.666 32.770 10
    PInvoke: PartialTrustCall() (2 call average) [count=1000 scale=2.0] 29.764 29.963 0.578 29.568 31.493 10
    PInvoke: PartialTrustCall() (10 call average) [count=1000 scale=10.0] 29.083 29.242 0.392 28.766 29.953 10
    Threading: Thread.CurrentThread [count=1000 scale=10.0] 4.684 4.738 0.123 4.684 5.084 10
    Threading: threadId = Thread.CurrentThread.ManagedThreadId [count=1000 scale=10.0] 3.391 3.430 0.086 3.391 3.666 10
    Threading: aTLSInt++ [count=1000 scale=10.0] 42.845 42.689 0.462 41.878 43.509 10
    Threading: aTLSString = aString [count=1000 scale=10.0] 28.418 28.400 0.098 28.236 28.562 10
    Threading: Interlocked.CompareExchange 0 [count=1000 scale=10.0] 11.124 11.233 0.176 11.124 11.658 10
    Threading: Interlocked.CompareExchange i [count=1000 scale=10.0] 12.295 12.418 0.165 12.295 12.747 10
    Threading: Spin Interlocked.CompareExchange [count=1000 scale=10.0] 11.255 11.352 0.156 11.253 11.705 10
    Locks: Monitor lock [count=1000] 25.422 30.083 9.524 25.383 56.935 10
    Locks: lock statement [count=1000] 29.980 30.656 1.194 29.980 34.028 10
    Locks: ReaderWriterLock ReadLock [count=1000] 125.403 125.874 1.269 124.637 127.898 10
    Locks: ReaderWriterLock WriteLock [count=1000] 116.778 117.462 1.338 116.346 120.550 10
    Varags: Class.ParamsArgMethod(1) [count=1000 scale=10.0] 6.470 7.868 3.370 5.595 16.499 10
    Varags: Class.VarArgMethod(1) [count=1000 scale=10.0] 1.489 1.509 0.060 1.489 1.690 10
    Guid: new Guid(string) [count=1000 scale=10.0] 508.737 508.967 4.154 502.613 517.517 10
    Guid: new Guid(int, ..)) [count=1000 scale=10.0] 11.823 11.930 0.464 11.301 12.955 10
    Guid: g = staticGuid) [count=1000 scale=10.0] 3.261 3.405 0.388 3.261 4.562 10
    Regex: Regex fetch word len=18 [count=1000] 1004.283 1000.754 30.355 929.862 1060.943 10
    Regex: Compiled Regex fetch word len=18 [count=1000] 411.356 446.248 68.202 387.780 591.356 10
    Regex: ByHand fetch word len=18 [count=1000] 184.145 190.063 19.436 180.668 248.134 10
    Regex: Regex fetch word len=85 [count=1000] 1027.367 1025.890 23.699 981.297 1073.517 10
    Regex: Compiled Regex fetch word len=85 [count=1000] 436.031 441.367 29.904 404.362 487.859 10
    Regex: ByHand fetch word len=85 [count=1000] 1262.613 1268.193 19.660 1253.320 1324.361 10
    Regex: Regex fetch word len=152 [count=1000] 1088.507 1089.686 22.923 1053.084 1123.497 10
    Regex: Compiled Regex fetch word len=152 [count=1000] 482.358 495.988 75.862 430.766 711.081 10
    Regex: ByHand fetch word len=152 [count=1000] 2294.067 2295.831 6.635 2288.526 2308.251 10
    Regex: Regex fetch word len=219 [count=1000] 1131.159 1129.792 25.126 1078.271 1165.815 10
    Regex: Compiled Regex fetch word len=219 [count=1000] 562.927 552.090 40.046 493.399 618.625 10
    Regex: ByHand fetch word len=219 [count=1000] 3341.257 3369.151 50.332 3320.432 3483.104 10
    Regex: Regex fetch word len=286 [count=1000] 1197.210 1215.666 53.466 1157.525 1346.169 10
    Regex: Compiled Regex fetch word len=286 [count=1000] 504.283 520.813 32.521 486.562 569.509 10
    Regex: ByHand fetch word len=286 [count=1000] 4449.784 4479.399 73.659 4403.261 4627.348 10
    Enums: aEnum.ToString() [count=1000] 1059.646 1082.130 86.279 991.788 1218.428 10
    Enums: aFlagsEnum.ToString() (1 flag) [count=1000] 2624.283 2642.978 123.658 2512.809 2870.923 10
    Enums: aEnum.ToString() (4 flags) [count=1000] 2976.169 3039.183 157.770 2932.691 3485.147 10

     

    Attributes of the machine used to collect the data

    Attribute Value
    Computer Name PC-200906121517
    Number of Processors 1
    Processor Name Intel(R) Pentium(R) Dual CPU E2160 @ 1.80GHz
    Processor Mhz 1794
    Memory MBytes 3069
    L1 Cache KBytes 32
    L2 Cache KBytes 1024
    Operating System Microsoft Windows XP Professional
    Operating System Version 5.1.2600
    Stopwatch resolution (nsec) 0.557
    CompileType JIT
    CodeSharing AppDomainSpecific
    CodeOptimization Optimized

    Friday, April 30, 2010 3:09 AM
  • in this test, 4.0 has same performance with others

     

    using System;
    using System.Collections.Generic;
    using System.Diagnostics;
    
    namespace Test
    {
     class Program
     {
      static Stopwatch sWatch = new Stopwatch();
      const int COUNT = 100000;
    
      static void Main(string[] args)
      {
       int strLength = 20000;
    
       char[] match = new char[strLength];
       char[] pattern = new char[strLength];
       Random rnd = new Random(2010);
    
       for (int i = 0; i < match.Length; i++)
       {
        match[i] = (char)rnd.Next(10, 65535);
        pattern[i] = (char)rnd.Next(10, 65535);
       }
    
       string matchString = new string(match);
       
       sWatch.Start();
    
       for (int i = 0; i < COUNT; i++)
        matchString.IndexOf(pattern[i % strLength]); 
    
       sWatch.Stop();
       Console.WriteLine("IndexOf:" + sWatch.ElapsedMilliseconds);
       Console.ReadKey();
      }
     }
    }

     

    Friday, April 30, 2010 3:39 AM
  • In this test, 4.0 was slower than the other version about 4 times.

    using System;
    using System.Diagnostics;
    
    namespace Test
    {
      class Program
      {
        static Stopwatch sWatch = new Stopwatch();
        static Random rnd = new Random(2010);
        const int COUNT = 1000;
    
        static void Main(string[] args)
        {
          int strLength = 200000;
    
          char[] match = new char[strLength];
          
          for (int i = 0; i < match.Length; i++)
            match[i] = GetRandomChar();
    
          string matchString = new string(match);
          string[] pattern = new string[100];
    
          for (int i = 0; i < pattern.Length; i++)
            pattern[i] = GetRandomString(4);
    
          long sum = 0;
    
          sWatch.Start();
    
          for (int i = 0; i < COUNT; i++)
            sum += matchString.IndexOf(pattern[i % pattern.Length]);
    
          sWatch.Stop();
          Console.WriteLine("Sum = {0} IndexOf {1}ms" , sum, sWatch.ElapsedMilliseconds);
          Console.ReadKey();
        }
    
        static string GetRandomString(int length)
        {
          char[] result = new char[length];
    
          for (int i = 0; i < result.Length; i++)
            result[i] = GetRandomChar();
    
          return new string(result);
        }
    
        static char GetRandomChar()
        {
          return (char)rnd.Next('A', 'z');
        }
      }
    }

    Friday, April 30, 2010 2:24 PM
  • Did you hook your perf-test into MeasureIt? Can you please paste that code here? And the MeasureIt results of your method only on 3.5 and 4.0?

    Another option is just to file a bug on MS Connect and wait for official response from perf team (that might take some time).

    Thanks,
    -Karel

    Friday, April 30, 2010 3:51 PM
    Moderator
  • Hi Karel, Sorry, I don't know how to use MeasureIt yet, this is my program, Compile it in different version of framwork(4.0 ,3.5)

    In my computer, it's running about 9000ms in framework 3.5, and 25000ms in framework 4.0

    you can test it in your computer

    Thanks

    using System;
    using System.Diagnostics;
    
    namespace Test
    {
      class Program
      {
        static Stopwatch sWatch = new Stopwatch();
        static Random rnd = new Random(2010);
        const int COUNT = 50;
    
        static void Main(string[] args)
        {
          int strLength = 10000000;
    
          char[] match = new char[strLength];
    
          for (int i = 0; i < match.Length; i++)
            match[i] = GetRandomChar();
    
          string matchString = new string(match);
          string[] pattern = new string[100];
    
          for (int i = 0; i < pattern.Length; i++)
            pattern[i] = GetRandomString(4);
    
          long sum = 0;
    
          sWatch.Start();
    
          for (int i = 0; i < COUNT; i++)
            sum += matchString.IndexOf(pattern[i % pattern.Length]);
    
          sWatch.Stop();
          Console.WriteLine("Sum = {0} IndexOf {1}ms", sum, sWatch.ElapsedMilliseconds);
          Console.ReadKey();
        }
    
        static string GetRandomString(int length)
        {
          char[] result = new char[length];
    
          for (int i = 0; i < result.Length; i++)
            result[i] = GetRandomChar();
    
          return new string(result);
        }
    
        static char GetRandomChar()
        {
          return (char)rnd.Next('A', 'z');
        }
      }
    }

    Saturday, May 1, 2010 1:46 AM
  • The MeasureIt tool does useful things like running the scenario first without measuring and then computes statistics from multiple runs. That is quite reliable measuring we could use for further investigation. Also IMO removing the randomness from your repro would help us better understand the difference between 3.5 and 4.0.

    Unfortunatelly I probably won't have time to convert your repro into MeasureIt myself in next few days. If you can do it that would be great help, if you cannot do it then please wait ...

    Also it would be good to explain what's the impact of this slowdown (perf regression) on your application/business.

    -Karel

    Saturday, May 1, 2010 8:48 PM
    Moderator