• Problems with many log entries

    By Holger Chudek 1 decade ago

    Hi,



    I have been working with DAF on a Domino Server with many agents and had to set the LogLevel to "debug". The scan-agent crashed with some informations concerning about Error 4000 in LiblogAppender on line number 102 (which is a doc.save).

    Looking for the log-Document i see, there are 5500 Fields calling "Messages", so the LogFunctionality will create for each MessageLine a new Field in the Document.



    This is a known error in Richtextitem.appendText since Notes 4.6.



    This also slows the Logging hard down, from 1500 Fields up it lasts for about one Second to make a richtextitem.appendtext and save.



    I will search for some workaround, i think about using richtextfield.compact (just have to test the performance implications) or another way to store the Message in the Richtextfield (without creating new fields) or a threshhold to automatically create a new log-document, say from more than 1000 entries.



    Can anyone prove the behavior of the logging (it will only slow down with a lot of Messages in the log and according to Knowledge base the fields will be joined into one by opening the Document in UI).



    I think the crash comes from 32K limit for Fields in Document, still working on it with a basic test database

    • log4domino

      By Joerg Reck 1 decade ago

      Hello Holger,



      sorry I didn't test the log4domino, I just used it.



      Please can you try the following?



      First in the SL libDBAppender there is a line like -> Call Me.mrtiMessages.AddNewLine( 1 )

      Please change it to -> Call Me.mrtiMessages.AddNewLine( 1, False )



      Run a test agent with the follwing code in the first lines ->

      Set session = New NotesSession<br/>
Set ndtToday = New NotesDateTime(Now)       <br/>
ConfigureAgent session.CurrentDatabase.FilePath, session, False <br/>
Set myLogger = LogCategoryFactory( &quot;&quot;, &quot;ObserveR6&quot; )<br/>
For i = -32000 To 32000<br/>
    Print i<br/>
    If myLogger.isEnabledFor(INFO_INT) Then myLogger.info &quot;Start agent + &quot; + Cstr(i)<br/>
Next<br/>
myLogger.Flush<br/>
Exit Sub<br/>



      Third change in the Log Configuration in the Tab Advanced from Eager to Lazy



      In my 8.5 Client it creates a the log document with 64000 lines and a size from around 4 MB without problems.



      When it works in your environment I will make a new release.



      Greetings JJR



      Code Domain

      • Logging to slow

        By Holger Chudek 1 decade ago

        Hi Joerg,



        thanks for the fast response. I have made some testing for the basic functionalities. Changing from eager to lazy will do it, i guess because the save of the Logentries (and thus the creating of the neccessary richtext-Field) will be made at the end of the logging.



        I created an Agent which only creat one Document and write 7000 entries to a richtext-field. I used first the appendText + save() in the loop, then i used appendText, compact, save in the loop and lst i used append text in the loop and after the looping doing the save. Now the Result :





        ==> Agent with Save() in Loop,

        creating 7000 Richtext-Fields

        using aprox 11 Hours !!!





        CreateRTFieldswithdefinedText Profil



        01.08.2009 05:04:43 CEDT

        Verstrichene Zeit: 38879826 msec

        Profiling dieser Methoden: 5

        Gesamte gemessene Zeit: 38861729 msec

        Klasse Methode Vorgang Aufrufe Uhrzeit

        Document Save 7000 38861097

        RichTextItem AppendText 7000 622

        Database CreateDocument 1 10

        Document CreateRichTextItem 1 0

        Session CurrentDatabase Get 1 0





        Agent 'CreateRTFieldswithdefinedText' wurde am 31.07.2009 18:16:43 gestartet

        LotusScript Code ausgeführt

        Agent 'CreateRTFieldswithdefinedText' wurde am 01.08.2009 05:04:43 beendet







        ==> Agent with Save() after the Loop,

        creating 30 Richtext-Fields with aprox. 30 k Text each

        using aprox. 8 Seconds





        03.08.2009 07:35:16 CEDT

        Verstrichene Zeit: 7832 msec

        Profiling dieser Methoden: 5

        Gesamte gemessene Zeit: 401 msec

        Klasse Methode Vorgang Aufrufe Uhrzeit

        RichTextItem AppendText 7000 351

        Document Save 1 50

        Document CreateRichTextItem 1 0

        Session CurrentDatabase Get 1 0

        Database CreateDocument 1 0





        Agent 'CreateRTFieldswithdefinedText' wurde am 03.08.2009 07:35:09 gestartet

        LotusScript Code ausgeführt

        Agent 'CreateRTFieldswithdefinedText' wurde am 03.08.2009 07:35:16 beendet





        ==> Agent with Compact in the Loop before the Save(),

        creating 30 Richtext-Fields with aprox. 30 k Text each

        using aprox. 90 Seconds





        03.08.2009 07:41:14 CEDT

        Verstrichene Zeit: 100554 msec

        Profiling dieser Methoden: 7

        Gesamte gemessene Zeit: 90497 msec

        Klasse Methode Vorgang Aufrufe Uhrzeit

        Document Save 7000 50337

        RichTextItem Compact 7000 39078

        RichTextItem AppendText 7000 812

        RichTextItem AddNewline 7000 260

        Document CreateRichTextItem 1 10

        Session CurrentDatabase Get 1 0

        Database CreateDocument 1 0





        Agent 'CreateRTFieldswithdefinedText' wurde am 03.08.2009 07:39:33 gestartet

        LotusScript Code ausgeführt

        Agent 'CreateRTFieldswithdefinedText' wurde am 03.08.2009 07:41:14 beendet



        So, appending with save in the same loop will blow the code to run about 11 hours while saving it after the loop will do the same process in about 10 Seconds. I think this is, what the "eager" switch does, it will do the Save (or the flush) not on every line of Logging but at the end (or with calling dediceted the "Flush"-Function).



        Using compact slows the code a little down, but it will use about 2 Minutes which will be ok.



        For my situation in the Project, I am worrying about loosing Log-Informations with using "eager" logging (say, in special case where some error occure in the log-Function itself or a error-condition which isn´t catched by no reasonable cause and do kil the logging without running in the flush-Function), so i will add the "richtextitem.compact" in the Flush-Function.



        I think this will do it best for my situation. I will post a comment to the log4domino-Project to discuss further development for this point. Thanks for your assistance in this case,



        kind regards,



        Holger