2010-07-11 3 views
3

Этот код имеет тайминги для п вызовов двух методов, что и не делают ничего (MyMethod1, MyMethod2), но украшенных различными атрибутами (MyAspect1, MyAspect2).Может ли кто-нибудь помочь мне объяснить эти тайминги метода?

MyAspect1 не содержит логики, кроме сдачи MyMethod1 run (Proceed()).

MyAspect2 делает то же самое для MyMethod2, но также создает задачу, предоставляющую анонимного делегата для запуска, который должен приравниваться к почти нулевой работе для ЦП (обрезка строки).

Я ожидаю, что таймеры для итераций более MyMethod1 и MyMethod2 будут примерно одинаковыми.

Фактические тайминги ниже; они кажутся противоположными интуитивно понятными, начиная с MyMethod1, начиная значительно медленнее (в соответствии с тем, что я ожидаю), и, в конечном итоге, с потерей гонки с 10000 итераций вперед. Может ли кто-нибудь помочь мне объяснить это?

Test results (average of 3 runs per iteration value): 

No. of iterations |   Ticks 
         Method 1 | Method 2 
     5     25282  6999 
     100    22128  8176 
     1000    22982  23720 
     10000    25995  265621 
     1000000   994359  25125076 

--------------------------------------------------- 

public class TestClass2 
{ 
    public void MyTest() 
    { 
     const int iterations = 100; 
     var stopWatch = new Stopwatch(); 
     stopWatch.Start(); 
     for (int x = 0; x < iterations; x++) 
     { 
      MyMethod1(); 
     } 
     stopWatch.Stop(); 
     Console.WriteLine("Method1 calls duration: " + stopWatch.ElapsedTicks);    
     stopWatch.Reset(); 
     stopWatch.Start(); 
     for (int x = 0; x < iterations; x++) 
     { 
      MyMethod2(); 
     } 
     stopWatch.Stop(); 
     Console.WriteLine("Method2 calls duration: " + stopWatch.ElapsedTicks);       
    } 

    [MyAspect1] 
    private void MyMethod1() {} 
    [MyAspect2] 
    private void MyMethod2() {} 
} 

[Serializable] 
public class MyAspect1 : AsynchronousMetricsAspect 
{ 
    public override void OnInvoke(MethodInterceptionArgs args) 
    { 
     args.Proceed(); 
    } 
} 

//NOTE: this type is the same as MyAspect1, but adds a Task creation 
[Serializable] 
public class MyAspect2 : AsynchronousMetricsAspect 
{ 
    public override void OnInvoke(MethodInterceptionArgs args) 
    { 
     args.Proceed(); 
     Task.Factory.StartNew(() => "bleh".Trim()); //invoke the logging method asynchronously   
    } 
} 

Дополнительная информация: Тест быть вызван из ReSharper NUnit VS плагин и атрибуты PostSharp MethodInterceptionAspect s.

Edit: Updated figures for when the methods are pre-invoked before the tests, to ensure any JIT compilation has occurred. 

Test results (ballpark): 

No. of iterations |   Ticks 
         Method 1 | Method 2 
     5     22   437 
     100    37   2204 
     1000    192   24476 
     10000    7931  286403 
     100000   115451  2862439 
     1000000   695950  29049021 
     10000000   8347867  275777590 
+0

способен вызвать тест в профайлер (nProf, EQATEC и т.д.) Вы? –

+1

Я загрузил точку трассировки и отчитаюсь о своих выводах, когда я разработал, как ее использовать. – Ben

+0

Проверьте, какой код имеет PostSharp, сгенерированный с помощью Reflector. –

ответ

4

Ну, чтобы начать с, я бы попытаться определить, является ли что-либо делать с PostSharp или нет. Я попытался бы называть те же методы без участия любого АОП.

Вот мои подозрения, хотя:

  • 25000 тики (довольно короткий отрезок времени, заметьте) обусловлено JITting бит инфраструктуры PostSharp. Поэтому они являются постоянной стоимостью, которую не должны быть оплачены вторым методом. Вы можете проверить это, переключив порядок ваших тестов. Однако, учитывая цифры, я подозреваю, что есть другой постоянные затраты, связанные с настройкой фабрик задач и т. Д. ... что объясняет, почему 100 итераций метода 2 не занимают много больше, чем 5 итераций.

  • Создание задачи не является бесплатным, и я не ожидал, что это произойдет. Просто тот факт, что вы создаете объект, означает, что работа продолжается ... и тогда есть планирование и координация между задачами и потоками. Параллельные расширения хороши, но не могут творить чудеса. Я не знаю, как PFX будет распространять эту работу, но возможно, что часть этой дополнительной работы создается (задачи короткие, но они все равно должны выполняться) заканчивается на том же ядре, что и основной поток. Вы очень быстро создаете множество задач.

  • Возможно, существует разница между этими двумя методами, чтобы изменить, могут ли они быть встроены или нет. Это немного запутывается использованием PostSharp, но я не был бы полностью удивлен, обнаружив, что это так.

  • Масштабирование не является линейным в случае метода 2, но оно не за горами. Если вы примете формулу 6000 + 23 * N в качестве быстрого и грязного аппроксимации, вы можете ожидать значения 6115, 8300, 29000, 236000 и 23006000 - которые не являются очень.

  • Я сильно подозреваю, что огромная цифра для первого метода в последнем тесте обусловлена ​​сбором мусора и ростом кучи. Здесь вы создаете множество объектов, и я подозреваю, что он делает полный GC и расширяет различные поколения соответственно - метод 2 в том же тесте, а затем использует эту большую кучу.

Те действительно только предположения, но они дают какое-то объяснение для всего, что вы видите :)

+0

Спасибо, Джон. Не ожидал ответа от самого человека! В настоящее время я пытаюсь расшифровать вывод DotTrace. Спасибо, спасибо, большое спасибо за свет. – Ben

+0

@Ben: Остерегайтесь предполагать, что любой из этих ответов действительно точным. Идеи могут помочь вам в дальнейшем диагностировать, но ни один из них не должен считаться правильным :) (Самый простой, чтобы проверить, - это мое подозрение в компиляторе JIT, ответственном за первый метод, который занимает больше времени для небольшого количества итераций.) –

Смежные вопросы