Home | History | Annotate | Download | only in src 
      1 // Copyright 2009 the V8 project authors. All rights reserved.
      2 // Redistribution and use in source and binary forms, with or without
      3 // modification, are permitted provided that the following conditions are
      4 // met:
      5 //
      6 //     * Redistributions of source code must retain the above copyright
      7 //       notice, this list of conditions and the following disclaimer.
      8 //     * Redistributions in binary form must reproduce the above
      9 //       copyright notice, this list of conditions and the following
     10 //       disclaimer in the documentation and/or other materials provided
     11 //       with the distribution.
     12 //     * Neither the name of Google Inc. nor the names of its
     13 //       contributors may be used to endorse or promote products derived
     14 //       from this software without specific prior written permission.
     15 //
     16 // THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
     17 // "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
     18 // LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
     19 // A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
     20 // OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
     21 // SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
     22 // LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
     23 // DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
     24 // THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
     25 // (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
     26 // OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
     27 
     28 #include "v8.h"
     29 
     30 #include "log-utils.h"
     31 #include "string-stream.h"
     32 
     33 namespace v8 {
     34 namespace internal {
     35 
     36 #ifdef ENABLE_LOGGING_AND_PROFILING
     37 
     38 LogDynamicBuffer::LogDynamicBuffer(
     39     int block_size, int max_size, const char* seal, int seal_size)
     40     : block_size_(block_size),
     41       max_size_(max_size - (max_size % block_size_)),
     42       seal_(seal),
     43       seal_size_(seal_size),
     44       blocks_(max_size_ / block_size_ + 1),
     45       write_pos_(0), block_index_(0), block_write_pos_(0), is_sealed_(false) {
     46   ASSERT(BlocksCount() > 0);
     47   AllocateBlock(0);
     48   for (int i = 1; i < BlocksCount(); ++i) {
     49     blocks_[i] = NULL;
     50   }
     51 }
     52 
     53 
     54 LogDynamicBuffer::~LogDynamicBuffer() {
     55   for (int i = 0; i < BlocksCount(); ++i) {
     56     DeleteArray(blocks_[i]);
     57   }
     58 }
     59 
     60 
     61 int LogDynamicBuffer::Read(int from_pos, char* dest_buf, int buf_size) {
     62   if (buf_size == 0) return 0;
     63   int read_pos = from_pos;
     64   int block_read_index = BlockIndex(from_pos);
     65   int block_read_pos = PosInBlock(from_pos);
     66   int dest_buf_pos = 0;
     67   // Read until dest_buf is filled, or write_pos_ encountered.
     68   while (read_pos < write_pos_ && dest_buf_pos < buf_size) {
     69     const int read_size = Min(write_pos_ - read_pos,
     70         Min(buf_size - dest_buf_pos, block_size_ - block_read_pos));
     71     memcpy(dest_buf + dest_buf_pos,
     72            blocks_[block_read_index] + block_read_pos, read_size);
     73     block_read_pos += read_size;
     74     dest_buf_pos += read_size;
     75     read_pos += read_size;
     76     if (block_read_pos == block_size_) {
     77       block_read_pos = 0;
     78       ++block_read_index;
     79     }
     80   }
     81   return dest_buf_pos;
     82 }
     83 
     84 
     85 int LogDynamicBuffer::Seal() {
     86   WriteInternal(seal_, seal_size_);
     87   is_sealed_ = true;
     88   return 0;
     89 }
     90 
     91 
     92 int LogDynamicBuffer::Write(const char* data, int data_size) {
     93   if (is_sealed_) {
     94     return 0;
     95   }
     96   if ((write_pos_ + data_size) <= (max_size_ - seal_size_)) {
     97     return WriteInternal(data, data_size);
     98   } else {
     99     return Seal();
    100   }
    101 }
    102 
    103 
    104 int LogDynamicBuffer::WriteInternal(const char* data, int data_size) {
    105   int data_pos = 0;
    106   while (data_pos < data_size) {
    107     const int write_size =
    108         Min(data_size - data_pos, block_size_ - block_write_pos_);
    109     memcpy(blocks_[block_index_] + block_write_pos_, data + data_pos,
    110            write_size);
    111     block_write_pos_ += write_size;
    112     data_pos += write_size;
    113     if (block_write_pos_ == block_size_) {
    114       block_write_pos_ = 0;
    115       AllocateBlock(++block_index_);
    116     }
    117   }
    118   write_pos_ += data_size;
    119   return data_size;
    120 }
    121 
    122 // Must be the same message as in Logger::PauseProfiler.
    123 const char* const Log::kDynamicBufferSeal = "profiler,\"pause\"\n";
    124 
    125 Log::Log(Logger* logger)
    126   : write_to_file_(false),
    127     is_stopped_(false),
    128     output_handle_(NULL),
    129     output_code_handle_(NULL),
    130     output_buffer_(NULL),
    131     mutex_(NULL),
    132     message_buffer_(NULL),
    133     logger_(logger) {
    134 }
    135 
    136 
    137 static void AddIsolateIdIfNeeded(StringStream* stream) {
    138   Isolate* isolate = Isolate::Current();
    139   if (isolate->IsDefaultIsolate()) return;
    140   stream->Add("isolate-%p-", isolate);
    141 }
    142 
    143 
    144 void Log::Initialize() {
    145 #ifdef ENABLE_LOGGING_AND_PROFILING
    146   mutex_ = OS::CreateMutex();
    147   message_buffer_ = NewArray<char>(kMessageBufferSize);
    148 
    149   // --log-all enables all the log flags.
    150   if (FLAG_log_all) {
    151     FLAG_log_runtime = true;
    152     FLAG_log_api = true;
    153     FLAG_log_code = true;
    154     FLAG_log_gc = true;
    155     FLAG_log_suspect = true;
    156     FLAG_log_handles = true;
    157     FLAG_log_regexp = true;
    158   }
    159 
    160   // --prof implies --log-code.
    161   if (FLAG_prof) FLAG_log_code = true;
    162 
    163   // --prof_lazy controls --log-code, implies --noprof_auto.
    164   if (FLAG_prof_lazy) {
    165     FLAG_log_code = false;
    166     FLAG_prof_auto = false;
    167   }
    168 
    169   bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api
    170       || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
    171       || FLAG_log_regexp || FLAG_log_state_changes;
    172 
    173   bool open_log_file = start_logging || FLAG_prof_lazy;
    174 
    175   // If we're logging anything, we need to open the log file.
    176   if (open_log_file) {
    177     if (strcmp(FLAG_logfile, "-") == 0) {
    178       OpenStdout();
    179     } else if (strcmp(FLAG_logfile, "*") == 0) {
    180       OpenMemoryBuffer();
    181     } else  {
    182       if (strchr(FLAG_logfile, '%') != NULL ||
    183           !Isolate::Current()->IsDefaultIsolate()) {
    184         // If there's a '%' in the log file name we have to expand
    185         // placeholders.
    186         HeapStringAllocator allocator;
    187         StringStream stream(&allocator);
    188         AddIsolateIdIfNeeded(&stream);
    189         for (const char* p = FLAG_logfile; *p; p++) {
    190           if (*p == '%') {
    191             p++;
    192             switch (*p) {
    193               case '\0':
    194                 // If there's a % at the end of the string we back up
    195                 // one character so we can escape the loop properly.
    196                 p--;
    197                 break;
    198               case 't': {
    199                 // %t expands to the current time in milliseconds.
    200                 double time = OS::TimeCurrentMillis();
    201                 stream.Add("%.0f", FmtElm(time));
    202                 break;
    203               }
    204               case '%':
    205                 // %% expands (contracts really) to %.
    206                 stream.Put('%');
    207                 break;
    208               default:
    209                 // All other %'s expand to themselves.
    210                 stream.Put('%');
    211                 stream.Put(*p);
    212                 break;
    213             }
    214           } else {
    215             stream.Put(*p);
    216           }
    217         }
    218         SmartPointer<const char> expanded = stream.ToCString();
    219         OpenFile(*expanded);
    220       } else {
    221         OpenFile(FLAG_logfile);
    222       }
    223     }
    224   }
    225 #endif
    226 }
    227 
    228 
    229 void Log::OpenStdout() {
    230   ASSERT(!IsEnabled());
    231   output_handle_ = stdout;
    232   write_to_file_ = true;
    233 }
    234 
    235 
    236 static const char kCodeLogExt[] = ".code";
    237 
    238 
    239 void Log::OpenFile(const char* name) {
    240   ASSERT(!IsEnabled());
    241   output_handle_ = OS::FOpen(name, OS::LogFileOpenMode);
    242   write_to_file_ = true;
    243   if (FLAG_ll_prof) {
    244     // Open a file for logging the contents of code objects so that
    245     // they can be disassembled later.
    246     size_t name_len = strlen(name);
    247     ScopedVector<char> code_name(
    248         static_cast<int>(name_len + sizeof(kCodeLogExt)));
    249     memcpy(code_name.start(), name, name_len);
    250     memcpy(code_name.start() + name_len, kCodeLogExt, sizeof(kCodeLogExt));
    251     output_code_handle_ = OS::FOpen(code_name.start(), OS::LogFileOpenMode);
    252   }
    253 }
    254 
    255 
    256 void Log::OpenMemoryBuffer() {
    257   ASSERT(!IsEnabled());
    258   output_buffer_ = new LogDynamicBuffer(
    259       kDynamicBufferBlockSize, kMaxDynamicBufferSize,
    260       kDynamicBufferSeal, StrLength(kDynamicBufferSeal));
    261   write_to_file_ = false;
    262 }
    263 
    264 
    265 void Log::Close() {
    266   if (write_to_file_) {
    267     if (output_handle_ != NULL) fclose(output_handle_);
    268     output_handle_ = NULL;
    269     if (output_code_handle_ != NULL) fclose(output_code_handle_);
    270     output_code_handle_ = NULL;
    271   } else {
    272     delete output_buffer_;
    273     output_buffer_ = NULL;
    274   }
    275 
    276   DeleteArray(message_buffer_);
    277   message_buffer_ = NULL;
    278 
    279   delete mutex_;
    280   mutex_ = NULL;
    281 
    282   is_stopped_ = false;
    283 }
    284 
    285 
    286 int Log::GetLogLines(int from_pos, char* dest_buf, int max_size) {
    287   if (write_to_file_) return 0;
    288   ASSERT(output_buffer_ != NULL);
    289   ASSERT(from_pos >= 0);
    290   ASSERT(max_size >= 0);
    291   int actual_size = output_buffer_->Read(from_pos, dest_buf, max_size);
    292   ASSERT(actual_size <= max_size);
    293   if (actual_size == 0) return 0;
    294 
    295   // Find previous log line boundary.
    296   char* end_pos = dest_buf + actual_size - 1;
    297   while (end_pos >= dest_buf && *end_pos != '\n') --end_pos;
    298   actual_size = static_cast<int>(end_pos - dest_buf + 1);
    299   // If the assertion below is hit, it means that there was no line end
    300   // found --- something wrong has happened.
    301   ASSERT(actual_size > 0);
    302   ASSERT(actual_size <= max_size);
    303   return actual_size;
    304 }
    305 
    306 
    307 LogMessageBuilder::LogMessageBuilder(Logger* logger)
    308   : log_(logger->log_),
    309     sl(log_->mutex_),
    310     pos_(0) {
    311   ASSERT(log_->message_buffer_ != NULL);
    312 }
    313 
    314 
    315 void LogMessageBuilder::Append(const char* format, ...) {
    316   Vector<char> buf(log_->message_buffer_ + pos_,
    317                    Log::kMessageBufferSize - pos_);
    318   va_list args;
    319   va_start(args, format);
    320   AppendVA(format, args);
    321   va_end(args);
    322   ASSERT(pos_ <= Log::kMessageBufferSize);
    323 }
    324 
    325 
    326 void LogMessageBuilder::AppendVA(const char* format, va_list args) {
    327   Vector<char> buf(log_->message_buffer_ + pos_,
    328                    Log::kMessageBufferSize - pos_);
    329   int result = v8::internal::OS::VSNPrintF(buf, format, args);
    330 
    331   // Result is -1 if output was truncated.
    332   if (result >= 0) {
    333     pos_ += result;
    334   } else {
    335     pos_ = Log::kMessageBufferSize;
    336   }
    337   ASSERT(pos_ <= Log::kMessageBufferSize);
    338 }
    339 
    340 
    341 void LogMessageBuilder::Append(const char c) {
    342   if (pos_ < Log::kMessageBufferSize) {
    343     log_->message_buffer_[pos_++] = c;
    344   }
    345   ASSERT(pos_ <= Log::kMessageBufferSize);
    346 }
    347 
    348 
    349 void LogMessageBuilder::Append(String* str) {
    350   AssertNoAllocation no_heap_allocation;  // Ensure string stay valid.
    351   int length = str->length();
    352   for (int i = 0; i < length; i++) {
    353     Append(static_cast<char>(str->Get(i)));
    354   }
    355 }
    356 
    357 
    358 void LogMessageBuilder::AppendAddress(Address addr) {
    359   Append("0x%" V8PRIxPTR, addr);
    360 }
    361 
    362 
    363 void LogMessageBuilder::AppendDetailed(String* str, bool show_impl_info) {
    364   AssertNoAllocation no_heap_allocation;  // Ensure string stay valid.
    365   int len = str->length();
    366   if (len > 0x1000)
    367     len = 0x1000;
    368   if (show_impl_info) {
    369     Append(str->IsAsciiRepresentation() ? 'a' : '2');
    370     if (StringShape(str).IsExternal())
    371       Append('e');
    372     if (StringShape(str).IsSymbol())
    373       Append('#');
    374     Append(":%i:", str->length());
    375   }
    376   for (int i = 0; i < len; i++) {
    377     uc32 c = str->Get(i);
    378     if (c > 0xff) {
    379       Append("\\u%04x", c);
    380     } else if (c < 32 || c > 126) {
    381       Append("\\x%02x", c);
    382     } else if (c == ',') {
    383       Append("\\,");
    384     } else if (c == '\\') {
    385       Append("\\\\");
    386     } else if (c == '\"') {
    387       Append("\"\"");
    388     } else {
    389       Append("%lc", c);
    390     }
    391   }
    392 }
    393 
    394 
    395 void LogMessageBuilder::AppendStringPart(const char* str, int len) {
    396   if (pos_ + len > Log::kMessageBufferSize) {
    397     len = Log::kMessageBufferSize - pos_;
    398     ASSERT(len >= 0);
    399     if (len == 0) return;
    400   }
    401   Vector<char> buf(log_->message_buffer_ + pos_,
    402                    Log::kMessageBufferSize - pos_);
    403   OS::StrNCpy(buf, str, len);
    404   pos_ += len;
    405   ASSERT(pos_ <= Log::kMessageBufferSize);
    406 }
    407 
    408 
    409 void LogMessageBuilder::WriteToLogFile() {
    410   ASSERT(pos_ <= Log::kMessageBufferSize);
    411   const int written = log_->write_to_file_ ?
    412       log_->WriteToFile(log_->message_buffer_, pos_) :
    413       log_->WriteToMemory(log_->message_buffer_, pos_);
    414   if (written != pos_) {
    415     log_->stop();
    416     log_->logger_->LogFailure();
    417   }
    418 }
    419 
    420 
    421 #endif  // ENABLE_LOGGING_AND_PROFILING
    422 
    423 } }  // namespace v8::internal
    424