src/v8/src/third_party/xdk/xdk-agent.cc

   1 // Copyright (c) 2013 Intel Corporation. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #ifdef __linux__
   6 #include <sys/stat.h>
   7 #endif  // __linux__
   8
   9 #include "xdk-agent.h"
  10 #include <vector>
  11 #include <string>
  12 #include <sstream>
  13 #include "platform.h"
  14 #include "log-utils.h"
  15
  16 namespace xdk {
  17 namespace internal {
  18
  19 static unsigned int XDK_COMMAND_LENGTH = 100;  // It should be enough.
  20
  21 static const char* XDK_TRACE_FILE =
  22   "/data/data/com.intel.app_analyzer/files/result.xdk2v8";
  23
  24 static const char* XDK_MARKER_FILE =
  25   "/data/data/com.intel.app_analyzer/files/profiler.run";
  26
  27 XDKAgent XDKAgent::instance_;
  28
  29 // SetIdle has the same semantics as CpuProfiler::SetIdle has (v8/src/api.cc)
  30 // It is used to tell the sampler that XDK agent is idle (it is not busy with
  31 // some tasks). If the agent is idle that the sampler put a IDLE VM state into
  32 // the Tick record. The samples happen during IDLE will be attributed to (idle)
  33 // line in the XDK viewer.
  34 static void SetIdle(bool isIdle, v8engine::Isolate* isolate) {
  35   CHECK(isolate);
  36   v8engine::StateTag state = isolate->current_vm_state();
  37   if (isolate->js_entry_sp() != NULL) return;
  38   if (state == v8engine::EXTERNAL || state == v8engine::IDLE) {
  39     if (isIdle) {
  40       isolate->set_current_vm_state(v8engine::IDLE);
  41     } else if (state == v8engine::IDLE) {
  42       isolate->set_current_vm_state(v8engine::EXTERNAL);
  43     }
  44   }
  45 }
  46
  47
  48 bool XDKAgent::setUp(v8engine::Isolate* isolate) {
  49   CHECK(isolate);
  50
  51   if (m_isolate) {
  52     // The setUp method is called for the main thread first, then may be called
  53     // again if the app uses Workers (each Worker object has own V8 instance).
  54     // XDK agent does not support JavaScript Worker currently.
  55     XDKLog("xdk: Agent is already initialized\n");
  56     return false;
  57   }
  58
  59   FILE* file = v8engine::OS::FOpen(XDK_MARKER_FILE, "r");
  60   if (file == NULL) {
  61     return false;
  62   }
  63
  64   fclose(file);
  65   m_alive = true;
  66   m_isolate = isolate;
  67
  68   return m_alive;
  69 }
  70
  71
  72 void XDKAgent::resumeSampling() {
  73   v8engine::LockGuard<v8engine::Mutex> l(m_agent_access);
  74   CHECK(m_isolate);
  75
  76   v8engine::Log* log = m_isolate->logger()->XDKGetLog();
  77   CHECK(log);
  78
  79   // Create a new log file for new profiling session
  80   CHECK(!log->IsEnabled());
  81   log->Initialize(XDK_TRACE_FILE);
  82
  83 #ifdef __linux__
  84   int mode = S_IRUSR|S_IROTH|S_IRGRP|S_IWUSR|S_IWOTH|S_IWGRP;
  85   if (chmod(XDK_TRACE_FILE, mode) != 0) {
  86     XDKLog("xdk: Couldn't change permissions for a trace file\n");
  87   }
  88 #endif  // __linux__
  89
  90   CHECK(log->IsEnabled());
  91
  92   logFunctionSnapshot();
  93
  94   // Write a marker line into the log for testing purpose
  95   v8engine::Log::MessageBuilder msg(log);
  96   msg.Append("Profiler started.\n");
  97   msg.WriteToLogFile();
  98
  99   // Resume collection the CPU Tick events
 100   m_isolate->logger()->XDKResumeProfiler();
 101   XDKLog("xdk: Sampling is resumed\n");
 102
 103   SetIdle(true, m_isolate);
 104 }
 105
 106
 107 void XDKAgent::pauseSampling() {
 108   // Pause collection the CPU Tick events
 109   CHECK(m_isolate);
 110   m_isolate->logger()->StopProfiler();
 111
 112   // Use v8 logger internals to close the trace file.
 113   // Once XDK agent implements own sampler this will be removed.
 114   v8engine::Log* log = m_isolate->logger()->XDKGetLog();
 115   CHECK(log);
 116   log->stop();
 117   log->Close();
 118
 119   XDKLog("xdk: Sampling is stopped\n");
 120 }
 121
 122
 123 struct ObjectDeallocator {
 124   template<typename T>
 125   void operator()(const T& obj) const { delete obj.second; }
 126 };
 127
 128
 129 XDKAgent::~XDKAgent() {
 130   CHECK(m_server != NULL);
 131   CHECK(m_agent_access != NULL);
 132
 133   if (m_alive) {
 134     CHECK(m_isolate != NULL);
 135
 136     m_terminate = true;
 137
 138     std::for_each(m_lineMaps.begin(), m_lineMaps.end(), ObjectDeallocator());
 139     m_lineMaps.clear();
 140
 141     m_server->Shutdown();
 142
 143     Join();
 144   }
 145
 146   delete m_server;
 147   m_server = NULL;
 148
 149   delete m_agent_access;
 150   m_agent_access = NULL;
 151
 152   m_isolate = NULL;
 153 }
 154
 155
 156 // The XDK listener thread.
 157 void XDKAgent::Run() {
 158   v8engine::Isolate::EnsureDefaultIsolate();
 159   v8engine::DisallowHeapAllocation no_allocation;
 160   v8engine::DisallowHandleAllocation no_handles;
 161   v8engine::DisallowHandleDereference no_deref;
 162
 163   XDKLog("xdk: Listener thread is running\n");
 164   CHECK(m_server);
 165
 166   bool ok = m_server->Bind(m_port);
 167   if (!ok) {
 168     XDKLog("xdk: Unable to bind port=%d %d\n",
 169             m_port, v8engine::Socket::GetLastError());
 170     return;
 171   }
 172
 173   std::vector<char> buf(XDK_COMMAND_LENGTH);
 174
 175   const std::string cmdStart = "start";
 176   const std::string cmdStop = "stop";
 177
 178   while (!m_terminate) {
 179     XDKLog("xdk: Listener thread is waiting for connection\n");
 180
 181     ok = m_server->Listen(1);
 182     XDKLog("xdk: Listener thread got a connection request. Return value=%d\n",
 183              v8engine::Socket::GetLastError());
 184     if (ok) {
 185       v8engine::Socket* client = m_server->Accept();
 186       if (client == NULL) {
 187         XDKLog("xdk: Accept failed %d\n", v8engine::Socket::GetLastError());
 188         continue;
 189       }
 190
 191       XDKLog("xdk: Connected\n");
 192
 193       int bytes_read = client->Receive(&buf[0], buf.size() - 1);
 194       if (bytes_read == 0) {
 195         XDKLog("xdk: Receive failed %d\n", v8engine::Socket::GetLastError());
 196         break;
 197       }
 198       buf[bytes_read] = '\0';
 199
 200   #ifdef WIN32
 201       if (bytes_read > 3) buf[bytes_read - 2] = '\0';  // remove CR+LF symbols
 202   #else
 203       if (bytes_read > 2) buf[bytes_read - 1] = '\0';  // remove LF symbol
 204   #endif
 205
 206       std::string clientCommand(&buf[0]);
 207       XDKLog("xdk: Got '%s' profiling command\n", clientCommand.c_str());
 208
 209       if (clientCommand == cmdStart) {
 210         resumeSampling();
 211       } else if (clientCommand == cmdStop) {
 212         pauseSampling();
 213       } else {
 214         XDKLog("xdk: '%s' is not handled command\n", clientCommand.c_str());
 215         break;
 216       }
 217     }
 218   }
 219
 220   XDKLog("xdk: Listener thread is stopped\n");
 221   return;
 222 }
 223
 224
 225 void XDKAgent::processCodeMovedEvent(const v8::JitCodeEvent* event) {
 226   v8engine::LockGuard<v8engine::Mutex> l(m_agent_access);
 227   v8engine::Address from = static_cast<v8engine::Address>(event->code_start);
 228   v8engine::Address to = static_cast<v8engine::Address>(event->new_code_start);
 229
 230   if (!from || !to) return;
 231   XDKLog("xdk: CODE_MOVED from=0x%x to=0x%x\n", from, to);
 232   m_snapshot.move(from, to);
 233 }
 234
 235
 236 void XDKAgent::processCodeRemovedEvent(const v8::JitCodeEvent* event) {
 237   v8engine::LockGuard<v8engine::Mutex> l(m_agent_access);
 238   v8engine::Address addr = static_cast<v8engine::Address>(event->code_start);
 239
 240   if (!addr) return;
 241   XDKLog("xdk: CODE_REMOVED for addr=0x%x\n", addr);
 242   m_snapshot.remove(addr);
 243 }
 244
 245
 246 void XDKAgent::processCodeAddedEvent(const v8::JitCodeEvent* event) {
 247   v8engine::LockGuard<v8engine::Mutex> l(m_agent_access);
 248
 249   v8engine::Address codeAddr =
 250     static_cast<v8engine::Address>(event->code_start);
 251   uint32_t codeLen = event->code_len;
 252
 253   if (!codeAddr || !codeLen) return;
 254   XDKLog("xdk: CODE_ADDED for addr=0x%x len=0x%x\n", codeAddr, codeLen);
 255
 256   // Look for line number information
 257   LineMap* lineMap = NULL;
 258   LineMaps::iterator itr = m_lineMaps.find(codeAddr);
 259   if (itr == m_lineMaps.end()) {
 260     XDKLog("xdk: Unable to find line info for addr=0x%x\n", codeAddr);
 261   } else {
 262     lineMap = itr->second;
 263
 264     // Remove line map if no chance to get source lines for it
 265     v8::Handle<v8::Script> script = event->script;
 266     if (*script == NULL) {
 267       XDKLog("xdk: Script is empty. No line info for addr=0x%x.\n", codeAddr);
 268       delete lineMap;
 269       lineMap = NULL;
 270       m_lineMaps.erase(codeAddr);
 271     } else {
 272       // Convert V8 pos value into source line number.
 273       LineMap::Entries* entries =
 274         const_cast<LineMap::Entries*>(lineMap->getEntries());
 275       CHECK(entries);
 276       CHECK(entries->size());
 277       XDKLog("xdk: Found line info (%d lines) for addr=0x%x\n",
 278               entries->size(), codeAddr);
 279       size_t srcLine = 0;
 280       LineMap::Entries::iterator lineItr = entries->begin();
 281       LineMap::Entries::iterator lineEnd = entries->end();
 282       for (; lineItr != lineEnd; ++lineItr) {
 283         srcLine = script->GetLineNumber(lineItr->line) + 1;
 284         lineItr->line = srcLine;
 285         XDKLog("xdk:   offset=%p line=%d\n", lineItr->pcOffset, lineItr->line);
 286       }
 287     }
 288   }
 289
 290   std::string funcType;
 291   std::string name(event->name.str, event->name.len);
 292   Function func(codeAddr, codeLen, name, funcType, lineMap);
 293
 294   if (lineMap) {
 295     // Put the line number information for the given method into the trace file
 296     // if profiling session is running.
 297     logLineNumberInfo(codeAddr, *lineMap);
 298
 299     // Release memory allocated on CODE_START_LINE_INFO_RECORDING
 300     delete lineMap;
 301     lineMap = NULL;
 302     m_lineMaps.erase(codeAddr);
 303   }
 304
 305   m_snapshot.insert(func);
 306 }
 307
 308
 309 void XDKAgent::processLineMapAddedEvent(const v8::JitCodeEvent* event) {
 310   v8engine::LockGuard<v8engine::Mutex> l(m_agent_access);
 311   v8engine::Address codeAddr =
 312     static_cast<v8engine::Address>(event->code_start);
 313   void* userData = event->user_data;
 314
 315   if (!userData || !codeAddr) return;
 316
 317   LineMap* lineMap = reinterpret_cast<LineMap*>(userData);
 318   if (lineMap->getSize() == 0) {
 319     XDKLog("xdk: CODE_END_LINE no entries for user_data=%p addr=0x%x\n",
 320             userData, codeAddr);
 321     return;
 322   }
 323
 324   std::pair<LineMaps::iterator, bool>
 325     result = m_lineMaps.insert(std::make_pair(codeAddr, lineMap));
 326   if (!result.second) {
 327     m_lineMaps.erase(codeAddr);
 328     XDKLog("xdk: removed unprocessed line info for addr=0x%x\n", codeAddr);
 329     result = m_lineMaps.insert(std::make_pair(codeAddr, lineMap));
 330     CHECK(result.second);
 331   }
 332
 333   XDKLog("xdk: CODE_END_LINE added %d entries for user_data=%p addr=0x%x\n",
 334            lineMap->getSize(), userData, codeAddr);
 335 }
 336
 337
 338 void EventHandler(const v8::JitCodeEvent* event) {
 339   // This callback is called regardless of whether profiling is running.
 340   //
 341   // By default profiling is launched in paused mode, the agent is awaiting
 342   // a command to resume profiling. At the same time, V8's JIT compiler is
 343   // working. The functions which are JIT-compiled while sampling is paused
 344   // are cached by V8's Logger and will be written in log (trace file) when
 345   // XDK resumes the profiling. The line number info for such functions are not
 346   // cached. We need to capture and cache the line number info and flush
 347   // the cache on resume profiling.
 348
 349   if (event == NULL) return;
 350
 351   switch (event->type) {
 352     case v8::JitCodeEvent::CODE_MOVED:
 353       XDKAgent::instance().processCodeMovedEvent(event);
 354       break;
 355
 356     case v8::JitCodeEvent::CODE_REMOVED:
 357       XDKAgent::instance().processCodeRemovedEvent(event);
 358       break;
 359
 360     case v8::JitCodeEvent::CODE_ADDED:
 361       XDKAgent::instance().processCodeAddedEvent(event);
 362
 363     case v8::JitCodeEvent::CODE_ADD_LINE_POS_INFO: {
 364       void* userData = event->user_data;
 365       if (!userData) return;
 366       LineMap* lineMap = reinterpret_cast<LineMap*>(userData);
 367       size_t offset = event->line_info.offset;
 368       size_t pos = event->line_info.pos;
 369       lineMap->setPosition(offset, pos);
 370       XDKLog("xdk: CODE_ADD_LINE_POS for user_data=%p offset=0x%x pos=%d\n",
 371                userData, offset, pos);
 372       break;
 373     }
 374
 375     case v8::JitCodeEvent::CODE_START_LINE_INFO_RECORDING: {
 376       v8::JitCodeEvent* data = const_cast<v8::JitCodeEvent*>(event);
 377       data->user_data = new LineMap();
 378       XDKLog("xdk: CODE_START_LINE for user_data=%p\n", event->user_data);
 379       break;
 380     }
 381
 382     case v8::JitCodeEvent::CODE_END_LINE_INFO_RECORDING: {
 383       XDKAgent::instance().processLineMapAddedEvent(event);
 384       break;
 385     }
 386
 387     default:
 388       XDKLog("xdk: Unknown event\n");
 389       break;
 390   }
 391
 392   SetIdle(true, XDKAgent::instance().isolate());
 393
 394   return;
 395 }
 396
 397
 398 void XDKAgent::logLineNumberInfo(v8engine::Address addr,
 399                                  const LineMap& lineInfo) {
 400   CHECK(addr);
 401   v8engine::Log* log = m_isolate->logger()->XDKGetLog();
 402   CHECK(log);
 403   if (!log->IsEnabled()) return;
 404   if (lineInfo.getSize() == 0) return;
 405   const LineMap::Entries* lines = lineInfo.getEntries();
 406   CHECK(lines);
 407   LineMap::Entries::const_iterator lineItr = lines->begin();
 408   LineMap::Entries::const_iterator lineEnd = lines->end();
 409
 410   // Put 'src-pos' lines into the log in our own format
 411   for (; lineItr != lineEnd; ++lineItr) {
 412     v8engine::Log::MessageBuilder msg(m_isolate->logger()->XDKGetLog());
 413     msg.Append("src-pos,");
 414     msg.Append("0x%x,%d,%d\n", addr, lineItr->pcOffset, lineItr->line);
 415     msg.WriteToLogFile();
 416   }
 417 }
 418
 419
 420 void XDKAgent::logFunctionSnapshot() {
 421   CHECK(m_isolate);
 422
 423   CodeMap::const_iterator funcItr = m_snapshot.entries().begin();
 424   CodeMap::const_iterator funcEnd = m_snapshot.entries().end();
 425
 426   XDKLog("FunctionSnapshot: %d entries\n", m_snapshot.entries().size());
 427   if (m_snapshot.entries().size() == 0) return;
 428
 429   unsigned int i = 1;
 430
 431   for (; funcItr != funcEnd; ++funcItr, i++) {
 432     const Range& range = funcItr->first;
 433     const Function& func = funcItr->second;
 434
 435     XDKLog("%d    %s\n", i, func.getLogLine().c_str());
 436
 437     const LineMap& map = func.getLineMap();
 438     if (map.getSize()) {
 439       v8engine::Address codeAddr = range.start();
 440       XDKLog("  Found %d lines for addr=%p\n", map.getSize(), codeAddr);
 441       logLineNumberInfo(codeAddr, map);
 442     }
 443
 444     // Write 'code-creation' line into the log
 445     v8engine::Log::MessageBuilder msg(m_isolate->logger()->XDKGetLog());
 446     msg.Append("%s\n", func.getLogLine().c_str());
 447     msg.WriteToLogFile();
 448   }
 449 }
 450
 451 }}  // namespace xdk::internal