Added a profiler and investageted Server.

6 files changed, 288 insertions, 1 deletions

diff --git a/src/stable/client.cpp b/src/stable/client.cpp
index f6feb7c..56c5094 100644
--- a/src/stable/client.cpp
+++ b/src/stable/client.cpp
@@ -16,6 +16,13 @@
 
 /** Read buffer size. */
 #define RBS     (2000) // 1500 is the nominal MTU for ethernet, it's a good guess
+#ifdef PROFILE_BU_SERVER
+#define BU_PROFILE_START( x ) Bu::Profiler::getInstance().startEvent( x )
+#define BU_PROFILE_END( x ) Bu::Profiler::getInstance().endEvent( x )
+#else
+#define BU_PROFILE_START( x ) (void)0
+#define BU_PROFILE_END( x ) (void)0
+#endif
 
 Bu::Client::Client( Bu::TcpSocket *pSocket,
         class Bu::ClientLinkFactory *pfLink ) :
@@ -47,6 +54,7 @@ void Bu::Client::processInput()
     char buf[RBS];
     Bu::size nRead, nTotal=0;
 
+    BU_PROFILE_START("client.read");
     for(;;)
     {
         try
@@ -72,6 +80,7 @@ void Bu::Client::processInput()
             break;
         }
     }
+    BU_PROFILE_END("client.read");
     mRead.unlock();
 
     if( nTotal == 0 )
@@ -82,7 +91,9 @@ void Bu::Client::processInput()
 
     if( pProto && nTotal )
     {
+        BU_PROFILE_START("client.process");
         pProto->onNewData( this );
+        BU_PROFILE_END("client.process");
     }
 }
 
diff --git a/src/stable/client.h b/src/stable/client.h
index 119e2f7..abde682 100644
--- a/src/stable/client.h
+++ b/src/stable/client.h
@@ -16,6 +16,14 @@
 #include "bu/mutex.h"
 #include "bu/readwritemutex.h"
 
+#ifndef PROFILE_BU_SERVER
+// #define PROFILE_BU_SERVER   1
+#endif
+
+#ifdef PROFILE_BU_SERVER
+#include "bu/profiler.h"
+#endif
+
 namespace Bu
 {
     class Protocol;
@@ -29,7 +37,7 @@ namespace Bu
     class Client : public Bu::Stream
     {
     public:
-        Client( Bu::TcpSocket *pSocket, Bu::ClientLinkFactory *pfLink );
+        Client( Bu::TcpSocket *pSocket, Bu::ClientLinkFactory *pfLink);
         virtual ~Client();
 
         void processInput();
diff --git a/src/stable/server.cpp b/src/stable/server.cpp
index 3c42bf4..0552510 100644
--- a/src/stable/server.cpp
+++ b/src/stable/server.cpp
@@ -13,17 +13,27 @@
 #include "bu/tcpsocket.h"
 #include "bu/config.h"
 
+#ifdef PROFILE_BU_SERVER
+#define BU_PROFILE_START( x ) Bu::Profiler::getInstance().startEvent( x )
+#define BU_PROFILE_END( x ) Bu::Profiler::getInstance().endEvent( x )
+#else
+#define BU_PROFILE_START( x ) (void)0
+#define BU_PROFILE_END( x ) (void)0
+#endif
+
 Bu::Server::Server() :
     nTimeoutSec( 0 ),
     nTimeoutUSec( 0 ),
     bAutoTick( false )
 {
+    BU_PROFILE_START("server");
     FD_ZERO( &fdActive );
 }
 
 Bu::Server::~Server()
 {
     shutdown();
+    BU_PROFILE_START("server");
 }
 
 void Bu::Server::addPort( int nPort, int nPoolSize )
@@ -50,6 +60,7 @@ void Bu::Server::setTimeout( int nTimeoutSec, int nTimeoutUSec )
 
 void Bu::Server::scan()
 {
+    BU_PROFILE_START("scan");
     struct timeval xTimeout = { nTimeoutSec, nTimeoutUSec };
     
     fd_set fdRead = fdActive;
@@ -68,6 +79,7 @@ void Bu::Server::scan()
     {
         char buf[1024];
         strerror_r( errno, buf, 1024 );
+        BU_PROFILE_END("scan");
         throw ExceptionBase(
             Bu::String("Error attempting to scan open connections: %1: %2").arg( errno ).arg( buf ).end().getStr()
             );
@@ -85,7 +97,9 @@ void Bu::Server::scan()
             else
             {
                 Client *pClient = hClients.get( j );
+                BU_PROFILE_START("processInput");
                 pClient->processInput();
+                BU_PROFILE_END("processInput");
                 if( !pClient->isOpen() )
                 {
                     closeClient( j );
@@ -99,7 +113,9 @@ void Bu::Server::scan()
                 Client *pClient = hClients.get( j );
                 try
                 {
+                    BU_PROFILE_START("processOutput");
                     pClient->processOutput();
+                    BU_PROFILE_END("processOutput");
                 }
                 catch( Bu::TcpSocketException &e )
                 {
@@ -133,10 +149,13 @@ void Bu::Server::scan()
 
     if( bAutoTick )
         tick();
+
+    BU_PROFILE_END("scan");
 }
 
 void Bu::Server::addClient( socket_t nSocket, int nPort )
 {
+    BU_PROFILE_START("addClient");
     FD_SET( nSocket, &fdActive );
 
     Client *c = new Client(
@@ -146,6 +165,7 @@ void Bu::Server::addClient( socket_t nSocket, int nPort )
     hClients.insert( nSocket, c );
 
     onNewConnection( c, nPort );
+    BU_PROFILE_END("addClient");
 }
 
 Bu::Server::SrvClientLink::SrvClientLink( Bu::Client *pClient ) :
@@ -208,11 +228,13 @@ void Bu::Server::shutdown()
 
 void Bu::Server::closeClient( socket_t iSocket )
 {
+    BU_PROFILE_START("closeClient");
     Bu::Client *pClient = hClients.get( iSocket );
     onClosedConnection( pClient );
     pClient->close();
     hClients.erase( iSocket );
     FD_CLR( iSocket, &fdActive );
     delete pClient;
+    BU_PROFILE_END("closeClient");
 }
 
diff --git a/src/stable/server.h b/src/stable/server.h
index ee76fd2..d3f0903 100644
--- a/src/stable/server.h
+++ b/src/stable/server.h
@@ -23,6 +23,14 @@
 
 #include "bu/config.h"
 
+#ifndef PROFILE_BU_SERVER
+// #define PROFILE_BU_SERVER   1
+#endif
+
+#ifdef PROFILE_BU_SERVER
+#include "bu/profiler.h"
+#endif
+
 namespace Bu
 {
     class TcpServerSocket;
diff --git a/src/unstable/profiler.cpp b/src/unstable/profiler.cpp
new file mode 100644
index 0000000..1b176b9
--- /dev/null
+++ b/src/unstable/profiler.cpp
@@ -0,0 +1,184 @@
+#include "bu/profiler.h"
+#include "bu/mutexlocker.h"
+#include "bu/sio.h"
+
+#include <sys/time.h>
+
+Bu::Profiler::Profiler()
+{
+}
+
+Bu::Profiler::~Profiler()
+{
+    printReport();
+}
+
+uint64_t Bu::Profiler::getMicroTime()
+{
+    struct timeval tv;
+    gettimeofday( &tv, NULL );
+    return ((uint64_t)tv.tv_sec)*1000000 + ((uint64_t)tv.tv_usec);
+}
+
+void Bu::Profiler::startEvent( const Bu::Blob &bName )
+{
+    Bu::MutexLocker l( mLock );
+    if( hEvent.has( bName ) )
+    {
+        hEvent.get( bName ).append( Event() );
+    }
+    else
+    {
+        hEvent.insert( bName, EventList( Event() ) );
+    }
+}
+
+void Bu::Profiler::endEvent( const Bu::Blob &bName )
+{
+    Bu::MutexLocker l( mLock );
+    if( !hEvent.has( bName ) )
+        return;
+
+    if( hEvent.get( bName ).isEmpty() )
+        return;
+
+    hEvent.get( bName ).last().end();
+}
+
+void Bu::Profiler::printReport() const
+{
+    class Breakdown
+    {
+    public:
+        Breakdown( const Bu::Blob &bName ) :
+            bName( bName ), uCount( 0 ), uTotal( 0 ), uMin( 0 ), uMax( 0 ) { }
+        Breakdown( const Breakdown &rSrc ) :
+            bName( rSrc.bName ), uCount( rSrc.uCount ), uTotal( rSrc.uTotal ),
+            uMin( rSrc.uMin ), uMax( rSrc.uMax ) { }
+        ~Breakdown() { }
+
+        bool operator<( const Breakdown &rhs ) const
+        {
+            return uTotal > rhs.uTotal;
+        }
+        Breakdown &operator=( const Breakdown &rhs )
+        {
+            bName = rhs.bName;
+            uCount = rhs.uCount;
+            uTotal = rhs.uTotal;
+            uMin = rhs.uMin;
+            uMax = rhs.uMax;
+            return *this;
+        }
+        
+        void add( uint64_t uSpan )
+        {
+            if( uCount == 0 )
+            {
+                uMin = uMax = uSpan;
+            }
+            else
+            {
+                if( uMin > uSpan )
+                    uMin = uSpan;
+                if( uMax < uSpan )
+                    uMax = uSpan;
+
+            }
+            uCount++;
+            uTotal += uSpan;
+        }
+
+        Bu::Blob bName;
+        uint64_t uCount;
+        uint64_t uTotal;
+        uint64_t uMin;
+        uint64_t uMax;
+    };
+    Bu::MutexLocker l( mLock );
+
+    int iTitleLen = 0;
+    Bu::List<Breakdown> lBreakdown;
+    for( EventListHash::const_iterator iType = hEvent.begin(); iType; iType++ )
+    {
+        Breakdown b( iType.getKey() );
+        if( iTitleLen < b.bName.getSize() )
+            iTitleLen = b.bName.getSize();
+        for( EventList::const_iterator iEv = iType.getValue().begin();
+                iEv; iEv++ )
+        {
+            b.add( (*iEv).getSpan() );
+        }
+        lBreakdown.append( b );
+    }
+
+    lBreakdown.sort();
+
+    Bu::println("%1 %2 %3 %4 %5 %6")
+        .arg("Title",   Bu::Fmt(iTitleLen) )
+        .arg("Cnt",     Bu::Fmt(5) )
+        .arg("Total",   Bu::Fmt(9) )
+        .arg("Avg",     Bu::Fmt(9) )
+        .arg("Max",     Bu::Fmt(9) )
+        .arg("Min",     Bu::Fmt(9) );
+    for( Bu::List<Breakdown>::iterator i = lBreakdown.begin(); i; i++ )
+    {
+        Bu::println("%1 %2 %3.%4 %5.%6 %7.%8 %9.%10")
+            .arg( (*i).bName.getData(), Bu::Fmt(iTitleLen) )
+            .arg( (*i).uCount, Bu::Fmt(5) )
+            .arg( ((*i).uTotal/1000000), Bu::Fmt(5).right() )
+            .arg( ((*i).uTotal/1000)%1000, Bu::Fmt(3).fill('0').right() )
+            .arg( ((*i).uTotal/(*i).uCount)/1000000, Bu::Fmt(5).right() )
+            .arg( (((*i).uTotal/(*i).uCount)/1000)%1000, Bu::Fmt(3).right().fill('0') )
+            .arg( (*i).uMax/1000000, Bu::Fmt(5).right() )
+            .arg( ((*i).uMax/1000)%1000, Bu::Fmt(3).right().fill('0') )
+            .arg( (*i).uMin/1000000, Bu::Fmt(5).right() )
+            .arg( ((*i).uMin/1000)%1000, Bu::Fmt(3).right().fill('0') )
+            ;
+    }
+}
+
+Bu::Profiler::Event::Event() :
+    iStart( Bu::Profiler::getMicroTime() ),
+    iStop( 0 )
+{
+}
+
+Bu::Profiler::Event::Event( const Event &rSrc ) :
+    iStart( rSrc.iStart ),
+    iStop( rSrc.iStop )
+{
+}
+
+Bu::Profiler::Event::~Event()
+{
+}
+
+void Bu::Profiler::Event::end()
+{
+    if( iStop == 0 )
+        iStop = Bu::Profiler::getMicroTime();
+}
+
+bool Bu::Profiler::Event::hasEnded() const
+{
+    return iStop != 0;
+}
+
+uint64_t Bu::Profiler::Event::getStart() const
+{
+    return iStart;
+}
+
+uint64_t Bu::Profiler::Event::getEnd() const
+{
+    return iStop;
+}
+
+uint64_t Bu::Profiler::Event::getSpan() const
+{
+    if( iStop < iStart )
+        return 0;
+    return iStop-iStart;
+}
+
diff --git a/src/unstable/profiler.h b/src/unstable/profiler.h
new file mode 100644
index 0000000..df05023
--- /dev/null
+++ b/src/unstable/profiler.h
@@ -0,0 +1,54 @@
+#ifndef BU_PROFILER_H
+#define BU_PROFILER_H
+
+#include "bu/blob.h"
+#include "bu/hash.h"
+#include "bu/list.h"
+#include "bu/mutex.h"
+#include "bu/singleton.h"
+
+namespace Bu
+{
+    class Profiler : public Bu::Singleton<Profiler>
+    {
+    friend class Bu::Singleton<Profiler>;
+    private:
+        Profiler();
+        virtual ~Profiler();
+
+    public:
+        static uint64_t getMicroTime();
+
+        void startEvent( const Bu::Blob &bName );
+        void endEvent( const Bu::Blob &bName );
+
+        void printReport() const;
+
+    private:
+        class Event
+        {
+        public:
+            Event();
+            Event( const Event &rSrc );
+            ~Event();
+
+            void end();
+            bool hasEnded() const;
+
+            uint64_t getStart() const;
+            uint64_t getEnd() const;
+            uint64_t getSpan() const;
+
+        private:
+            uint64_t iStart;
+            uint64_t iStop;
+        };
+
+        typedef Bu::List<Event> EventList;
+        typedef Bu::Hash<Bu::Blob, EventList> EventListHash;
+        EventListHash hEvent;
+        mutable Bu::Mutex mLock;
+    };
+};
+
+#endif