Диагностика узкого места ввода-вывода диска?

Question

У меня есть служба .NET, установленная на сервере Windows 2008 R2, работающем в VDI с 6 ядрами Xeon. Использование ЦП для этой службы составляло в среднем около 10-20% за время возникновения этой проблемы, хотя время прерывания БД происходило с перерывами.

Мое приложение на самом деле единственное, что есть на коробке, и использование ЦП приводит меня к мысли, что следующее не является узким местом процессора или проблемой времени/разреза.

Мы используем log4net для регистрации

<appender name="LogFileAppender" type="log4net.Appender.RollingFileAppender"> 
     <File value="C:\app\service.log" /> 
     <AppendToFile value="true" /> 
     <rollingStyle value="Date" /> 
     <datePattern value="yyyyMMdd" /> 
     <layout type="log4net.Layout.PatternLayout"> 
     <param name="ConversionPattern" value="%date{yyyy-MM-dd hh:mm:ss:fff} %-5level %logger - %message%newline" /> 
     </layout> 
    </appender> 

Я следующий код с фактическими длительными частями удалены

DateTime mst = DateTime.Now; 

//...really long running code 

DateTime st = DateTime.Now; 

//...more long running code 

DateTime et = DateTime.Now; 
LogHelper.LogMessage("REGISTRATION: " + subscriber.Principal.Identity.Name + " packaging complete in " + (et - st).TotalMilliseconds + "ms"); 

et = DateTime.Now; 
LogHelper.LogMessage("REGISTRATION: " + subscriber.Principal.Identity.Name + " Registration complete in " + (et - mst).TotalMilliseconds + "ms"); 

обычно я получаю следующие записи журнала

2013-07-15 07:00:02:238 DEBUG (T:118)Register - REGISTRATION: CORP\user packaging complete in 15.6001ms 
2013-07-15 07:00:02:238 DEBUG (T:118)Register - REGISTRATION: CORP\user Registration complete in 1294.8083ms 

но сегодня я получил следующее:

2013-07-15 11:35:02:498 DEBUG (T:70)Register - REGISTRATION: CORP\user packaging complete in 12589.2807ms 
2013-07-15 11:35:04:386 DEBUG (T:70)Register - REGISTRATION: CORP\user Registration complete in 56768.7639ms 

При просмотре штампов времени две записи журнала записываются на расстоянии 1888 мс, дольше, чем продолжительность обычного выполнения.

1. Как я могу определить, действительно ли это вызвано узким местом ввода-вывода диска?
2. Что еще может объяснить 1888 миллисекунд, которые потребовались между записью журнала, где обычно я получаю 0?

Я рассматриваю implementing this solution, чтобы помочь устранить ввод-вывод в качестве возможной причины.

Answer 1

Мы закончили использование ANTS-профиля Red-Gate, чтобы идентифицировать утечку памяти во время «мягкого перезапуска» службы (удалить/перераспределить объекты). Нормальный поток операций не имел проблем, плоского профиля памяти, чистого счета здоровья.

Только после того, как мы представили таймер для моделирования ряда неожиданных проблем, которые приведут к мягким перезапускам, мы смогли идентифицировать все большее количество затяжных объектов и воспроизвести проблему, что привело к массовому использованию памяти и ужасающему количеству ошибок страницы с ухудшение характеристики.

Моя теория заключается в том, что весь этот пейджинг на диск повлиял как на нашу способность записывать в файл журнала, так и выделять новые объекты.