LCOV - code coverage report
Current view: top level - source/ps - Profiler2.cpp (source / functions) Hit Total Coverage
Test: 0 A.D. test coverage report Lines: 83 526 15.8 %
Date: 2022-06-14 00:41:00 Functions: 12 46 26.1 %

          Line data    Source code
       1             : /* Copyright (C) 2021 Wildfire Games.
       2             :  *
       3             :  * Permission is hereby granted, free of charge, to any person obtaining
       4             :  * a copy of this software and associated documentation files (the
       5             :  * "Software"), to deal in the Software without restriction, including
       6             :  * without limitation the rights to use, copy, modify, merge, publish,
       7             :  * distribute, sublicense, and/or sell copies of the Software, and to
       8             :  * permit persons to whom the Software is furnished to do so, subject to
       9             :  * the following conditions:
      10             :  *
      11             :  * The above copyright notice and this permission notice shall be included
      12             :  * in all copies or substantial portions of the Software.
      13             :  *
      14             :  * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
      15             :  * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
      16             :  * MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.
      17             :  * IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY
      18             :  * CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT,
      19             :  * TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE
      20             :  * SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
      21             :  */
      22             : 
      23             : #include "precompiled.h"
      24             : 
      25             : #include "Profiler2.h"
      26             : 
      27             : #include "lib/allocators/shared_ptr.h"
      28             : #include "lib/os_path.h"
      29             : #include "ps/CLogger.h"
      30             : #include "ps/ConfigDB.h"
      31             : #include "ps/CStr.h"
      32             : #include "ps/Profiler2GPU.h"
      33             : #include "ps/Pyrogenesis.h"
      34             : #include "third_party/mongoose/mongoose.h"
      35             : 
      36             : #include <fstream>
      37             : #include <iomanip>
      38             : #include <map>
      39             : #include <set>
      40             : #include <tuple>
      41             : #include <unordered_map>
      42             : 
      43             : CProfiler2 g_Profiler2;
      44             : 
      45             : const size_t CProfiler2::MAX_ATTRIBUTE_LENGTH = 256;
      46             : 
      47             : // TODO: what's a good size?
      48             : const size_t CProfiler2::BUFFER_SIZE = 4 * 1024 * 1024;
      49             : const size_t CProfiler2::HOLD_BUFFER_SIZE = 128 * 1024;
      50             : 
      51             : // A human-recognisable pattern (for debugging) followed by random bytes (for uniqueness)
      52             : const u8 CProfiler2::RESYNC_MAGIC[8] = {0x11, 0x22, 0x33, 0x44, 0xf4, 0x93, 0xbe, 0x15};
      53             : 
      54             : thread_local CProfiler2::ThreadStorage* CProfiler2::m_CurrentStorage = nullptr;
      55             : 
      56           0 : CProfiler2::CProfiler2() :
      57           0 :     m_Initialised(false), m_FrameNumber(0), m_MgContext(NULL), m_GPU(NULL)
      58             : {
      59           0 : }
      60             : 
      61           1 : CProfiler2::~CProfiler2()
      62             : {
      63           1 :     if (m_Initialised)
      64           0 :         Shutdown();
      65           1 : }
      66             : 
      67             : /**
      68             :  * Mongoose callback. Run in an arbitrary thread (possibly concurrently with other requests).
      69             :  */
      70           0 : static void* MgCallback(mg_event event, struct mg_connection *conn, const struct mg_request_info *request_info)
      71             : {
      72           0 :     CProfiler2* profiler = (CProfiler2*)request_info->user_data;
      73           0 :     ENSURE(profiler);
      74             : 
      75           0 :     void* handled = (void*)""; // arbitrary non-NULL pointer to indicate successful handling
      76             : 
      77           0 :     const char* header200 =
      78             :         "HTTP/1.1 200 OK\r\n"
      79             :         "Access-Control-Allow-Origin: *\r\n" // TODO: not great for security
      80             :         "Content-Type: text/plain; charset=utf-8\r\n\r\n";
      81             : 
      82           0 :     const char* header404 =
      83             :         "HTTP/1.1 404 Not Found\r\n"
      84             :         "Content-Type: text/plain; charset=utf-8\r\n\r\n"
      85             :         "Unrecognised URI";
      86             : 
      87           0 :     const char* header400 =
      88             :         "HTTP/1.1 400 Bad Request\r\n"
      89             :         "Content-Type: text/plain; charset=utf-8\r\n\r\n"
      90             :         "Invalid request";
      91             : 
      92           0 :     switch (event)
      93             :     {
      94           0 :     case MG_NEW_REQUEST:
      95           0 :     {
      96           0 :         std::stringstream stream;
      97             : 
      98           0 :         std::string uri = request_info->uri;
      99             : 
     100           0 :         if (uri == "/download")
     101             :         {
     102           0 :             profiler->SaveToFile();
     103             :         }
     104           0 :         else if (uri == "/overview")
     105             :         {
     106           0 :             profiler->ConstructJSONOverview(stream);
     107             :         }
     108           0 :         else if (uri == "/query")
     109             :         {
     110           0 :             if (!request_info->query_string)
     111             :             {
     112           0 :                 mg_printf(conn, "%s (no query string)", header400);
     113           0 :                 return handled;
     114             :             }
     115             : 
     116             :             // Identify the requested thread
     117           0 :             char buf[256];
     118           0 :             int len = mg_get_var(request_info->query_string, strlen(request_info->query_string), "thread", buf, ARRAY_SIZE(buf));
     119           0 :             if (len < 0)
     120             :             {
     121           0 :                 mg_printf(conn, "%s (no 'thread')", header400);
     122             :                 return handled;
     123             :             }
     124           0 :             std::string thread(buf);
     125             : 
     126           0 :             const char* err = profiler->ConstructJSONResponse(stream, thread);
     127           0 :             if (err)
     128             :             {
     129           0 :                 mg_printf(conn, "%s (%s)", header400, err);
     130           0 :                 return handled;
     131             :             }
     132             :         }
     133             :         else
     134             :         {
     135           0 :             mg_printf(conn, "%s", header404);
     136             :             return handled;
     137             :         }
     138             : 
     139           0 :         mg_printf(conn, "%s", header200);
     140           0 :         std::string str = stream.str();
     141           0 :         mg_write(conn, str.c_str(), str.length());
     142           0 :         return handled;
     143             :     }
     144             : 
     145             :     case MG_HTTP_ERROR:
     146             :         return NULL;
     147             : 
     148           0 :     case MG_EVENT_LOG:
     149             :         // Called by Mongoose's cry()
     150           0 :         LOGERROR("Mongoose error: %s", request_info->log_message);
     151           0 :         return NULL;
     152             : 
     153             :     case MG_INIT_SSL:
     154             :         return NULL;
     155             : 
     156           0 :     default:
     157           0 :         debug_warn(L"Invalid Mongoose event type");
     158             :         return NULL;
     159             :     }
     160             : };
     161             : 
     162           1 : void CProfiler2::Initialise()
     163             : {
     164           1 :     ENSURE(!m_Initialised);
     165           1 :     m_Initialised = true;
     166             : 
     167           2 :     RegisterCurrentThread("main");
     168           1 : }
     169             : 
     170           0 : void CProfiler2::InitialiseGPU()
     171             : {
     172           0 :     ENSURE(!m_GPU);
     173           0 :     m_GPU = new CProfiler2GPU(*this);
     174           0 : }
     175             : 
     176           0 : void CProfiler2::EnableHTTP()
     177             : {
     178           0 :     ENSURE(m_Initialised);
     179           0 :     LOGMESSAGERENDER("Starting profiler2 HTTP server");
     180             : 
     181             :     // Ignore multiple enablings
     182           0 :     if (m_MgContext)
     183           0 :         return;
     184             : 
     185           0 :     CStr listeningPort = "8000";
     186           0 :     CStr listeningServer = "127.0.0.1";
     187           0 :     CStr numThreads = "6";
     188           0 :     if (CConfigDB::IsInitialised())
     189             :     {
     190           0 :         CFG_GET_VAL("profiler2.server.port", listeningPort);
     191           0 :         CFG_GET_VAL("profiler2.server", listeningServer);
     192           0 :         CFG_GET_VAL("profiler2.server.threads", numThreads);
     193             :     }
     194             : 
     195           0 :     std::string listening_ports = fmt::format("{0}:{1}", listeningServer, listeningPort);
     196           0 :     const char* options[] = {
     197           0 :         "listening_ports", listening_ports.c_str(),
     198           0 :         "num_threads", numThreads.c_str(),
     199             :         nullptr
     200           0 :     };
     201           0 :     m_MgContext = mg_start(MgCallback, this, options);
     202           0 :     ENSURE(m_MgContext);
     203             : }
     204             : 
     205           0 : void CProfiler2::EnableGPU()
     206             : {
     207           0 :     ENSURE(m_Initialised);
     208           0 :     if (!m_GPU)
     209             :     {
     210           0 :         LOGMESSAGERENDER("Starting profiler2 GPU mode");
     211           0 :         InitialiseGPU();
     212             :     }
     213           0 : }
     214             : 
     215           0 : void CProfiler2::ShutdownGPU()
     216             : {
     217           0 :     LOGMESSAGERENDER("Shutting down profiler2 GPU mode");
     218           0 :     SAFE_DELETE(m_GPU);
     219           0 : }
     220             : 
     221           0 : void CProfiler2::ShutDownHTTP()
     222             : {
     223           0 :     LOGMESSAGERENDER("Shutting down profiler2 HTTP server");
     224           0 :     if (m_MgContext)
     225             :     {
     226           0 :         mg_stop(m_MgContext);
     227           0 :         m_MgContext = NULL;
     228             :     }
     229           0 : }
     230             : 
     231           0 : void CProfiler2::Toggle()
     232             : {
     233             :     // TODO: Maybe we can open the browser to the profiler page automatically
     234           0 :     if (m_GPU && m_MgContext)
     235             :     {
     236           0 :         ShutdownGPU();
     237           0 :         ShutDownHTTP();
     238             :     }
     239           0 :     else if (!m_GPU && !m_MgContext)
     240             :     {
     241           0 :         EnableGPU();
     242           0 :         EnableHTTP();
     243             :     }
     244           0 : }
     245             : 
     246           1 : void CProfiler2::Shutdown()
     247             : {
     248           1 :     ENSURE(m_Initialised);
     249             : 
     250           1 :     ENSURE(!m_GPU); // must shutdown GPU before profiler
     251             : 
     252           1 :     if (m_MgContext)
     253             :     {
     254           0 :         mg_stop(m_MgContext);
     255           0 :         m_MgContext = NULL;
     256             :     }
     257             : 
     258             :     // the destructor is not called for the main thread
     259             :     // we have to call it manually to avoid memory leaks
     260           1 :     ENSURE(Threading::IsMainThread());
     261           1 :     m_Initialised = false;
     262           1 : }
     263             : 
     264           0 : void CProfiler2::RecordGPUFrameStart()
     265             : {
     266           0 :     if (m_GPU)
     267           0 :         m_GPU->FrameStart();
     268           0 : }
     269             : 
     270           0 : void CProfiler2::RecordGPUFrameEnd()
     271             : {
     272           0 :     if (m_GPU)
     273           0 :         m_GPU->FrameEnd();
     274           0 : }
     275             : 
     276           0 : void CProfiler2::RecordGPURegionEnter(const char* id)
     277             : {
     278           0 :     if (m_GPU)
     279           0 :         m_GPU->RegionEnter(id);
     280           0 : }
     281             : 
     282           0 : void CProfiler2::RecordGPURegionLeave(const char* id)
     283             : {
     284           0 :     if (m_GPU)
     285           0 :         m_GPU->RegionLeave(id);
     286           0 : }
     287             : 
     288          14 : void CProfiler2::RegisterCurrentThread(const std::string& name)
     289             : {
     290          14 :     ENSURE(m_Initialised);
     291             : 
     292             :     // Must not register a thread more than once.
     293          14 :     ENSURE(m_CurrentStorage == nullptr);
     294             : 
     295          14 :     m_CurrentStorage = new ThreadStorage(*this, name);
     296          14 :     AddThreadStorage(m_CurrentStorage);
     297             : 
     298          14 :     RecordSyncMarker();
     299          14 :     RecordEvent("thread start");
     300          14 : }
     301             : 
     302          14 : void CProfiler2::AddThreadStorage(ThreadStorage* storage)
     303             : {
     304          14 :     std::lock_guard<std::mutex> lock(m_Mutex);
     305          28 :     m_Threads.push_back(std::unique_ptr<ThreadStorage>(storage));
     306          14 : }
     307             : 
     308           0 : void CProfiler2::RemoveThreadStorage(ThreadStorage* storage)
     309             : {
     310           0 :     std::lock_guard<std::mutex> lock(m_Mutex);
     311           0 :     m_Threads.erase(std::find_if(m_Threads.begin(), m_Threads.end(), [storage](const std::unique_ptr<ThreadStorage>& s) { return s.get() == storage; }));
     312           0 : }
     313             : 
     314          14 : CProfiler2::ThreadStorage::ThreadStorage(CProfiler2& profiler, const std::string& name) :
     315         126 : m_Profiler(profiler), m_Name(name), m_BufferPos0(0), m_BufferPos1(0), m_LastTime(timer_Time()), m_HeldDepth(0)
     316             : {
     317          14 :     m_Buffer = new u8[BUFFER_SIZE];
     318          14 :     memset(m_Buffer, ITEM_NOP, BUFFER_SIZE);
     319          14 : }
     320             : 
     321         126 : CProfiler2::ThreadStorage::~ThreadStorage()
     322             : {
     323          14 :     delete[] m_Buffer;
     324          14 : }
     325             : 
     326        1455 : void CProfiler2::ThreadStorage::Write(EItem type, const void* item, u32 itemSize)
     327             : {
     328        1455 :     if (m_HeldDepth > 0)
     329             :     {
     330         354 :         WriteHold(type, item, itemSize);
     331         354 :         return;
     332             :     }
     333             :     // See m_BufferPos0 etc for comments on synchronisation
     334             : 
     335        1101 :     u32 size = 1 + itemSize;
     336        1101 :     u32 start = m_BufferPos0;
     337        1101 :     if (start + size > BUFFER_SIZE)
     338             :     {
     339             :         // The remainder of the buffer is too small - fill the rest
     340             :         // with NOPs then start from offset 0, so we don't have to
     341             :         // bother splitting the real item across the end of the buffer
     342             : 
     343           0 :         m_BufferPos0 = size;
     344           0 :         COMPILER_FENCE; // must write m_BufferPos0 before m_Buffer
     345             : 
     346           0 :         memset(m_Buffer + start, 0, BUFFER_SIZE - start);
     347           0 :         start = 0;
     348             :     }
     349             :     else
     350             :     {
     351        1101 :         m_BufferPos0 = start + size;
     352        1101 :         COMPILER_FENCE; // must write m_BufferPos0 before m_Buffer
     353             :     }
     354             : 
     355        1101 :     m_Buffer[start] = (u8)type;
     356        1101 :     memcpy(&m_Buffer[start + 1], item, itemSize);
     357             : 
     358        1101 :     COMPILER_FENCE; // must write m_BufferPos1 after m_Buffer
     359        1101 :     m_BufferPos1 = start + size;
     360             : }
     361             : 
     362         354 : void CProfiler2::ThreadStorage::WriteHold(EItem type, const void* item, u32 itemSize)
     363             : {
     364         354 :     u32 size = 1 + itemSize;
     365             : 
     366         354 :     if (m_HoldBuffers[m_HeldDepth - 1].pos + size > CProfiler2::HOLD_BUFFER_SIZE)
     367             :         return; // we held on too much data, ignore the rest
     368             : 
     369         354 :     m_HoldBuffers[m_HeldDepth - 1].buffer[m_HoldBuffers[m_HeldDepth - 1].pos] = (u8)type;
     370         354 :     memcpy(&m_HoldBuffers[m_HeldDepth - 1].buffer[m_HoldBuffers[m_HeldDepth - 1].pos + 1], item, itemSize);
     371             : 
     372         354 :     m_HoldBuffers[m_HeldDepth - 1].pos += size;
     373             : }
     374             : 
     375           0 : std::string CProfiler2::ThreadStorage::GetBuffer()
     376             : {
     377             :     // Called from an arbitrary thread (not the one writing to the buffer).
     378             :     //
     379             :     // See comments on m_BufferPos0 etc.
     380             : 
     381           0 :     std::shared_ptr<u8> buffer(new u8[BUFFER_SIZE], ArrayDeleter());
     382             : 
     383           0 :     u32 pos1 = m_BufferPos1;
     384           0 :     COMPILER_FENCE; // must read m_BufferPos1 before m_Buffer
     385             : 
     386           0 :     memcpy(buffer.get(), m_Buffer, BUFFER_SIZE);
     387             : 
     388           0 :     COMPILER_FENCE; // must read m_BufferPos0 after m_Buffer
     389           0 :     u32 pos0 = m_BufferPos0;
     390             : 
     391             :     // The range [pos1, pos0) modulo BUFFER_SIZE is invalid, so concatenate the rest of the buffer
     392             : 
     393           0 :     if (pos1 <= pos0) // invalid range is in the middle of the buffer
     394           0 :         return std::string(buffer.get()+pos0, buffer.get()+BUFFER_SIZE) + std::string(buffer.get(), buffer.get()+pos1);
     395             :     else // invalid wrap is wrapped around the end/start buffer
     396           0 :         return std::string(buffer.get()+pos0, buffer.get()+pos1);
     397             : }
     398             : 
     399         137 : void CProfiler2::ThreadStorage::RecordAttribute(const char* fmt, va_list argp)
     400             : {
     401         137 :     char buffer[MAX_ATTRIBUTE_LENGTH + 4] = {0}; // first 4 bytes are used for storing length
     402         137 :     int len = vsnprintf(buffer + 4, MAX_ATTRIBUTE_LENGTH - 1, fmt, argp); // subtract 1 from length to make MSVC vsnprintf safe
     403             :     // (Don't use vsprintf_s because it treats overflow as fatal)
     404             : 
     405             :     // Terminate the string if the printing was truncated
     406         137 :     if (len < 0 || len >= (int)MAX_ATTRIBUTE_LENGTH - 1)
     407             :     {
     408           0 :         strncpy(buffer + 4 + MAX_ATTRIBUTE_LENGTH - 4, "...", 4);
     409           0 :         len = MAX_ATTRIBUTE_LENGTH - 1; // excluding null terminator
     410             :     }
     411             : 
     412             :     // Store the length in the buffer
     413         137 :     memcpy(buffer, &len, sizeof(len));
     414             : 
     415         137 :     Write(ITEM_ATTRIBUTE, buffer, 4 + len);
     416         137 : }
     417             : 
     418           0 : size_t CProfiler2::ThreadStorage::HoldLevel()
     419             : {
     420         118 :     return m_HeldDepth;
     421             : }
     422             : 
     423           0 : u8 CProfiler2::ThreadStorage::HoldType()
     424             : {
     425         118 :     return m_HoldBuffers[m_HeldDepth - 1].type;
     426             : }
     427             : 
     428           0 : void CProfiler2::ThreadStorage::PutOnHold(u8 newType)
     429             : {
     430         118 :     m_HeldDepth++;
     431         118 :     m_HoldBuffers[m_HeldDepth - 1].clear();
     432         236 :     m_HoldBuffers[m_HeldDepth - 1].setType(newType);
     433           0 : }
     434             : 
     435             : // this flattens the stack, use it sensibly
     436           0 : void rewriteBuffer(u8* buffer, u32& bufferSize)
     437             : {
     438           0 :     double startTime = timer_Time();
     439             : 
     440           0 :     u32 size = bufferSize;
     441           0 :     u32 readPos = 0;
     442             : 
     443           0 :     double initialTime = -1;
     444           0 :     double total_time = -1;
     445           0 :     const char* regionName;
     446           0 :     std::set<std::string> topLevelArgs;
     447             : 
     448           0 :     using infoPerType = std::tuple<const char*, double, std::set<std::string> >;
     449           0 :     using timeByTypeMap = std::unordered_map<std::string, infoPerType>;
     450             : 
     451           0 :     timeByTypeMap timeByType;
     452           0 :     std::vector<double> last_time_stack;
     453           0 :     std::vector<const char*> last_names;
     454             : 
     455             :     // never too many hacks
     456           0 :     std::string current_attribute = "";
     457           0 :     std::map<std::string, double> time_per_attribute;
     458             : 
     459             :     // Let's read the first event
     460           0 :     {
     461           0 :         u8 type = buffer[readPos];
     462           0 :         ++readPos;
     463           0 :         if (type != CProfiler2::ITEM_ENTER)
     464             :         {
     465           0 :             debug_warn("Profiler2: Condensing a region should run into ITEM_ENTER first");
     466           0 :             return; // do nothing
     467             :         }
     468           0 :         CProfiler2::SItem_dt_id item;
     469           0 :         memcpy(&item, buffer + readPos, sizeof(item));
     470           0 :         readPos += sizeof(item);
     471             : 
     472           0 :         regionName = item.id;
     473           0 :         last_names.push_back(item.id);
     474           0 :         initialTime = (double)item.dt;
     475             :     }
     476           0 :     int enter = 1;
     477           0 :     int leaves = 0;
     478             :     // Read subsequent events. Flatten hierarchy because it would get too complicated otherwise.
     479             :     // To make sure time doesn't bloat, subtract time from nested events
     480           0 :     while (readPos < size)
     481             :     {
     482           0 :         u8 type = buffer[readPos];
     483           0 :         ++readPos;
     484             : 
     485           0 :         switch (type)
     486             :         {
     487             :         case CProfiler2::ITEM_NOP:
     488             :         {
     489             :             // ignore
     490             :             break;
     491             :         }
     492           0 :         case CProfiler2::ITEM_SYNC:
     493           0 :         {
     494           0 :             debug_warn("Aggregated regions should not be used across frames");
     495             :             // still try to act sane
     496           0 :             readPos += sizeof(double);
     497           0 :             readPos += sizeof(CProfiler2::RESYNC_MAGIC);
     498           0 :             break;
     499             :         }
     500           0 :         case CProfiler2::ITEM_EVENT:
     501           0 :         {
     502             :             // skip for now
     503           0 :             readPos += sizeof(CProfiler2::SItem_dt_id);
     504           0 :             break;
     505             :         }
     506           0 :         case CProfiler2::ITEM_ENTER:
     507           0 :         {
     508           0 :             enter++;
     509           0 :             CProfiler2::SItem_dt_id item;
     510           0 :             memcpy(&item, buffer + readPos, sizeof(item));
     511           0 :             readPos += sizeof(item);
     512           0 :             last_time_stack.push_back((double)item.dt);
     513           0 :             last_names.push_back(item.id);
     514           0 :             current_attribute = "";
     515           0 :             break;
     516             :         }
     517           0 :         case CProfiler2::ITEM_LEAVE:
     518           0 :         {
     519           0 :             float item_time;
     520           0 :             memcpy(&item_time, buffer + readPos, sizeof(float));
     521           0 :             readPos += sizeof(float);
     522             : 
     523           0 :             leaves++;
     524           0 :             if (last_names.empty())
     525             :             {
     526             :                 // we somehow lost the first entry in the process
     527           0 :                 debug_warn("Invalid buffer for condensing");
     528             :             }
     529           0 :             const char* item_name = last_names.back();
     530           0 :             last_names.pop_back();
     531             : 
     532           0 :             if (last_time_stack.empty())
     533             :             {
     534             :                 // this is the leave for the whole scope
     535           0 :                 total_time = (double)item_time;
     536           0 :                 break;
     537             :             }
     538           0 :             double time = (double)item_time - last_time_stack.back();
     539             : 
     540           0 :             std::string name = std::string(item_name);
     541           0 :             timeByTypeMap::iterator TimeForType = timeByType.find(name);
     542           0 :             if (TimeForType == timeByType.end())
     543             :             {
     544             :                 // keep reference to the original char pointer to make sure we don't break things down the line
     545           0 :                 std::get<0>(timeByType[name]) = item_name;
     546           0 :                 std::get<1>(timeByType[name]) = 0;
     547             :             }
     548           0 :             std::get<1>(timeByType[name]) += time;
     549             : 
     550           0 :             last_time_stack.pop_back();
     551             :             // if we were nested, subtract our time from the below scope by making it look like it starts later
     552           0 :             if (!last_time_stack.empty())
     553           0 :                 last_time_stack.back() += time;
     554             : 
     555           0 :             if (!current_attribute.empty())
     556             :             {
     557           0 :                 time_per_attribute[current_attribute] += time;
     558             :             }
     559             : 
     560           0 :             break;
     561             :         }
     562           0 :         case CProfiler2::ITEM_ATTRIBUTE:
     563           0 :         {
     564             :             // skip for now
     565           0 :             u32 len;
     566           0 :             memcpy(&len, buffer + readPos, sizeof(len));
     567           0 :             ENSURE(len <= CProfiler2::MAX_ATTRIBUTE_LENGTH);
     568           0 :             readPos += sizeof(len);
     569             : 
     570           0 :             char message[CProfiler2::MAX_ATTRIBUTE_LENGTH] = {0};
     571           0 :             memcpy(&message[0], buffer + readPos, std::min(size_t(len), CProfiler2::MAX_ATTRIBUTE_LENGTH));
     572           0 :             CStr mess = CStr((const char*)message, len);
     573           0 :             if (!last_names.empty())
     574             :             {
     575           0 :                 timeByTypeMap::iterator it = timeByType.find(std::string(last_names.back()));
     576           0 :                 if (it == timeByType.end())
     577           0 :                     topLevelArgs.insert(mess);
     578             :                 else
     579           0 :                     std::get<2>(timeByType[std::string(last_names.back())]).insert(mess);
     580             :             }
     581           0 :             readPos += len;
     582           0 :             current_attribute = mess;
     583           0 :             break;
     584             :         }
     585           0 :         default:
     586           0 :             debug_warn(L"Invalid profiler item when condensing buffer");
     587           0 :             continue;
     588             :         }
     589             :     }
     590             : 
     591             :     // rewrite the buffer
     592             :     // what we rewrite will always be smaller than the current buffer's size
     593           0 :     u32 writePos = 0;
     594           0 :     double curTime = initialTime;
     595             :     // the region enter
     596           0 :     {
     597           0 :         CProfiler2::SItem_dt_id item = { (float)curTime, regionName };
     598           0 :         buffer[writePos] = (u8)CProfiler2::ITEM_ENTER;
     599           0 :         memcpy(buffer + writePos + 1, &item, sizeof(item));
     600           0 :         writePos += sizeof(item) + 1;
     601             :         // add a nanosecond for sanity
     602           0 :         curTime += 0.000001;
     603             :     }
     604             :     // sub-events, aggregated
     605           0 :     for (const std::pair<const std::string, infoPerType>& type : timeByType)
     606             :     {
     607           0 :         CProfiler2::SItem_dt_id item = { (float)curTime, std::get<0>(type.second) };
     608           0 :         buffer[writePos] = (u8)CProfiler2::ITEM_ENTER;
     609           0 :         memcpy(buffer + writePos + 1, &item, sizeof(item));
     610           0 :         writePos += sizeof(item) + 1;
     611             : 
     612             :         // write relevant attributes if present
     613           0 :         for (const std::string& attrib : std::get<2>(type.second))
     614             :         {
     615           0 :             buffer[writePos] = (u8)CProfiler2::ITEM_ATTRIBUTE;
     616           0 :             writePos++;
     617           0 :             std::string basic = attrib;
     618           0 :             std::map<std::string, double>::iterator time_attrib = time_per_attribute.find(attrib);
     619           0 :             if (time_attrib != time_per_attribute.end())
     620           0 :                 basic += " " + CStr::FromInt(1000000*time_attrib->second) + "us";
     621             : 
     622           0 :             u32 length = basic.size();
     623           0 :             memcpy(buffer + writePos, &length, sizeof(length));
     624           0 :             writePos += sizeof(length);
     625           0 :             memcpy(buffer + writePos, basic.c_str(), length);
     626           0 :             writePos += length;
     627             :         }
     628             : 
     629           0 :         curTime += std::get<1>(type.second);
     630             : 
     631           0 :         float leave_time = (float)curTime;
     632           0 :         buffer[writePos] = (u8)CProfiler2::ITEM_LEAVE;
     633           0 :         memcpy(buffer + writePos + 1, &leave_time, sizeof(float));
     634           0 :         writePos += sizeof(float) + 1;
     635             :     }
     636             :     // Time of computation
     637           0 :     {
     638           0 :         CProfiler2::SItem_dt_id item = { (float)curTime, "CondenseBuffer" };
     639           0 :         buffer[writePos] = (u8)CProfiler2::ITEM_ENTER;
     640           0 :         memcpy(buffer + writePos + 1, &item, sizeof(item));
     641           0 :         writePos += sizeof(item) + 1;
     642             :     }
     643           0 :     {
     644           0 :         float time_out = (float)(curTime + timer_Time() - startTime);
     645           0 :         buffer[writePos] = (u8)CProfiler2::ITEM_LEAVE;
     646           0 :         memcpy(buffer + writePos + 1, &time_out, sizeof(float));
     647           0 :         writePos += sizeof(float) + 1;
     648             :         // add a nanosecond for sanity
     649           0 :         curTime += 0.000001;
     650             :     }
     651             : 
     652             :     // the region leave
     653           0 :     {
     654           0 :         if (total_time < 0)
     655             :         {
     656           0 :             total_time = curTime + 0.000001;
     657             : 
     658           0 :             buffer[writePos] = (u8)CProfiler2::ITEM_ATTRIBUTE;
     659           0 :             writePos++;
     660           0 :             u32 length = sizeof("buffer overflow");
     661           0 :             memcpy(buffer + writePos, &length, sizeof(length));
     662           0 :             writePos += sizeof(length);
     663           0 :             memcpy(buffer + writePos, "buffer overflow", length);
     664           0 :             writePos += length;
     665             :         }
     666             :         else if (total_time < curTime)
     667             :         {
     668             :             // this seems to happen on rare occasions.
     669             :             curTime = total_time;
     670             :         }
     671           0 :         float leave_time = (float)total_time;
     672           0 :         buffer[writePos] = (u8)CProfiler2::ITEM_LEAVE;
     673           0 :         memcpy(buffer + writePos + 1, &leave_time, sizeof(float));
     674           0 :         writePos += sizeof(float) + 1;
     675             :     }
     676           0 :     bufferSize = writePos;
     677             : }
     678             : 
     679           0 : void CProfiler2::ThreadStorage::HoldToBuffer(bool condensed)
     680             : {
     681           0 :     ENSURE(m_HeldDepth);
     682           0 :     if (condensed)
     683             :     {
     684             :         // rewrite the buffer to show aggregated data
     685           0 :         rewriteBuffer(m_HoldBuffers[m_HeldDepth - 1].buffer, m_HoldBuffers[m_HeldDepth - 1].pos);
     686             :     }
     687             : 
     688           0 :     if (m_HeldDepth > 1)
     689             :     {
     690             :         // copy onto buffer below
     691           0 :         HoldBuffer& copied = m_HoldBuffers[m_HeldDepth - 1];
     692           0 :         HoldBuffer& target = m_HoldBuffers[m_HeldDepth - 2];
     693           0 :         if (target.pos + copied.pos > HOLD_BUFFER_SIZE)
     694             :             return; // too much data, too bad
     695             : 
     696           0 :         memcpy(&target.buffer[target.pos], copied.buffer, copied.pos);
     697             : 
     698           0 :         target.pos += copied.pos;
     699             :     }
     700             :     else
     701             :     {
     702           0 :         u32 size = m_HoldBuffers[m_HeldDepth - 1].pos;
     703           0 :         u32 start = m_BufferPos0;
     704           0 :         if (start + size > BUFFER_SIZE)
     705             :         {
     706           0 :             m_BufferPos0 = size;
     707           0 :             COMPILER_FENCE;
     708           0 :             memset(m_Buffer + start, 0, BUFFER_SIZE - start);
     709           0 :             start = 0;
     710             :         }
     711             :         else
     712             :         {
     713           0 :             m_BufferPos0 = start + size;
     714           0 :             COMPILER_FENCE; // must write m_BufferPos0 before m_Buffer
     715             :         }
     716           0 :         memcpy(&m_Buffer[start], m_HoldBuffers[m_HeldDepth - 1].buffer, size);
     717           0 :         COMPILER_FENCE; // must write m_BufferPos1 after m_Buffer
     718           0 :         m_BufferPos1 = start + size;
     719             :     }
     720           0 :     m_HeldDepth--;
     721             : }
     722           0 : void CProfiler2::ThreadStorage::ThrowawayHoldBuffer()
     723             : {
     724         118 :     if (!m_HeldDepth)
     725             :         return;
     726         118 :     m_HeldDepth--;
     727             : }
     728             : 
     729           0 : void CProfiler2::ConstructJSONOverview(std::ostream& stream)
     730             : {
     731           0 :     TIMER(L"profile2 overview");
     732             : 
     733           0 :     std::lock_guard<std::mutex> lock(m_Mutex);
     734             : 
     735           0 :     stream << "{\"threads\":[";
     736           0 :     bool first_time = true;
     737           0 :     for (std::unique_ptr<ThreadStorage>& storage : m_Threads)
     738             :     {
     739           0 :         if (!first_time)
     740           0 :             stream << ",";
     741           0 :         stream << "{\"name\":\"" << CStr(storage->GetName()).EscapeToPrintableASCII() << "\"}";
     742           0 :         first_time = false;
     743             :     }
     744           0 :     stream << "]}";
     745           0 : }
     746             : 
     747             : /**
     748             :  * Given a buffer and a visitor class (with functions OnEvent, OnEnter, OnLeave, OnAttribute),
     749             :  * calls the visitor for every item in the buffer.
     750             :  */
     751             : template<typename V>
     752           0 : void RunBufferVisitor(const std::string& buffer, V& visitor)
     753             : {
     754           0 :     TIMER(L"profile2 visitor");
     755             : 
     756             :     // The buffer doesn't necessarily start at the beginning of an item
     757             :     // (we just grabbed it from some arbitrary point in the middle),
     758             :     // so scan forwards until we find a sync marker.
     759             :     // (This is probably pretty inefficient.)
     760             : 
     761           0 :     u32 realStart = (u32)-1; // the start point decided by the scan algorithm
     762             : 
     763           0 :     for (u32 start = 0; start + 1 + sizeof(CProfiler2::RESYNC_MAGIC) <= buffer.length(); ++start)
     764             :     {
     765           0 :         if (buffer[start] == CProfiler2::ITEM_SYNC
     766           0 :             && memcmp(buffer.c_str() + start + 1, &CProfiler2::RESYNC_MAGIC, sizeof(CProfiler2::RESYNC_MAGIC)) == 0)
     767             :         {
     768             :             realStart = start;
     769             :             break;
     770             :         }
     771             :     }
     772             : 
     773           0 :     ENSURE(realStart != (u32)-1); // we should have found a sync point somewhere in the buffer
     774             : 
     775             :     u32 pos = realStart; // the position as we step through the buffer
     776             : 
     777             :     double lastTime = -1;
     778             :         // set to non-negative by EVENT_SYNC; we ignore all items before that
     779             :         // since we can't compute their absolute times
     780             : 
     781           0 :     while (pos < buffer.length())
     782             :     {
     783           0 :         u8 type = buffer[pos];
     784           0 :         ++pos;
     785             : 
     786           0 :         switch (type)
     787             :         {
     788             :         case CProfiler2::ITEM_NOP:
     789             :         {
     790             :             // ignore
     791             :             break;
     792             :         }
     793           0 :         case CProfiler2::ITEM_SYNC:
     794             :         {
     795             :             u8 magic[sizeof(CProfiler2::RESYNC_MAGIC)];
     796             :             double t;
     797           0 :             memcpy(magic, buffer.c_str()+pos, ARRAY_SIZE(magic));
     798           0 :             ENSURE(memcmp(magic, &CProfiler2::RESYNC_MAGIC, sizeof(CProfiler2::RESYNC_MAGIC)) == 0);
     799           0 :             pos += sizeof(CProfiler2::RESYNC_MAGIC);
     800           0 :             memcpy(&t, buffer.c_str()+pos, sizeof(t));
     801           0 :             pos += sizeof(t);
     802           0 :             lastTime = t;
     803           0 :             visitor.OnSync(lastTime);
     804             :             break;
     805             :         }
     806           0 :         case CProfiler2::ITEM_EVENT:
     807             :         {
     808             :             CProfiler2::SItem_dt_id item;
     809           0 :             memcpy(&item, buffer.c_str()+pos, sizeof(item));
     810           0 :             pos += sizeof(item);
     811           0 :             if (lastTime >= 0)
     812             :             {
     813           0 :                 visitor.OnEvent(lastTime + (double)item.dt, item.id);
     814             :             }
     815             :             break;
     816             :         }
     817           0 :         case CProfiler2::ITEM_ENTER:
     818             :         {
     819             :             CProfiler2::SItem_dt_id item;
     820           0 :             memcpy(&item, buffer.c_str()+pos, sizeof(item));
     821           0 :             pos += sizeof(item);
     822           0 :             if (lastTime >= 0)
     823             :             {
     824           0 :                 visitor.OnEnter(lastTime + (double)item.dt, item.id);
     825             :             }
     826             :             break;
     827             :         }
     828           0 :         case CProfiler2::ITEM_LEAVE:
     829             :         {
     830             :             float leave_time;
     831           0 :             memcpy(&leave_time, buffer.c_str() + pos, sizeof(float));
     832           0 :             pos += sizeof(float);
     833           0 :             if (lastTime >= 0)
     834             :             {
     835           0 :                 visitor.OnLeave(lastTime + (double)leave_time);
     836             :             }
     837             :             break;
     838             :         }
     839           0 :         case CProfiler2::ITEM_ATTRIBUTE:
     840             :         {
     841             :             u32 len;
     842           0 :             memcpy(&len, buffer.c_str()+pos, sizeof(len));
     843           0 :             ENSURE(len <= CProfiler2::MAX_ATTRIBUTE_LENGTH);
     844           0 :             pos += sizeof(len);
     845           0 :             std::string attribute(buffer.c_str()+pos, buffer.c_str()+pos+len);
     846           0 :             pos += len;
     847           0 :             if (lastTime >= 0)
     848             :             {
     849           0 :                 visitor.OnAttribute(attribute);
     850             :             }
     851             :             break;
     852             :         }
     853           0 :         default:
     854           0 :             debug_warn(L"Invalid profiler item when parsing buffer");
     855           0 :             return;
     856             :         }
     857             :     }
     858             : };
     859             : 
     860             : /**
     861             :  * Visitor class that dumps events as JSON.
     862             :  * TODO: this is pretty inefficient (in implementation and in output format).
     863             :  */
     864             : struct BufferVisitor_Dump
     865             : {
     866             :     NONCOPYABLE(BufferVisitor_Dump);
     867             : public:
     868           0 :     BufferVisitor_Dump(std::ostream& stream) : m_Stream(stream)
     869             :     {
     870             :     }
     871             : 
     872           0 :     void OnSync(double UNUSED(time))
     873             :     {
     874             :         // Split the array of items into an array of array (arbitrarily splitting
     875             :         // around the sync points) to avoid array-too-large errors in JSON decoders
     876           0 :         m_Stream << "null], [\n";
     877           0 :     }
     878             : 
     879           0 :     void OnEvent(double time, const char* id)
     880             :     {
     881           0 :         m_Stream << "[1," << std::fixed << std::setprecision(9) << time;
     882           0 :         m_Stream << ",\"" << CStr(id).EscapeToPrintableASCII() << "\"],\n";
     883           0 :     }
     884             : 
     885           0 :     void OnEnter(double time, const char* id)
     886             :     {
     887           0 :         m_Stream << "[2," << std::fixed << std::setprecision(9) << time;
     888           0 :         m_Stream << ",\"" << CStr(id).EscapeToPrintableASCII() << "\"],\n";
     889           0 :     }
     890             : 
     891           0 :     void OnLeave(double time)
     892             :     {
     893           0 :         m_Stream << "[3," << std::fixed << std::setprecision(9) << time << "],\n";
     894           0 :     }
     895             : 
     896           0 :     void OnAttribute(const std::string& attr)
     897             :     {
     898           0 :         m_Stream << "[4,\"" << CStr(attr).EscapeToPrintableASCII() << "\"],\n";
     899           0 :     }
     900             : 
     901             :     std::ostream& m_Stream;
     902             : };
     903             : 
     904           0 : const char* CProfiler2::ConstructJSONResponse(std::ostream& stream, const std::string& thread)
     905             : {
     906           0 :     TIMER(L"profile2 query");
     907             : 
     908           0 :     std::string buffer;
     909             : 
     910           0 :     {
     911           0 :         TIMER(L"profile2 get buffer");
     912             : 
     913           0 :         std::lock_guard<std::mutex> lock(m_Mutex); // lock against changes to m_Threads or deletions of ThreadStorage
     914             : 
     915           0 :         std::vector<std::unique_ptr<ThreadStorage>>::iterator it =
     916           0 :             std::find_if(m_Threads.begin(), m_Threads.end(), [&thread](std::unique_ptr<ThreadStorage>& storage) {
     917           0 :                 return storage->GetName() == thread;
     918           0 :             });
     919           0 : 
     920           0 :         if (it == m_Threads.end())
     921             :             return "cannot find named thread";
     922           0 : 
     923           0 :         stream << "{\"events\":[\n";
     924             : 
     925             :         stream << "[\n";
     926           0 :         buffer = (*it)->GetBuffer();
     927           0 :     }
     928             : 
     929           0 :     BufferVisitor_Dump visitor(stream);
     930             :     RunBufferVisitor(buffer, visitor);
     931           0 : 
     932           0 :     stream << "null]\n]}";
     933             : 
     934             :     return NULL;
     935           0 : }
     936           0 : 
     937             : void CProfiler2::SaveToFile()
     938           0 : {
     939             :     OsPath path = psLogDir()/"profile2.jsonp";
     940             :     debug_printf("Writing profile data to %s \n", path.string8().c_str());
     941             :     LOGMESSAGERENDER("Writing profile data to %s \n", path.string8().c_str());
     942             :     std::ofstream stream(OsString(path).c_str(), std::ofstream::out | std::ofstream::trunc);
     943           0 :     ENSURE(stream.good());
     944             : 
     945           0 :     stream << "profileDataCB({\"threads\": [\n";
     946           0 :     bool first_time = true;
     947           0 :     for (std::unique_ptr<ThreadStorage>& storage : m_Threads)
     948           0 :     {
     949           0 :         if (!first_time)
     950             :             stream << ",\n";
     951           0 :         stream << "{\"name\":\"" << CStr(storage->GetName()).EscapeToPrintableASCII() << "\",\n";
     952           0 :         stream << "\"data\": ";
     953           0 :         ConstructJSONResponse(stream, storage->GetName());
     954             :         stream << "\n}";
     955           0 :         first_time = false;
     956           0 :     }
     957           0 :     stream << "\n]});\n";
     958           0 : }
     959           0 : 
     960           0 : CProfile2SpikeRegion::CProfile2SpikeRegion(const char* name, double spikeLimit) :
     961           0 :     m_Name(name), m_Limit(spikeLimit), m_PushedHold(true)
     962             : {
     963           0 :     if (g_Profiler2.HoldLevel() < 8 &&  g_Profiler2.HoldType() != CProfiler2::ThreadStorage::BUFFER_AGGREGATE)
     964           0 :         g_Profiler2.HoldMessages(CProfiler2::ThreadStorage::BUFFER_SPIKE);
     965             :     else
     966         118 :         m_PushedHold = false;
     967         118 :     COMPILER_FENCE;
     968             :     g_Profiler2.RecordRegionEnter(m_Name);
     969         118 :     m_StartTime = g_Profiler2.GetTime();
     970         118 : }
     971             : CProfile2SpikeRegion::~CProfile2SpikeRegion()
     972           0 : {
     973         118 :     double time = g_Profiler2.GetTime();
     974         118 :     g_Profiler2.RecordRegionLeave();
     975         118 :     bool shouldWrite = time - m_StartTime > m_Limit;
     976         118 : 
     977         236 :     if (m_PushedHold)
     978             :         g_Profiler2.StopHoldingMessages(shouldWrite);
     979         118 : }
     980         118 : 
     981         118 : CProfile2AggregatedRegion::CProfile2AggregatedRegion(const char* name, double spikeLimit) :
     982             :     m_Name(name), m_Limit(spikeLimit), m_PushedHold(true)
     983         118 : {
     984         118 :     if (g_Profiler2.HoldLevel() < 8 && g_Profiler2.HoldType() != CProfiler2::ThreadStorage::BUFFER_AGGREGATE)
     985         118 :         g_Profiler2.HoldMessages(CProfiler2::ThreadStorage::BUFFER_AGGREGATE);
     986             :     else
     987           0 :         m_PushedHold = false;
     988           0 :     COMPILER_FENCE;
     989             :     g_Profiler2.RecordRegionEnter(m_Name);
     990           0 :     m_StartTime = g_Profiler2.GetTime();
     991           0 : }
     992             : CProfile2AggregatedRegion::~CProfile2AggregatedRegion()
     993           0 : {
     994           0 :     double time = g_Profiler2.GetTime();
     995           0 :     g_Profiler2.RecordRegionLeave();
     996           0 :     bool shouldWrite = time - m_StartTime > m_Limit;
     997           0 : 
     998           0 :     if (m_PushedHold)
     999             :         g_Profiler2.StopHoldingMessages(shouldWrite, true);
    1000           0 : }

Generated by: LCOV version 1.13