Hi Douglas, Yes. OsSysLog is an event based logger using the same mechanism as the SIP Transports for example. Right now it allows for a buffer of max size 1000. The original intention was to probably let the logger not interfere with real time operations. However, the need to duplicate strings just to pass around events as well as the need for semaphores to guard the event queue proves too much for a logger to be consuming. Thus, I needed to back my theory with a series of test proving that a simple none threaded logger might prove more efficient than a queue based implementation. My test shows that event queue would normally lag behind around 300 events in a tight loop doing nothing but logging. If these events are Sip Messages in debug priority then it could take up a bit of heap allocations. the new logger has no need for such queue and prolonged heap allocations are not needed. Thus, the new logger has a flat liner in terms of its memory consumption and surpasses the speed and efficiency of OsSysLog by several folds.
Joegen On 05/05/2011 10:16 AM, Douglas Hubler wrote: > Joegen, > > Nice work. > > Can you describe the impetus in detail for this change to the logger. > I know the high level, but you proved a log buffer was filling up > causing a back-up of sip messages of some sort. Also, have you shown > this issue is now gone with the new logger? > > On Wed, May 4, 2011 at 8:20 PM, Joegen Baclor<[email protected]> wrote: >> A new logger class is now out in git master branch. The goal of the new >> logger is to replace OsSysLog with a more CPU/Memory efficient logger and >> hopefully convert the savings to more CPS in a high load environment. >> Function signatures remains the same as OsSysLog. We still support the old >> c-style logging which accepts a format string. >> >> Example: >> >> Os::Logger::instance().log(FAC_SIP, PRI_DEBUG, >> "SipRouter::proxyMessage " >> " From '%s' is unauthenticated local user >> - challenge for PAI", >> fromUrl.toString().data()); >> >> >> However I advise everyone touching the C++ code to now use the stream based >> version of this function. The above example may be coded as follows >> >> OS_LOG_DEBUG(FAC_SIP, "SipRouter::proxyMessage From "<< >> fromUrl.toString().data()<< " is unauthenticated local user - challenge for >> PAI"); >> >> The following macros are defined >> >> OS_LOG_DEBUG >> OS_LOG_INFO >> OS_LOG_NOTICE >> OS_LOG_WARNING >> OS_LOG_ERROR >> OS_LOG_CRITICAL >> OS_LOG_ALERT >> OS_LOG_EMERGENCY >> >> >> ----------------------------------------------------------------------------------------------------------------------------------------------- >> >> Stress Design: >> >> 1. Os::Logger is assigned 4 threads [x1(), x2(), x3(), x4()] each iterating >> 2.5 M worth of logs lines. Total: 10 M >> 2. OsSysLog is assigned 4 threads [y1(), y2(), y3(), y4()] each iterating >> 2.5 M worth of logs lines. Total: 10 M >> 3. 4 Threads assigned a CPU Hog loop [z1(), z2(), z3(), z4()] >> >> As soon as this code is runs, all of my 4 cores spikes at 100%. >> >> >> Stress Test Metrics: >> >> -- OsSysLog -- >> >> First Entry: >> "2011-04-28T11:53:17.377003Z":4:SIP:DEBUG:braviac4.mysipdomain.ph:pid-6850:E3FFF700:Test-OsSysLog >> Last Entry: >> "2011-04-28T12:04:19.436342Z":10000001:SIP:DEBUG:braviac4.mysipdomain.ph:pid-6850:E27FC700:Test-OsSysLog >> Total Time: 11 mins and 2 seconds >> >> -- Os::Logger -- >> >> First Entry: >> >> "2011-04-28T11:53:17.374691Z":1:PERF:INFO:sipx.ossapp.com:Sample-Task:7ffff203f700:TestLogger >> Last Entry: >> >> "2011-04-28T11:57:09.060341Z":10000000:PERF:INFO:sipx.ossapp.com:Sample-Task: >> Total Time: 3 mins and 54 seconds >> >> >> More findings: I have noticed that OsSysLog doubles its CPU consumption >> when called from 4 separate threads while Os::Logger consumes the same CPU >> rate in single or multi threaded run. >> >> >> Memory Profiling Metrics: >> >> Attached are the results of the mem profiling i did for the new logger. The >> profiling is done using a 20K iteration from each of the loggers. I had to >> make it low because mem profiling is really a very slow process and takes a >> while. Anyway here are the metrics: >> >> OsSysLog: Peaked at 858,728 bytes heap allocations >> OS::Logger: Peaked at 40,120 bytes heap allocations >> >> Attached are the two profile results respectively. This is generated by >> valgrind::massif. You can find the manual here ( >> http://valgrind.org/docs/manual/ms-manual.html ) if you care to read the >> profiles >> >> >> >> _______________________________________________ >> sipx-dev mailing list >> [email protected] >> List Archive: http://list.sipfoundry.org/archive/sipx-dev/ >> > _______________________________________________ > sipx-dev mailing list > [email protected] > List Archive: http://list.sipfoundry.org/archive/sipx-dev/ > _______________________________________________ sipx-dev mailing list [email protected] List Archive: http://list.sipfoundry.org/archive/sipx-dev/
