EDIT 2: Mam rozwiązać problem (patrz odpowiedź poniżej) Należy pamiętać, że problem dotyczy potencjalnie wszystkich appenders ozdobione BufferingForwardingAppender jak również wszystkich appenders dziedziczących z BufferingAppenderSkeleton (odpowiednio: AdoNetAppender, RemotingAppender, SmtpAppender i SmtpPickupDirAppender) *log4net problem wydajność BufferingForwardingAppender
Robiłem kilka bardzo podstawowych ławek log4net i próbowałem udekorować RollingFileAppender za pomocą BufferingForwardingAppender.
Przeżyłem straszny występ przechodząc przez BufferingForwardingAppender zamiast bezpośrednio przez RollingFileAppender i naprawdę nie rozumiem powodu.
Oto moja konfiguracja:
<appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender">
<file value="c:\" />
<appendToFile value="false" />
<rollingStyle value="Composite" />
<datePattern value="'.'MMdd-HH'.log'" />
<maxSizeRollBackups value="168" />
<staticLogFileName value="false" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date [%thread] %-5level %logger - %message%newline" />
</layout>
</appender>
<appender name="BufferingForwardingAppender" type="log4net.Appender.BufferingForwardingAppender">
<bufferSize value="512" />
<appender-ref ref="RollingLogFileAppender" />
</appender>
<root>
<level value="DEBUG" />
<appender-ref ref="BufferingForwardingAppender" />
</root>
I tu jest punkt odniesienia (bardzo prosty kod):
var stopWatch = new Stopwatch();
stopWatch.Start();
for (int i = 0; i < 100000; i++)
{
Log.Debug("Hello");
}
stopWatch.Stop();
Console.WriteLine("Done in {0} ms", stopWatch.ElapsedMilliseconds);
przechodząc bezpośrednio przez RollingFileAppender wyjście jest:
odbywa się w 511 ms
Podczas gdy przechodzi BufferingForwardingAppender dekorowanie RollingFileAppender:
Sporządzono w 14261 ms
to około 30 razy wolniej.
Pomyślałem, że zyskałbym pewną prędkość, buforując pewną ilość dzienników przed zapisaniem ich do pliku, jednak z jakiegoś powodu sytuacja znacznie się pogorszy.
Wydaje mi się, że konfiguracja jest OK, więc to naprawdę dziwne.
Ktoś ma jakąś wskazówkę?
Dzięki!
EDIT 1:
Zachowanie jest ściśle ten sam owijając/zdobienia FileAppender lub nawet ConsoleAppender (wciąż tam jest przykładem podstawowy BufferingForwardingAppender owijania/zdobienia ConsoleAppender w urzędowych próbek log4net config .. i nic konkretne wspomniane kwestie dotyczące wydajności).
Po pewnym dochodzeniu/profilowaniu, widzę, że większość czasu jest zepsute wewnątrz BufferingForwardingAppender bardziej szczegółowo w wywołaniu WindowsIdentity.GetCurrent() ... jest nazywane KAŻDYM czasem, gdy wykonamy połączenie z Log.Debug() .. w poprzedniej próbce (100 000 razy w powyższym źródle próbki).
Połączenia z tą metodą są bardzo kosztowne i należy ich unikać lub minimalizować, naprawdę nie rozumiem, dlaczego są wywoływane w przypadku każdego zdarzenia dziennika. Czy naprawdę całkowicie błędnie coś konfiguruję/nie widzę czegoś oczywistego, czy jest to jakoś gdzieś błąd, to właśnie próbuję rozgryźć teraz ...
Częściowa stos połączenie jest:
- AppenderSkeleton.DoAppend
- BufferingAppenderSkeleton.Append
- LoggingEvent.FixVolatileData
- LoggingEvent.get_UserName()
Wywołanie jest get_LocationInformation() również wykonane w FixVolatileData, ponosząc również wysokie koszty perf (uchwycić s ślad za każdym razem).
Teraz próbuję zrozumieć, dlaczego to niezwykle kosztowne wywołanie FixVolatileData (przynajmniej dla poprawki) dzieje się dla każdego zdarzenia dziennika w tym kontekście, podczas gdy przechodzenie bezpośrednio przez zapakowanego appender (bezpośrednio przez ConsoleAppender/FileAppender ..) nie wykonać tego rodzaju operację.
Nadchodzące aktualizacja do naśladowania, chyba że ktoś dostał odpowiedź na to wszystko;)
Dzięki!
Witam, Logujemy wątek, wyjątek i niestandardowy identyfikator pola. Używamy log4net.Appender.AdoNetAppender. Próbowaliśmy określić
W przypadku AdoNetAppender należy się upewnić, że te rzeczy zostały naprawione. Dodaj wartości rzeczy, które musisz poprawić w tej dokumentacji referencyjnej: http://logging.apache.org/log4net/release/sdk/log4net.Core.FixFlags.html –
Dzięki za rozwiązanie! Tak więc numery _final_ będą miały postać 'RollingFileAppender': 511 ms vs 230 ms lub 350 ms (w zależności od konfiguracji) dla' BufferingForwardingAppender'? Z pewnością poprawa, ale nie tak imponująca, jak myślałam ... – Josep