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/
