log-utils.cc revision a7e24c173cf37484693b9abb38e494fa7bd7baeb 
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
32namespace v8 {
33namespace internal {
34
35#ifdef ENABLE_LOGGING_AND_PROFILING
36
37LogDynamicBuffer::LogDynamicBuffer(
38    int block_size, int max_size, const char* seal, int seal_size)
39    : block_size_(block_size),
40      max_size_(max_size - (max_size % block_size_)),
41      seal_(seal),
42      seal_size_(seal_size),
43      blocks_(max_size_ / block_size_ + 1),
44      write_pos_(0), block_index_(0), block_write_pos_(0), is_sealed_(false) {
45  ASSERT(BlocksCount() > 0);
46  AllocateBlock(0);
47  for (int i = 1; i < BlocksCount(); ++i) {
48    blocks_[i] = NULL;
49  }
50}
51
52
53LogDynamicBuffer::~LogDynamicBuffer() {
54  for (int i = 0; i < BlocksCount(); ++i) {
55    DeleteArray(blocks_[i]);
56  }
57}
58
59
60int LogDynamicBuffer::Read(int from_pos, char* dest_buf, int buf_size) {
61  if (buf_size == 0) return 0;
62  int read_pos = from_pos;
63  int block_read_index = BlockIndex(from_pos);
64  int block_read_pos = PosInBlock(from_pos);
65  int dest_buf_pos = 0;
66  // Read until dest_buf is filled, or write_pos_ encountered.
67  while (read_pos < write_pos_ && dest_buf_pos < buf_size) {
68    const int read_size = Min(write_pos_ - read_pos,
69        Min(buf_size - dest_buf_pos, block_size_ - block_read_pos));
70    memcpy(dest_buf + dest_buf_pos,
71           blocks_[block_read_index] + block_read_pos, read_size);
72    block_read_pos += read_size;
73    dest_buf_pos += read_size;
74    read_pos += read_size;
75    if (block_read_pos == block_size_) {
76      block_read_pos = 0;
77      ++block_read_index;
78    }
79  }
80  return dest_buf_pos;
81}
82
83
84int LogDynamicBuffer::Seal() {
85  WriteInternal(seal_, seal_size_);
86  is_sealed_ = true;
87  return 0;
88}
89
90
91int LogDynamicBuffer::Write(const char* data, int data_size) {
92  if (is_sealed_) {
93    return 0;
94  }
95  if ((write_pos_ + data_size) <= (max_size_ - seal_size_)) {
96    return WriteInternal(data, data_size);
97  } else {
98    return Seal();
99  }
100}
101
102
103int LogDynamicBuffer::WriteInternal(const char* data, int data_size) {
104  int data_pos = 0;
105  while (data_pos < data_size) {
106    const int write_size =
107        Min(data_size - data_pos, block_size_ - block_write_pos_);
108    memcpy(blocks_[block_index_] + block_write_pos_, data + data_pos,
109           write_size);
110    block_write_pos_ += write_size;
111    data_pos += write_size;
112    if (block_write_pos_ == block_size_) {
113      block_write_pos_ = 0;
114      AllocateBlock(++block_index_);
115    }
116  }
117  write_pos_ += data_size;
118  return data_size;
119}
120
121
122bool Log::is_stopped_ = false;
123Log::WritePtr Log::Write = NULL;
124FILE* Log::output_handle_ = NULL;
125LogDynamicBuffer* Log::output_buffer_ = NULL;
126// Must be the same message as in Logger::PauseProfiler.
127const char* Log::kDynamicBufferSeal = "profiler,\"pause\"\n";
128Mutex* Log::mutex_ = NULL;
129char* Log::message_buffer_ = NULL;
130
131
132void Log::Init() {
133  mutex_ = OS::CreateMutex();
134  message_buffer_ = NewArray<char>(kMessageBufferSize);
135}
136
137
138void Log::OpenStdout() {
139  ASSERT(!IsEnabled());
140  output_handle_ = stdout;
141  Write = WriteToFile;
142  Init();
143}
144
145
146void Log::OpenFile(const char* name) {
147  ASSERT(!IsEnabled());
148  output_handle_ = OS::FOpen(name, OS::LogFileOpenMode);
149  Write = WriteToFile;
150  Init();
151}
152
153
154void Log::OpenMemoryBuffer() {
155  ASSERT(!IsEnabled());
156  output_buffer_ = new LogDynamicBuffer(
157      kDynamicBufferBlockSize, kMaxDynamicBufferSize,
158      kDynamicBufferSeal, strlen(kDynamicBufferSeal));
159  Write = WriteToMemory;
160  Init();
161}
162
163
164void Log::Close() {
165  if (Write == WriteToFile) {
166    if (output_handle_ != NULL) fclose(output_handle_);
167    output_handle_ = NULL;
168  } else if (Write == WriteToMemory) {
169    delete output_buffer_;
170    output_buffer_ = NULL;
171  } else {
172    ASSERT(Write == NULL);
173  }
174  Write = NULL;
175
176  DeleteArray(message_buffer_);
177  message_buffer_ = NULL;
178
179  delete mutex_;
180  mutex_ = NULL;
181
182  is_stopped_ = false;
183}
184
185
186int Log::GetLogLines(int from_pos, char* dest_buf, int max_size) {
187  if (Write != WriteToMemory) return 0;
188  ASSERT(output_buffer_ != NULL);
189  ASSERT(from_pos >= 0);
190  ASSERT(max_size >= 0);
191  int actual_size = output_buffer_->Read(from_pos, dest_buf, max_size);
192  ASSERT(actual_size <= max_size);
193  if (actual_size == 0) return 0;
194
195  // Find previous log line boundary.
196  char* end_pos = dest_buf + actual_size - 1;
197  while (end_pos >= dest_buf && *end_pos != '\n') --end_pos;
198  actual_size = end_pos - dest_buf + 1;
199  ASSERT(actual_size <= max_size);
200  return actual_size;
201}
202
203
204LogMessageBuilder::WriteFailureHandler
205    LogMessageBuilder::write_failure_handler = NULL;
206
207
208LogMessageBuilder::LogMessageBuilder(): sl(Log::mutex_), pos_(0) {
209  ASSERT(Log::message_buffer_ != NULL);
210}
211
212
213void LogMessageBuilder::Append(const char* format, ...) {
214  Vector<char> buf(Log::message_buffer_ + pos_,
215                   Log::kMessageBufferSize - pos_);
216  va_list args;
217  va_start(args, format);
218  AppendVA(format, args);
219  va_end(args);
220  ASSERT(pos_ <= Log::kMessageBufferSize);
221}
222
223
224void LogMessageBuilder::AppendVA(const char* format, va_list args) {
225  Vector<char> buf(Log::message_buffer_ + pos_,
226                   Log::kMessageBufferSize - pos_);
227  int result = v8::internal::OS::VSNPrintF(buf, format, args);
228
229  // Result is -1 if output was truncated.
230  if (result >= 0) {
231    pos_ += result;
232  } else {
233    pos_ = Log::kMessageBufferSize;
234  }
235  ASSERT(pos_ <= Log::kMessageBufferSize);
236}
237
238
239void LogMessageBuilder::Append(const char c) {
240  if (pos_ < Log::kMessageBufferSize) {
241    Log::message_buffer_[pos_++] = c;
242  }
243  ASSERT(pos_ <= Log::kMessageBufferSize);
244}
245
246
247void LogMessageBuilder::Append(String* str) {
248  AssertNoAllocation no_heap_allocation;  // Ensure string stay valid.
249  int length = str->length();
250  for (int i = 0; i < length; i++) {
251    Append(static_cast<char>(str->Get(i)));
252  }
253}
254
255
256void LogMessageBuilder::AppendAddress(Address addr) {
257  static Address last_address_ = NULL;
258  AppendAddress(addr, last_address_);
259  last_address_ = addr;
260}
261
262
263void LogMessageBuilder::AppendAddress(Address addr, Address bias) {
264  if (!FLAG_compress_log) {
265    Append("0x%" V8PRIxPTR, addr);
266  } else if (bias == NULL) {
267    Append("%" V8PRIxPTR, addr);
268  } else {
269    uintptr_t delta;
270    char sign;
271    if (addr >= bias) {
272      delta = addr - bias;
273      sign = '+';
274    } else {
275      delta = bias - addr;
276      sign = '-';
277    }
278    Append("%c%" V8PRIxPTR, sign, delta);
279  }
280}
281
282
283void LogMessageBuilder::AppendDetailed(String* str, bool show_impl_info) {
284  AssertNoAllocation no_heap_allocation;  // Ensure string stay valid.
285  int len = str->length();
286  if (len > 0x1000)
287    len = 0x1000;
288  if (show_impl_info) {
289    Append(str->IsAsciiRepresentation() ? 'a' : '2');
290    if (StringShape(str).IsExternal())
291      Append('e');
292    if (StringShape(str).IsSymbol())
293      Append('#');
294    Append(":%i:", str->length());
295  }
296  for (int i = 0; i < len; i++) {
297    uc32 c = str->Get(i);
298    if (c > 0xff) {
299      Append("\\u%04x", c);
300    } else if (c < 32 || c > 126) {
301      Append("\\x%02x", c);
302    } else if (c == ',') {
303      Append("\\,");
304    } else if (c == '\\') {
305      Append("\\\\");
306    } else {
307      Append("%lc", c);
308    }
309  }
310}
311
312
313void LogMessageBuilder::AppendStringPart(const char* str, int len) {
314  if (pos_ + len > Log::kMessageBufferSize) {
315    len = Log::kMessageBufferSize - pos_;
316    ASSERT(len >= 0);
317    if (len == 0) return;
318  }
319  Vector<char> buf(Log::message_buffer_ + pos_,
320                   Log::kMessageBufferSize - pos_);
321  OS::StrNCpy(buf, str, len);
322  pos_ += len;
323  ASSERT(pos_ <= Log::kMessageBufferSize);
324}
325
326
327bool LogMessageBuilder::StoreInCompressor(LogRecordCompressor* compressor) {
328  return compressor->Store(Vector<const char>(Log::message_buffer_, pos_));
329}
330
331
332bool LogMessageBuilder::RetrieveCompressedPrevious(
333    LogRecordCompressor* compressor, const char* prefix) {
334  pos_ = 0;
335  if (prefix[0] != '\0') Append(prefix);
336  Vector<char> prev_record(Log::message_buffer_ + pos_,
337                           Log::kMessageBufferSize - pos_);
338  const bool has_prev = compressor->RetrievePreviousCompressed(&prev_record);
339  if (!has_prev) return false;
340  pos_ += prev_record.length();
341  return true;
342}
343
344
345void LogMessageBuilder::WriteToLogFile() {
346  ASSERT(pos_ <= Log::kMessageBufferSize);
347  const int written = Log::Write(Log::message_buffer_, pos_);
348  if (written != pos_ && write_failure_handler != NULL) {
349    write_failure_handler();
350  }
351}
352
353
354void LogMessageBuilder::WriteCStringToLogFile(const char* str) {
355  const int len = strlen(str);
356  const int written = Log::Write(str, len);
357  if (written != len && write_failure_handler != NULL) {
358    write_failure_handler();
359  }
360}
361
362
363// Formatting string for back references to the whole line. E.g. "#2" means
364// "the second line above".
365const char* LogRecordCompressor::kLineBackwardReferenceFormat = "#%d";
366
367// Formatting string for back references. E.g. "#2:10" means
368// "the second line above, start from char 10 (0-based)".
369const char* LogRecordCompressor::kBackwardReferenceFormat = "#%d:%d";
370
371
372LogRecordCompressor::~LogRecordCompressor() {
373  for (int i = 0; i < buffer_.length(); ++i) {
374    buffer_[i].Dispose();
375  }
376}
377
378
379static int GetNumberLength(int number) {
380  ASSERT(number >= 0);
381  ASSERT(number < 10000);
382  if (number < 10) return 1;
383  if (number < 100) return 2;
384  if (number < 1000) return 3;
385  return 4;
386}
387
388
389int LogRecordCompressor::GetBackwardReferenceSize(int distance, int pos) {
390  // See kLineBackwardReferenceFormat and kBackwardReferenceFormat.
391  return pos == 0 ? GetNumberLength(distance) + 1
392      : GetNumberLength(distance) + GetNumberLength(pos) + 2;
393}
394
395
396void LogRecordCompressor::PrintBackwardReference(Vector<char> dest,
397                                                 int distance,
398                                                 int pos) {
399  if (pos == 0) {
400    OS::SNPrintF(dest, kLineBackwardReferenceFormat, distance);
401  } else {
402    OS::SNPrintF(dest, kBackwardReferenceFormat, distance, pos);
403  }
404}
405
406
407bool LogRecordCompressor::Store(const Vector<const char>& record) {
408  // Check if the record is the same as the last stored one.
409  if (curr_ != -1) {
410    Vector<const char>& curr = buffer_[curr_];
411    if (record.length() == curr.length()
412        && strncmp(record.start(), curr.start(), record.length()) == 0) {
413      return false;
414    }
415  }
416  // buffer_ is circular.
417  prev_ = curr_++;
418  curr_ %= buffer_.length();
419  Vector<char> record_copy = Vector<char>::New(record.length());
420  memcpy(record_copy.start(), record.start(), record.length());
421  buffer_[curr_].Dispose();
422  buffer_[curr_] =
423      Vector<const char>(record_copy.start(), record_copy.length());
424  return true;
425}
426
427
428bool LogRecordCompressor::RetrievePreviousCompressed(
429    Vector<char>* prev_record) {
430  if (prev_ == -1) return false;
431
432  int index = prev_;
433  // Distance from prev_.
434  int distance = 0;
435  // Best compression result among records in the buffer.
436  struct {
437    intptr_t truncated_len;
438    int distance;
439    int copy_from_pos;
440    int backref_size;
441  } best = {-1, 0, 0, 0};
442  Vector<const char>& prev = buffer_[prev_];
443  const char* const prev_start = prev.start();
444  const char* const prev_end = prev.start() + prev.length();
445  do {
446    // We're moving backwards until we reach the current record.
447    // Remember that buffer_ is circular.
448    if (--index == -1) index = buffer_.length() - 1;
449    ++distance;
450    if (index == curr_) break;
451
452    Vector<const char>& data = buffer_[index];
453    if (data.start() == NULL) break;
454    const char* const data_end = data.start() + data.length();
455    const char* prev_ptr = prev_end;
456    const char* data_ptr = data_end;
457    // Compare strings backwards, stop on the last matching character.
458    while (prev_ptr != prev_start && data_ptr != data.start()
459          && *(prev_ptr - 1) == *(data_ptr - 1)) {
460      --prev_ptr;
461      --data_ptr;
462    }
463    const intptr_t truncated_len = prev_end - prev_ptr;
464    const int copy_from_pos = data_ptr - data.start();
465    // Check if the length of compressed tail is enough.
466    if (truncated_len <= kMaxBackwardReferenceSize
467        && truncated_len <= GetBackwardReferenceSize(distance, copy_from_pos)) {
468      continue;
469    }
470
471    // Record compression results.
472    if (truncated_len > best.truncated_len) {
473      best.truncated_len = truncated_len;
474      best.distance = distance;
475      best.copy_from_pos = copy_from_pos;
476      best.backref_size = GetBackwardReferenceSize(distance, copy_from_pos);
477    }
478  } while (true);
479
480  if (best.distance == 0) {
481    // Can't compress the previous record. Return as is.
482    ASSERT(prev_record->length() >= prev.length());
483    memcpy(prev_record->start(), prev.start(), prev.length());
484    prev_record->Truncate(prev.length());
485  } else {
486    // Copy the uncompressible part unchanged.
487    const intptr_t unchanged_len = prev.length() - best.truncated_len;
488    // + 1 for '\0'.
489    ASSERT(prev_record->length() >= unchanged_len + best.backref_size + 1);
490    memcpy(prev_record->start(), prev.start(), unchanged_len);
491    // Append the backward reference.
492    Vector<char> backref(
493        prev_record->start() + unchanged_len, best.backref_size + 1);
494    PrintBackwardReference(backref, best.distance, best.copy_from_pos);
495    ASSERT(strlen(backref.start()) - best.backref_size == 0);
496    prev_record->Truncate(unchanged_len + best.backref_size);
497  }
498  return true;
499}
500
501#endif  // ENABLE_LOGGING_AND_PROFILING
502
503} }  // namespace v8::internal
504