log4net BufferingForwardingAppender प्रदर्शन मुद्दा

Question

संपादित करें 2: मैं इस समस्या का समाधान कर लिया (नीचे का जवाब देखें) कृपया ध्यान दें कि समस्या संभवतः सभी appenders BufferingForwardingAppender के साथ-साथ BufferingAppenderSkeleton (क्रमशः से इनहेरिट सभी appenders के साथ सजाया प्रभावित करता है: AdoNetAppender, RemotingAppender, SmtpAppender और SmtpPickupDirAppender) *

मैं लॉग 4नेट के कुछ बहुत ही बुनियादी खंड बना रहा था और मैंने एक रोलिंगफाइलएपेंडर को एक बफरिंगफॉरवर्डिंग एपेंडर के साथ सजाने की कोशिश की।

मुझे रोलिंगफाइलएपेंडर के माध्यम से सीधे BufferingForwardingAppender के माध्यम से भयानक प्रदर्शन का अनुभव होता है और मुझे वास्तव में कारण नहीं मिलता है। यहाँ

<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> 

और बेंचमार्क (बहुत ही सरल कोड) है:

यहाँ मेरी विन्यास है

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); 

RollingFileAppender के माध्यम से सीधे उत्पादन हो रहा है:

में किया 511 एमएस

BufferingForwardingAppender सजाने RollingFileAppender माध्यम से जा रहा जबकि:

14261 एमएस

लगभग है 30 बार धीमी है कि में हो गया।

मैंने सोचा कि मुझे फ़ाइल में लिखने से पहले लॉग की एक निश्चित राशि बफर करके कुछ गति प्राप्त होगी, हालांकि किसी कारण से यह चीजों को और भी बदतर हो जाता है।

मुझे लगता है कि कॉन्फ़िगरेशन ठीक है, इसलिए यह वास्तव में अजीब है।

किसी को भी एक सुराग मिला?

धन्यवाद!

संपादित करें 1:

व्यवहार सख्ती से लपेटकर/एक FileAppender या यहाँ तक कि सजा ConsoleAppender द्वारा एक ही है (अभी भी वहाँ log4net आधिकारिक config नमूनों में बुनियादी BufferingForwardingAppender रैपिंग/सजाने ConsoleAppender का एक उदाहरण है .. और कुछ भी नहीं प्रदर्शन के साथ विशिष्ट उल्लिखित व्यवहार)।

कुछ जांच/प्रोफाइलिंग के बाद, मैं देख सकता हूं कि अधिकतर समय BufferingForwardingAppender के अंदर WindowsIdentity.GetCurrent() को कॉल में खराब कर दिया गया है ... हर बार कहा जा रहा है हम Log.Debug() पर कॉल करते हैं .. पिछले नमूने में (उपरोक्त नमूना स्रोत में 100K बार)।

इस विधि को कॉल बहुत महंगा माना जाता है और इसे टाला जाना चाहिए या कम किया जाना चाहिए, मुझे वास्तव में यह नहीं मिलता है कि यह प्रत्येक लॉग इवेंट के लिए क्यों बुलाया जाता है। क्या मैं वास्तव में कुछ स्पष्ट रूप से गलत कॉन्फ़िगर कर रहा हूं/कुछ स्पष्ट नहीं देख रहा हूं, या यह कि किसी भी तरह से एक बग है, यही वह है जिसे मैं अभी समझने की कोशिश कर रहा हूं ...

आंशिक कॉल स्टैक है:

• AppenderSkeleton.DoAppend
• BufferingAppenderSkeleton.Append
• LoggingEvent.FixVolatileData
• LoggingEvent.get_UserName()

get_LocationInformation() को एक कॉल है फिक्सवोलाटाइलडाटा में भी किया गया, जिसमें एक उच्च perf लागत भी शामिल है (एस को कैप्चर करें प्रत्येक बार ट्रेस ट्रेस)।

अब मैं यह समझने की कोशिश कर रहा हूं कि यह अत्यंत महंगी FixVolatileData कॉल (कम से कम ठीक से पूछे जाने वाले प्रश्न के लिए) इस संदर्भ में प्रत्येक लॉग इवेंट के लिए होता है जबकि सीधे लपेटा हुआ एपेंडर (सीधे ConsoleAppender/FileAppender .. के माध्यम से) के माध्यम से जाता है। इस तरह के ऑपरेशन करते हैं।

आगामी अद्यतन का पालन करने, जब तक कि कोई इस सब के लिए एक जवाब मिला,)

धन्यवाद!

Answer 1

मैं इस मुद्दे में पता चला।

BufferingForwardingAppenderBufferingAppenderSkeleton से इनहेरिट है (के रूप में अन्य लॉगिंग घटनाओं बफरिंग का इस्तेमाल कर रही appenders हैं AdoNetAppender जैसे, RemotingAppender, SmtpAppender ..)।

BufferingAppenderSkeleton वास्तव में एक निश्चित शर्त मिलने के बाद उन्हें वास्तव में लक्षित एपेंडर को वितरित करने से पहले लॉगिंग ईवेंट को बफर कर रहा है (उदाहरण के लिए बफर पूर्ण)।

LoggingEvent वर्ग के प्रलेखन के अनुसार

(एक लॉगिंग घटना का प्रतिनिधित्व करने, और घटना के सभी मान (संदेश, threadid ...) युक्त):

कुछ लॉगिंग घटनाओं गुण "अस्थिर" माना जाता है, मूल्य परिशिष्ट, पर ईवेंट वितरित होने पर सही होते हैं लेकिन बाद में किसी भी समय संगत नहीं होंगे। यदि कोई ईवेंट संग्रहीत किया जाता है और बाद में संसाधित किया जाता है, तो इन अस्थिर मान को FixVolatileData को ठीक करके तय किया जाना चाहिए। वहाँ एक प्रदर्शन दंड FixVolatileData बुला द्वारा किए गए है, लेकिन है बनाए रखने के डेटा स्थिरता के लिए आवश्यक है

ये "अस्थिर" गुण इस तरह के संदेश, ThreadName, उपयोगकर्ता नाम, पहचान के रूप में FixFlags गणन युक्त झंडे का प्रतिनिधित्व कर रहे ... तो सभी अस्थिर गुण। इसमें ध्वज "कोई नहीं" (कोई गुण ठीक नहीं), "सभी" (सभी गुणों को ठीक करें) और "आंशिक" (गुणों की केवल एक निश्चित पूर्व परिभाषा को ठीक करें) को ध्वज भी शामिल है।

व्हील BufferingAppenderSkeleton को तत्काल किया जाता है, DEFAULT द्वारा यह "सभी" को फिक्सिंग सेट करता है जिसका अर्थ है कि सभी "अस्थिर" गुणों को ठीक किया जाना चाहिए।

उस संदर्भ में, प्रत्येक लॉगिंगएवेंट के लिए BufferingAppenderSkeleton में जोड़ा गया, सभी "अस्थिर" गुण बफर में ईवेंट डालने से पहले तय किए जाएंगे। इसमें संपत्तियों (उपयोगकर्ता नाम) और स्थान जानकारी (स्टैक ट्रेस) शामिल हैं, भले ही इन गुणों को लेआउट में शामिल नहीं किया गया हो (लेकिन मुझे लगता है कि लेआउट बदल दिया गया है, तो लेआउट बदल दिया गया है ताकि इन गुणों को बाद में एक बफर के दौरान शामिल किया जा सके। LoggingEvents से पहले से ही भरा गया है)।

हालांकि मेरे मामले में यह वास्तव में HURTS प्रदर्शन। मैं पहचान और मेरे लेआउट में LocationInformation सहित नहीं कर रहा हूँ और (मुख्य रूप से प्रदर्शन के मुद्दों के लिए)

समाधान के लिए अब की योजना नहीं है ...

जो इस्तेमाल किया जा सकता BufferingAppenderSkeleton में दो गुण हैं FixFlagsBufferingAppenderSkeleton का ध्वज मान नियंत्रित करने के लिए (एक बार फिर डिफ़ॉल्ट रूप से यह "सभी" पर सेट होता है जो बहुत अच्छा नहीं है!)। ये दो गुण Fix (फ़िक्सफ्लैग प्रकार) और OnlyFixPartialEventData (बूल प्रकार) हैं।

ध्वज मूल्य की एक अच्छी धुन के लिए या सभी फिक्स अक्षम करने के लिए, Fix संपत्ति का उपयोग किया जाना चाहिए। झंडे के विशिष्ट आंशिक पूर्वनिर्धारित संयोजन (पहचान या स्थानइन्फो सहित) के लिए, OnlyFixPartialEventData का उपयोग इसे "सत्य" पर सेट करके उपयोग किया जा सकता है।

अगर मैं ऊपर विन्यास नमूना पुन: उपयोग (मेरे सवाल में), केवल परिवर्तन विन्यास प्रदर्शन दिलाने के लिए किए गए नीचे दिया गया है:

<appender name="BufferingForwardingAppender" type="log4net.Appender.BufferingForwardingAppender"> 
    <bufferSize value="512" /> 
    <appender-ref ref="RollingLogFileAppender" /> 
    <Fix value="0"/> <!-- Set Fix flag to NONE --> 
</appender> 

इस संशोधित विन्यास का उपयोग करना, बेंचमार्क कोड निष्पादन में प्रस्तुत मेरी ऊपर सवाल, लगभग 14000ms से 230ms (60X तेज) से गिर रहा है! और यदि मैं सभी सुधारों को अक्षम करने के बजाय <OnlyFixPartialEventData value="true"/> का उपयोग करता हूं तो यह लगभग 350ms ले रहा है।

दुःख की बात है इस ध्वज को बहुत अच्छी तरह से प्रलेखित है नहीं (SDK दस्तावेज़, एक छोटा सा को छोड़कर) .. तो मैं log4net स्रोतों में गहरी खुदाई करने के लिए इस मुद्दे को तलाश करनी है।

यह इस ध्वज कहीं नहीं दिखाई देता है, विशेष रूप से "संदर्भ" विन्यास नमूनों में विशेष रूप से समस्याग्रस्त है, (http://logging.apache.org/log4net/release/config-examples.html)। तो BufferingForwardingAppender के लिए प्रदान के नमूने, और AdoNetAppender (और अन्य appenders BufferingAppenderSkeleton से इनहेरिट) उपयोगकर्ताओं के लिए भयानक प्रदर्शन दे देंगे, भले ही लेआउट वे उपयोग कर रहे बहुत कम है।

Answer 2

क्या यह संभव है कि यह है क्योंकि आप BufferingForwardingAppender में एक प्रारूप का पैटर्न निर्दिष्ट नहीं कर रहे है, लेकिन आप RollingLogFileAppender में हैं इसलिए BufferingForwardingAppender सब कुछ में यह उपयोगकर्ता नाम (% उपयोगकर्ता नाम) सहित उत्पादन

नीचे एक है शामिल है दिलचस्प ब्लॉग आलेख जिसमें पैटर्न लेआउट में विकल्पों की एक सूची है और ऐसा लगता है कि उनमें से कई धीमे के रूप में चिह्नित हैं।

http://www.beefycode.com/post/Log4Net-Tutorial-pt-4-Layouts-and-Patterns.aspx