Profiling for mangos

profile.xml

<region name="default">
	<scope name="World::Update" count="153" recurses="0" time="23036000">
		<region name="default">
			<scope name="World::UpdateSessions" count="153" recurses="0" time="922000"/>
		</region>
	</scope>
</region>

profiling.patch

diff --git a/src/framework/Utilities/Profiling.cpp b/src/framework/Utilities/Profiling.cpp
new file mode 100644
index 0000000..282e391
--- /dev/null
+++ b/src/framework/Utilities/Profiling.cpp
@@ -0,0 +1,180 @@
+/*
+ * Copyright (C) 2005-2011 MaNGOS <http://getmangos.com/>
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
+ */
+
+#include "Profiling.h"
+
+#include <fstream>
+
+static char* sDefaultRegionName = "default";
+static string sTabs = "";
+
+ostream& operator<<(ostream& out, const Region& region)
+{
+    out << sTabs << "<region name=\"" << region.m_name << "\">" << endl;
+
+    sTabs += "\t";
+    for (ScopeMap::const_iterator it = region.m_scopes.begin(); it != region.m_scopes.end(); ++it)
+        out << *it->second;
+    sTabs.pop_back();
+
+    out << sTabs << "</region>" << endl;
+
+    return out;
+}
+
+ostream& operator<<(ostream& out, const Scope& scope)
+{
+    ACE_hrtime_t time;
+    scope.m_time.elapsed_time_incr(time);
+
+    out << sTabs << "<scope name=\"" << scope.m_name << "\" count=\"" << scope.m_count << "\" recurses=\"" << scope.m_recursiveCount << "\" time=\"" << time << "\"";
+
+    if (scope.m_regions.front()->m_scopes.size() > 0)
+    {
+        out << ">" << endl;
+
+        sTabs += "\t";
+        for (RegionList::const_iterator it = scope.m_regions.begin(); it != scope.m_regions.end(); ++it)
+            out << **it;
+        sTabs.pop_back();
+
+        out << sTabs << "</scope>" << endl;
+    }
+    else
+        out << "/>" << endl;
+
+
+    return out;
+}
+
+ScopeTimer::~ScopeTimer()
+{
+    if (m_timer)
+    {
+        m_timer->stop_incr();
+        sProfiler->LeaveScope();
+    }
+}
+
+Region::Region(string name) : m_name(name) { }
+
+Region::~Region()
+{
+    for (ScopeMap::iterator it = m_scopes.begin(); it != m_scopes.end(); ++it)
+    {
+        delete it->second;
+        it->second = NULL;
+    }
+
+    m_scopes.clear();
+}
+
+Scope::Scope(string name, Scope* parent) :
+    m_count(1), m_recursiveCount(0), m_name(name), m_parentScope(parent)
+{
+    m_regions.push_back(new Region(sDefaultRegionName));
+    m_currentRegion = m_regions.begin();
+}
+
+Scope::~Scope()
+{
+    for (RegionList::iterator it = m_regions.begin(); it != m_regions.end(); ++it)
+        delete *it;
+
+    m_regions.clear();
+}
+
+Scope* Scope::EnterScope(string name, Scope* parent)
+{
+    ScopeMap& scopes = (*m_currentRegion)->m_scopes;
+    Scope* scope;
+
+    ScopeMap::iterator it = scopes.find(name);
+    if (it == scopes.end())
+    {
+        scope = new Scope(name, parent);
+        scopes[name] = scope;
+    }
+    else
+    {
+        scope = it->second;
+        scope->m_count++;
+    }
+
+    return scope;
+}
+
+void Profiler::Clear()
+{
+    delete m_rootScope;
+
+    m_rootScope = new Scope("", NULL);
+    m_currentScope = m_rootScope;
+}
+
+void Profiler::EnterRegion(string name)
+{
+    // first look for the region
+    RegionList::iterator it = RegionList::iterator(m_currentScope->m_currentRegion);
+    for (; it != m_currentScope->m_regions.end(); ++it)
+        if (name.compare((*it)->m_name) == 0)
+        {
+            m_currentScope->m_currentRegion = it;
+            return;
+        }
+
+    // region not found, create a new one an insert it after current region's position
+    // then update current region to point to the new region
+    m_currentScope->m_currentRegion = m_currentScope->m_regions.insert(++m_currentScope->m_currentRegion, new Region(name.c_str()));
+}
+
+void Profiler::EnterScope(string name, ScopeTimer& timer)
+{
+    if (m_currentScope == NULL)
+    {
+        m_currentScope = m_rootScope->EnterScope(name, m_rootScope);
+    }
+    else if (name.compare(m_currentScope->m_name) == 0)
+    {
+        m_currentScope->m_recursiveCount++;
+        m_currentScope->m_currentRegion = m_currentScope->m_regions.begin();
+        return;
+    }
+    else
+        m_currentScope = m_currentScope->EnterScope(name, m_currentScope);
+
+    m_currentScope->m_currentRegion = m_currentScope->m_regions.begin();
+
+    timer.m_timer = &m_currentScope->m_time;
+    timer.m_timer->start_incr();
+}
+
+void Profiler::LeaveScope()
+{
+    m_currentScope = m_currentScope->m_parentScope;
+}
+
+void Profiler::DumpToFile(string filepath)
+{
+    fstream out(filepath, fstream::out);
+
+    for (RegionList::const_iterator it = m_rootScope->m_regions.begin(); it != m_rootScope->m_regions.end(); ++it)
+        out << **it;
+
+    out.close();
+}
diff --git a/src/framework/Utilities/Profiling.h b/src/framework/Utilities/Profiling.h
new file mode 100644
index 0000000..1260da4
--- /dev/null
+++ b/src/framework/Utilities/Profiling.h
@@ -0,0 +1,131 @@
+/*
+ * Copyright (C) 2005-2011 MaNGOS <http://getmangos.com/>
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
+ */
+
+#ifndef MANGOS_PROFILING
+#define MANGOS_PROFILING
+
+#include "Platform/Define.h"
+
+#include <ace/High_Res_Timer.h>
+#include <ace/Singleton.h>
+#include <list>
+#include <string>
+
+#include <ostream>
+
+#include "UnorderedMapSet.h"
+
+using namespace std;
+
+class Scope;
+class Region;
+class Profiler;
+
+typedef UNORDERED_MAP<string, Scope*> ScopeMap;
+typedef list<Region*> RegionList;
+
+ostream& operator<<(ostream& out, const Region& region);
+ostream& operator<<(ostream& out, const Scope& scope);
+
+class Region
+{
+private:
+    friend class Scope;
+    friend class Profiler;
+    friend ostream& operator<<(ostream& out, const Region& region);
+    friend ostream& operator<<(ostream& out, const Scope& region);
+
+    string m_name;
+    ScopeMap m_scopes;
+
+public:
+    Region(string name);
+    ~Region();
+};
+
+class ScopeTimer
+{
+private:
+    friend class Profiler;
+
+    ACE_High_Res_Timer* m_timer;
+
+public:
+    ScopeTimer() : m_timer(NULL) { }
+    ~ScopeTimer();
+};
+
+class Scope
+{
+private:
+    friend class Profiler;
+    friend ostream& operator<<(ostream& out, const Scope& scope);
+
+    string m_name;
+    Scope* m_parentScope;
+
+    uint32 m_count;             // number of times this scope has been entered
+    uint32 m_recursiveCount;    // number of times this scope has been re-entered
+    ACE_High_Res_Timer m_time;  // total time spent in this scope
+
+    RegionList m_regions;
+    RegionList::iterator m_currentRegion;
+
+public:
+    Scope(string name, Scope* parent);
+    ~Scope();
+
+    Scope* EnterScope(string name, Scope* parent);
+
+    string GetName() const { return m_name; }
+};
+
+class Profiler
+{
+private:
+    Scope* m_rootScope;
+    Scope* m_currentScope;
+    uint32 m_cycles;
+
+public:
+    Profiler() : m_rootScope(NULL) { Clear(); };
+
+    bool Enabled() const { return true; }
+
+    void EnterRegion(string name);
+    void EnterScope(string name, ScopeTimer& timer);
+    void LeaveScope();
+
+    const Scope* GetRootScope() { return m_rootScope; }
+
+    void Clear();
+    void DumpToFile(string filepath);
+};
+
+#define sProfiler ACE_Singleton<Profiler, ACE_Thread_Mutex>::instance()
+
+#define PROFILE_CURRENT_SCOPE() \
+    ScopeTimer profilerTimer;   \
+    if (sProfiler->Enabled())   \
+        sProfiler->EnterScope(__FUNCTION__, profilerTimer)
+
+#define PROFILE_NEW_REGION(name)        \
+    if (sProfiler->Enabled())           \
+        sProfiler->EnterRegion(name)
+
+#endif MANGOS_PROFILING
diff --git a/src/game/World.cpp b/src/game/World.cpp
index ca8750c..ce54be3 100644
--- a/src/game/World.cpp
+++ b/src/game/World.cpp
@@ -63,6 +63,8 @@
 #include "Util.h"
 #include "CharacterDatabaseCleaner.h"
 
+#include "Utilities/Profiling.h"
+
 INSTANTIATE_SINGLETON_1( World );
 
 volatile bool World::m_stopEvent = false;
@@ -192,6 +194,8 @@ void World::AddSession(WorldSession* s)
 void
 World::AddSession_ (WorldSession* s)
 {
+    PROFILE_CURRENT_SCOPE();
+
     MANGOS_ASSERT (s);
 
     //NOTE - Still there is race condition in WorldSession* being used in the Sockets
@@ -1412,6 +1416,8 @@ void World::DetectDBCLang()
 /// Update the World !
 void World::Update(uint32 diff)
 {
+    PROFILE_CURRENT_SCOPE();
+
     ///- Update the different timers
     for(int i = 0; i < WUPDATE_COUNT; ++i)
     {
@@ -1893,11 +1899,17 @@ void World::SendServerMessage(ServerMessageType type, const char *text, Player*
 
 void World::UpdateSessions( uint32 diff )
 {
+    PROFILE_CURRENT_SCOPE();
+
+    PROFILE_NEW_REGION("AddNewSessions");
+
     ///- Add new sessions
     WorldSession* sess;
     while(addSessQueue.next(sess))
         AddSession_ (sess);
 
+    PROFILE_NEW_REGION("UpdateSessions");
+
     ///- Then send an update signal to remaining ones
     for (SessionMap::iterator itr = m_sessions.begin(), next; itr != m_sessions.end(); itr = next)
     {
diff --git a/src/game/WorldSession.cpp b/src/game/WorldSession.cpp
index 8e4072d..74ecc24 100644
--- a/src/game/WorldSession.cpp
+++ b/src/game/WorldSession.cpp
@@ -40,6 +40,8 @@
 #include "Auth/HMACSHA1.h"
 #include "zlib/zlib.h"
 
+#include "Utilities/Profiling.h"
+
 // select opcodes appropriate for processing in Map::Update context for current session state
 static bool MapSessionFilterHelper(WorldSession* session, OpcodeHandler const& opHandle)
 {
@@ -200,6 +202,8 @@ void WorldSession::LogUnprocessedTail(WorldPacket *packet)
 /// Update the WorldSession (triggered by World update)
 bool WorldSession::Update(PacketFilter& updater)
 {
+    PROFILE_CURRENT_SCOPE();
+
     ///- Retrieve packets from the receive queue and call the appropriate handlers
     /// not process packets if socket already closed
     WorldPacket* packet;
diff --git a/src/mangosd/WorldRunnable.cpp b/src/mangosd/WorldRunnable.cpp
index 133119f..6ab8405 100644
--- a/src/mangosd/WorldRunnable.cpp
+++ b/src/mangosd/WorldRunnable.cpp
@@ -30,6 +30,8 @@
 
 #include "Database/DatabaseEnv.h"
 
+#include "Utilities/Profiling.h"
+
 #define WORLD_SLEEP_CONST 50
 
 #ifdef WIN32
@@ -78,6 +80,9 @@ void WorldRunnable::run()
         #endif
     }
 
+    sProfiler->DumpToFile("C:/profiling.xml");
+    sProfiler->Clear();
+
     sWorld.KickAll();                                       // save and kick all players
     sWorld.UpdateSessions( 1 );                             // real players unload required UpdateSessions call
 
diff --git a/win/VC100/framework.vcxproj b/win/VC100/framework.vcxproj
index 1e05705..785adae 100644
--- a/win/VC100/framework.vcxproj
+++ b/win/VC100/framework.vcxproj
@@ -315,6 +315,7 @@
     <ClInclude Include="..\..\src\framework\Utilities\LinkedList.h" />
     <ClInclude Include="..\..\src\framework\Utilities\LinkedReference\Reference.h" />
     <ClInclude Include="..\..\src\framework\Utilities\LinkedReference\RefManager.h" />
+    <ClInclude Include="..\..\src\framework\Utilities\Profiling.h" />
     <ClInclude Include="..\..\src\framework\Utilities\TypeList.h" />
     <ClInclude Include="..\..\src\framework\Utilities\UnorderedMapSet.h" />
   </ItemGroup>
@@ -322,6 +323,7 @@
     <ClCompile Include="..\..\src\framework\Policies\MemoryManagement.cpp" />
     <ClCompile Include="..\..\src\framework\Policies\ObjectLifeTime.cpp" />
     <ClCompile Include="..\..\src\framework\Utilities\EventProcessor.cpp" />
+    <ClCompile Include="..\..\src\framework\Utilities\Profiling.cpp" />
   </ItemGroup>
   <Import Project="$(VCTargetsPath)\Microsoft.Cpp.targets" />
   <ImportGroup Label="ExtensionTargets">
diff --git a/win/VC100/framework.vcxproj.filters b/win/VC100/framework.vcxproj.filters
index e602d28..2f9940e 100644
--- a/win/VC100/framework.vcxproj.filters
+++ b/win/VC100/framework.vcxproj.filters
@@ -96,6 +96,9 @@
     <ClInclude Include="..\..\src\framework\Dynamic\ObjectRegistry.h">
       <Filter>Dynamic</Filter>
     </ClInclude>
+    <ClInclude Include="..\..\src\framework\Utilities\Profiling.h">
+      <Filter>Utilities</Filter>
+    </ClInclude>
   </ItemGroup>
   <ItemGroup>
     <ClCompile Include="..\..\src\framework\Policies\MemoryManagement.cpp">
@@ -107,5 +110,8 @@
     <ClCompile Include="..\..\src\framework\Utilities\EventProcessor.cpp">
       <Filter>Utilities</Filter>
     </ClCompile>
+    <ClCompile Include="..\..\src\framework\Utilities\Profiling.cpp">
+      <Filter>Utilities</Filter>
+    </ClCompile>
   </ItemGroup>
 </Project>
\ No newline at end of file