log.cc revision d91b9f7d46489a9ee00f9cb415630299c76a502b
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 <stdarg.h> 29 30#include "v8.h" 31 32#include "bootstrapper.h" 33#include "global-handles.h" 34#include "log.h" 35#include "macro-assembler.h" 36#include "serialize.h" 37#include "string-stream.h" 38 39namespace v8 { 40namespace internal { 41 42#ifdef ENABLE_LOGGING_AND_PROFILING 43 44// 45// Sliding state window. Updates counters to keep track of the last 46// window of kBufferSize states. This is useful to track where we 47// spent our time. 48// 49class SlidingStateWindow { 50 public: 51 SlidingStateWindow(); 52 ~SlidingStateWindow(); 53 void AddState(StateTag state); 54 55 private: 56 static const int kBufferSize = 256; 57 int current_index_; 58 bool is_full_; 59 byte buffer_[kBufferSize]; 60 61 62 void IncrementStateCounter(StateTag state) { 63 Counters::state_counters[state].Increment(); 64 } 65 66 67 void DecrementStateCounter(StateTag state) { 68 Counters::state_counters[state].Decrement(); 69 } 70}; 71 72 73// 74// The Profiler samples pc and sp values for the main thread. 75// Each sample is appended to a circular buffer. 76// An independent thread removes data and writes it to the log. 77// This design minimizes the time spent in the sampler. 78// 79class Profiler: public Thread { 80 public: 81 Profiler(); 82 void Engage(); 83 void Disengage(); 84 85 // Inserts collected profiling data into buffer. 86 void Insert(TickSample* sample) { 87 if (paused_) 88 return; 89 90 if (Succ(head_) == tail_) { 91 overflow_ = true; 92 } else { 93 buffer_[head_] = *sample; 94 head_ = Succ(head_); 95 buffer_semaphore_->Signal(); // Tell we have an element. 96 } 97 } 98 99 // Waits for a signal and removes profiling data. 100 bool Remove(TickSample* sample) { 101 buffer_semaphore_->Wait(); // Wait for an element. 102 *sample = buffer_[tail_]; 103 bool result = overflow_; 104 tail_ = Succ(tail_); 105 overflow_ = false; 106 return result; 107 } 108 109 void Run(); 110 111 // Pause and Resume TickSample data collection. 112 static bool paused() { return paused_; } 113 static void pause() { paused_ = true; } 114 static void resume() { paused_ = false; } 115 116 private: 117 // Returns the next index in the cyclic buffer. 118 int Succ(int index) { return (index + 1) % kBufferSize; } 119 120 // Cyclic buffer for communicating profiling samples 121 // between the signal handler and the worker thread. 122 static const int kBufferSize = 128; 123 TickSample buffer_[kBufferSize]; // Buffer storage. 124 int head_; // Index to the buffer head. 125 int tail_; // Index to the buffer tail. 126 bool overflow_; // Tell whether a buffer overflow has occurred. 127 Semaphore* buffer_semaphore_; // Sempahore used for buffer synchronization. 128 129 // Tells whether profiler is engaged, that is, processing thread is stated. 130 bool engaged_; 131 132 // Tells whether worker thread should continue running. 133 bool running_; 134 135 // Tells whether we are currently recording tick samples. 136 static bool paused_; 137}; 138 139bool Profiler::paused_ = false; 140 141 142// 143// StackTracer implementation 144// 145void StackTracer::Trace(TickSample* sample) { 146 if (sample->state == GC) { 147 sample->frames_count = 0; 148 return; 149 } 150 151 const Address js_entry_sp = Top::js_entry_sp(Top::GetCurrentThread()); 152 if (js_entry_sp == 0) { 153 // Not executing JS now. 154 sample->frames_count = 0; 155 return; 156 } 157 158 const Address functionAddr = 159 sample->fp + JavaScriptFrameConstants::kFunctionOffset; 160 if (SafeStackFrameIterator::IsWithinBounds(sample->sp, js_entry_sp, 161 functionAddr)) { 162 sample->function = Memory::Address_at(functionAddr) - kHeapObjectTag; 163 } 164 165 int i = 0; 166 const Address callback = Logger::current_state_ != NULL ? 167 Logger::current_state_->external_callback() : NULL; 168 if (callback != NULL) { 169 sample->stack[i++] = callback; 170 } 171 172 SafeStackTraceFrameIterator it(sample->fp, sample->sp, 173 sample->sp, js_entry_sp); 174 while (!it.done() && i < TickSample::kMaxFramesCount) { 175 sample->stack[i++] = it.frame()->pc(); 176 it.Advance(); 177 } 178 sample->frames_count = i; 179} 180 181 182// 183// Ticker used to provide ticks to the profiler and the sliding state 184// window. 185// 186class Ticker: public Sampler { 187 public: 188 explicit Ticker(int interval): 189 Sampler(interval, FLAG_prof), window_(NULL), profiler_(NULL) {} 190 191 ~Ticker() { if (IsActive()) Stop(); } 192 193 void SampleStack(TickSample* sample) { 194 StackTracer::Trace(sample); 195 } 196 197 void Tick(TickSample* sample) { 198 if (profiler_) profiler_->Insert(sample); 199 if (window_) window_->AddState(sample->state); 200 } 201 202 void SetWindow(SlidingStateWindow* window) { 203 window_ = window; 204 if (!IsActive()) Start(); 205 } 206 207 void ClearWindow() { 208 window_ = NULL; 209 if (!profiler_ && IsActive()) Stop(); 210 } 211 212 void SetProfiler(Profiler* profiler) { 213 profiler_ = profiler; 214 if (!FLAG_prof_lazy && !IsActive()) Start(); 215 } 216 217 void ClearProfiler() { 218 profiler_ = NULL; 219 if (!window_ && IsActive()) Stop(); 220 } 221 222 private: 223 SlidingStateWindow* window_; 224 Profiler* profiler_; 225}; 226 227 228// 229// SlidingStateWindow implementation. 230// 231SlidingStateWindow::SlidingStateWindow(): current_index_(0), is_full_(false) { 232 for (int i = 0; i < kBufferSize; i++) { 233 buffer_[i] = static_cast<byte>(OTHER); 234 } 235 Logger::ticker_->SetWindow(this); 236} 237 238 239SlidingStateWindow::~SlidingStateWindow() { 240 Logger::ticker_->ClearWindow(); 241} 242 243 244void SlidingStateWindow::AddState(StateTag state) { 245 if (is_full_) { 246 DecrementStateCounter(static_cast<StateTag>(buffer_[current_index_])); 247 } else if (current_index_ == kBufferSize - 1) { 248 is_full_ = true; 249 } 250 buffer_[current_index_] = static_cast<byte>(state); 251 IncrementStateCounter(state); 252 ASSERT(IsPowerOf2(kBufferSize)); 253 current_index_ = (current_index_ + 1) & (kBufferSize - 1); 254} 255 256 257// 258// Profiler implementation. 259// 260Profiler::Profiler() 261 : head_(0), 262 tail_(0), 263 overflow_(false), 264 buffer_semaphore_(OS::CreateSemaphore(0)), 265 engaged_(false), 266 running_(false) { 267} 268 269 270void Profiler::Engage() { 271 if (engaged_) return; 272 engaged_ = true; 273 274 // TODO(mnaganov): This is actually "Chromium" mode. Flags need to be revised. 275 // http://code.google.com/p/v8/issues/detail?id=487 276 if (!FLAG_prof_lazy) { 277 OS::LogSharedLibraryAddresses(); 278 } 279 280 // Start thread processing the profiler buffer. 281 running_ = true; 282 Start(); 283 284 // Register to get ticks. 285 Logger::ticker_->SetProfiler(this); 286 287 Logger::ProfilerBeginEvent(); 288 Logger::LogAliases(); 289} 290 291 292void Profiler::Disengage() { 293 if (!engaged_) return; 294 295 // Stop receiving ticks. 296 Logger::ticker_->ClearProfiler(); 297 298 // Terminate the worker thread by setting running_ to false, 299 // inserting a fake element in the queue and then wait for 300 // the thread to terminate. 301 running_ = false; 302 TickSample sample; 303 // Reset 'paused_' flag, otherwise semaphore may not be signalled. 304 resume(); 305 Insert(&sample); 306 Join(); 307 308 LOG(UncheckedStringEvent("profiler", "end")); 309} 310 311 312void Profiler::Run() { 313 TickSample sample; 314 bool overflow = Logger::profiler_->Remove(&sample); 315 while (running_) { 316 LOG(TickEvent(&sample, overflow)); 317 overflow = Logger::profiler_->Remove(&sample); 318 } 319} 320 321 322// 323// Logger class implementation. 324// 325Ticker* Logger::ticker_ = NULL; 326Profiler* Logger::profiler_ = NULL; 327VMState* Logger::current_state_ = NULL; 328VMState Logger::bottom_state_(EXTERNAL); 329SlidingStateWindow* Logger::sliding_state_window_ = NULL; 330const char** Logger::log_events_ = NULL; 331CompressionHelper* Logger::compression_helper_ = NULL; 332bool Logger::is_logging_ = false; 333 334#define DECLARE_LONG_EVENT(ignore1, long_name, ignore2) long_name, 335const char* kLongLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = { 336 LOG_EVENTS_AND_TAGS_LIST(DECLARE_LONG_EVENT) 337}; 338#undef DECLARE_LONG_EVENT 339 340#define DECLARE_SHORT_EVENT(ignore1, ignore2, short_name) short_name, 341const char* kCompressedLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = { 342 LOG_EVENTS_AND_TAGS_LIST(DECLARE_SHORT_EVENT) 343}; 344#undef DECLARE_SHORT_EVENT 345 346 347void Logger::ProfilerBeginEvent() { 348 if (!Log::IsEnabled()) return; 349 LogMessageBuilder msg; 350 msg.Append("profiler,\"begin\",%d\n", kSamplingIntervalMs); 351 if (FLAG_compress_log) { 352 msg.Append("profiler,\"compression\",%d\n", kCompressionWindowSize); 353 } 354 msg.WriteToLogFile(); 355} 356 357 358void Logger::LogAliases() { 359 if (!Log::IsEnabled() || !FLAG_compress_log) return; 360 LogMessageBuilder msg; 361 for (int i = 0; i < NUMBER_OF_LOG_EVENTS; ++i) { 362 msg.Append("alias,%s,%s\n", 363 kCompressedLogEventsNames[i], kLongLogEventsNames[i]); 364 } 365 msg.WriteToLogFile(); 366} 367 368#endif // ENABLE_LOGGING_AND_PROFILING 369 370 371void Logger::Preamble(const char* content) { 372#ifdef ENABLE_LOGGING_AND_PROFILING 373 if (!Log::IsEnabled() || !FLAG_log_code) return; 374 LogMessageBuilder msg; 375 msg.WriteCStringToLogFile(content); 376#endif 377} 378 379 380void Logger::StringEvent(const char* name, const char* value) { 381#ifdef ENABLE_LOGGING_AND_PROFILING 382 if (FLAG_log) UncheckedStringEvent(name, value); 383#endif 384} 385 386 387#ifdef ENABLE_LOGGING_AND_PROFILING 388void Logger::UncheckedStringEvent(const char* name, const char* value) { 389 if (!Log::IsEnabled()) return; 390 LogMessageBuilder msg; 391 msg.Append("%s,\"%s\"\n", name, value); 392 msg.WriteToLogFile(); 393} 394#endif 395 396 397void Logger::IntEvent(const char* name, int value) { 398#ifdef ENABLE_LOGGING_AND_PROFILING 399 if (!Log::IsEnabled() || !FLAG_log) return; 400 LogMessageBuilder msg; 401 msg.Append("%s,%d\n", name, value); 402 msg.WriteToLogFile(); 403#endif 404} 405 406 407void Logger::HandleEvent(const char* name, Object** location) { 408#ifdef ENABLE_LOGGING_AND_PROFILING 409 if (!Log::IsEnabled() || !FLAG_log_handles) return; 410 LogMessageBuilder msg; 411 msg.Append("%s,0x%" V8PRIxPTR "\n", name, location); 412 msg.WriteToLogFile(); 413#endif 414} 415 416 417#ifdef ENABLE_LOGGING_AND_PROFILING 418// ApiEvent is private so all the calls come from the Logger class. It is the 419// caller's responsibility to ensure that log is enabled and that 420// FLAG_log_api is true. 421void Logger::ApiEvent(const char* format, ...) { 422 ASSERT(Log::IsEnabled() && FLAG_log_api); 423 LogMessageBuilder msg; 424 va_list ap; 425 va_start(ap, format); 426 msg.AppendVA(format, ap); 427 va_end(ap); 428 msg.WriteToLogFile(); 429} 430#endif 431 432 433void Logger::ApiNamedSecurityCheck(Object* key) { 434#ifdef ENABLE_LOGGING_AND_PROFILING 435 if (!Log::IsEnabled() || !FLAG_log_api) return; 436 if (key->IsString()) { 437 SmartPointer<char> str = 438 String::cast(key)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 439 ApiEvent("api,check-security,\"%s\"\n", *str); 440 } else if (key->IsUndefined()) { 441 ApiEvent("api,check-security,undefined\n"); 442 } else { 443 ApiEvent("api,check-security,['no-name']\n"); 444 } 445#endif 446} 447 448 449void Logger::SharedLibraryEvent(const char* library_path, 450 uintptr_t start, 451 uintptr_t end) { 452#ifdef ENABLE_LOGGING_AND_PROFILING 453 if (!Log::IsEnabled() || !FLAG_prof) return; 454 LogMessageBuilder msg; 455 msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n", 456 library_path, 457 start, 458 end); 459 msg.WriteToLogFile(); 460#endif 461} 462 463 464void Logger::SharedLibraryEvent(const wchar_t* library_path, 465 uintptr_t start, 466 uintptr_t end) { 467#ifdef ENABLE_LOGGING_AND_PROFILING 468 if (!Log::IsEnabled() || !FLAG_prof) return; 469 LogMessageBuilder msg; 470 msg.Append("shared-library,\"%ls\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n", 471 library_path, 472 start, 473 end); 474 msg.WriteToLogFile(); 475#endif 476} 477 478 479#ifdef ENABLE_LOGGING_AND_PROFILING 480void Logger::LogRegExpSource(Handle<JSRegExp> regexp) { 481 // Prints "/" + re.source + "/" + 482 // (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"") 483 LogMessageBuilder msg; 484 485 Handle<Object> source = GetProperty(regexp, "source"); 486 if (!source->IsString()) { 487 msg.Append("no source"); 488 return; 489 } 490 491 switch (regexp->TypeTag()) { 492 case JSRegExp::ATOM: 493 msg.Append('a'); 494 break; 495 default: 496 break; 497 } 498 msg.Append('/'); 499 msg.AppendDetailed(*Handle<String>::cast(source), false); 500 msg.Append('/'); 501 502 // global flag 503 Handle<Object> global = GetProperty(regexp, "global"); 504 if (global->IsTrue()) { 505 msg.Append('g'); 506 } 507 // ignorecase flag 508 Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase"); 509 if (ignorecase->IsTrue()) { 510 msg.Append('i'); 511 } 512 // multiline flag 513 Handle<Object> multiline = GetProperty(regexp, "multiline"); 514 if (multiline->IsTrue()) { 515 msg.Append('m'); 516 } 517 518 msg.WriteToLogFile(); 519} 520#endif // ENABLE_LOGGING_AND_PROFILING 521 522 523void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) { 524#ifdef ENABLE_LOGGING_AND_PROFILING 525 if (!Log::IsEnabled() || !FLAG_log_regexp) return; 526 LogMessageBuilder msg; 527 msg.Append("regexp-compile,"); 528 LogRegExpSource(regexp); 529 msg.Append(in_cache ? ",hit\n" : ",miss\n"); 530 msg.WriteToLogFile(); 531#endif 532} 533 534 535void Logger::LogRuntime(Vector<const char> format, JSArray* args) { 536#ifdef ENABLE_LOGGING_AND_PROFILING 537 if (!Log::IsEnabled() || !FLAG_log_runtime) return; 538 HandleScope scope; 539 LogMessageBuilder msg; 540 for (int i = 0; i < format.length(); i++) { 541 char c = format[i]; 542 if (c == '%' && i <= format.length() - 2) { 543 i++; 544 ASSERT('0' <= format[i] && format[i] <= '9'); 545 Object* obj = args->GetElement(format[i] - '0'); 546 i++; 547 switch (format[i]) { 548 case 's': 549 msg.AppendDetailed(String::cast(obj), false); 550 break; 551 case 'S': 552 msg.AppendDetailed(String::cast(obj), true); 553 break; 554 case 'r': 555 Logger::LogRegExpSource(Handle<JSRegExp>(JSRegExp::cast(obj))); 556 break; 557 case 'x': 558 msg.Append("0x%x", Smi::cast(obj)->value()); 559 break; 560 case 'i': 561 msg.Append("%i", Smi::cast(obj)->value()); 562 break; 563 default: 564 UNREACHABLE(); 565 } 566 } else { 567 msg.Append(c); 568 } 569 } 570 msg.Append('\n'); 571 msg.WriteToLogFile(); 572#endif 573} 574 575 576void Logger::ApiIndexedSecurityCheck(uint32_t index) { 577#ifdef ENABLE_LOGGING_AND_PROFILING 578 if (!Log::IsEnabled() || !FLAG_log_api) return; 579 ApiEvent("api,check-security,%u\n", index); 580#endif 581} 582 583 584void Logger::ApiNamedPropertyAccess(const char* tag, 585 JSObject* holder, 586 Object* name) { 587#ifdef ENABLE_LOGGING_AND_PROFILING 588 ASSERT(name->IsString()); 589 if (!Log::IsEnabled() || !FLAG_log_api) return; 590 String* class_name_obj = holder->class_name(); 591 SmartPointer<char> class_name = 592 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 593 SmartPointer<char> property_name = 594 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 595 Logger::ApiEvent("api,%s,\"%s\",\"%s\"\n", tag, *class_name, *property_name); 596#endif 597} 598 599void Logger::ApiIndexedPropertyAccess(const char* tag, 600 JSObject* holder, 601 uint32_t index) { 602#ifdef ENABLE_LOGGING_AND_PROFILING 603 if (!Log::IsEnabled() || !FLAG_log_api) return; 604 String* class_name_obj = holder->class_name(); 605 SmartPointer<char> class_name = 606 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 607 Logger::ApiEvent("api,%s,\"%s\",%u\n", tag, *class_name, index); 608#endif 609} 610 611void Logger::ApiObjectAccess(const char* tag, JSObject* object) { 612#ifdef ENABLE_LOGGING_AND_PROFILING 613 if (!Log::IsEnabled() || !FLAG_log_api) return; 614 String* class_name_obj = object->class_name(); 615 SmartPointer<char> class_name = 616 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 617 Logger::ApiEvent("api,%s,\"%s\"\n", tag, *class_name); 618#endif 619} 620 621 622void Logger::ApiEntryCall(const char* name) { 623#ifdef ENABLE_LOGGING_AND_PROFILING 624 if (!Log::IsEnabled() || !FLAG_log_api) return; 625 Logger::ApiEvent("api,%s\n", name); 626#endif 627} 628 629 630void Logger::NewEvent(const char* name, void* object, size_t size) { 631#ifdef ENABLE_LOGGING_AND_PROFILING 632 if (!Log::IsEnabled() || !FLAG_log) return; 633 LogMessageBuilder msg; 634 msg.Append("new,%s,0x%" V8PRIxPTR ",%u\n", name, object, 635 static_cast<unsigned int>(size)); 636 msg.WriteToLogFile(); 637#endif 638} 639 640 641void Logger::DeleteEvent(const char* name, void* object) { 642#ifdef ENABLE_LOGGING_AND_PROFILING 643 if (!Log::IsEnabled() || !FLAG_log) return; 644 LogMessageBuilder msg; 645 msg.Append("delete,%s,0x%" V8PRIxPTR "\n", name, object); 646 msg.WriteToLogFile(); 647#endif 648} 649 650 651#ifdef ENABLE_LOGGING_AND_PROFILING 652 653// A class that contains all common code dealing with record compression. 654class CompressionHelper { 655 public: 656 explicit CompressionHelper(int window_size) 657 : compressor_(window_size), repeat_count_(0) { } 658 659 // Handles storing message in compressor, retrieving the previous one and 660 // prefixing it with repeat count, if needed. 661 // Returns true if message needs to be written to log. 662 bool HandleMessage(LogMessageBuilder* msg) { 663 if (!msg->StoreInCompressor(&compressor_)) { 664 // Current message repeats the previous one, don't write it. 665 ++repeat_count_; 666 return false; 667 } 668 if (repeat_count_ == 0) { 669 return msg->RetrieveCompressedPrevious(&compressor_); 670 } 671 OS::SNPrintF(prefix_, "%s,%d,", 672 Logger::log_events_[Logger::REPEAT_META_EVENT], 673 repeat_count_ + 1); 674 repeat_count_ = 0; 675 return msg->RetrieveCompressedPrevious(&compressor_, prefix_.start()); 676 } 677 678 private: 679 LogRecordCompressor compressor_; 680 int repeat_count_; 681 EmbeddedVector<char, 20> prefix_; 682}; 683 684#endif // ENABLE_LOGGING_AND_PROFILING 685 686 687#ifdef ENABLE_LOGGING_AND_PROFILING 688void Logger::CallbackEventInternal(const char* prefix, const char* name, 689 Address entry_point) { 690 if (!Log::IsEnabled() || !FLAG_log_code) return; 691 LogMessageBuilder msg; 692 msg.Append("%s,%s,", 693 log_events_[CODE_CREATION_EVENT], log_events_[CALLBACK_TAG]); 694 msg.AppendAddress(entry_point); 695 msg.Append(",1,\"%s%s\"", prefix, name); 696 if (FLAG_compress_log) { 697 ASSERT(compression_helper_ != NULL); 698 if (!compression_helper_->HandleMessage(&msg)) return; 699 } 700 msg.Append('\n'); 701 msg.WriteToLogFile(); 702} 703#endif 704 705 706void Logger::CallbackEvent(String* name, Address entry_point) { 707#ifdef ENABLE_LOGGING_AND_PROFILING 708 if (!Log::IsEnabled() || !FLAG_log_code) return; 709 SmartPointer<char> str = 710 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 711 CallbackEventInternal("", *str, entry_point); 712#endif 713} 714 715 716void Logger::GetterCallbackEvent(String* name, Address entry_point) { 717#ifdef ENABLE_LOGGING_AND_PROFILING 718 if (!Log::IsEnabled() || !FLAG_log_code) return; 719 SmartPointer<char> str = 720 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 721 CallbackEventInternal("get ", *str, entry_point); 722#endif 723} 724 725 726void Logger::SetterCallbackEvent(String* name, Address entry_point) { 727#ifdef ENABLE_LOGGING_AND_PROFILING 728 if (!Log::IsEnabled() || !FLAG_log_code) return; 729 SmartPointer<char> str = 730 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 731 CallbackEventInternal("set ", *str, entry_point); 732#endif 733} 734 735 736void Logger::CodeCreateEvent(LogEventsAndTags tag, 737 Code* code, 738 const char* comment) { 739#ifdef ENABLE_LOGGING_AND_PROFILING 740 if (!Log::IsEnabled() || !FLAG_log_code) return; 741 LogMessageBuilder msg; 742 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]); 743 msg.AppendAddress(code->address()); 744 msg.Append(",%d,\"", code->ExecutableSize()); 745 for (const char* p = comment; *p != '\0'; p++) { 746 if (*p == '"') { 747 msg.Append('\\'); 748 } 749 msg.Append(*p); 750 } 751 msg.Append('"'); 752 if (FLAG_compress_log) { 753 ASSERT(compression_helper_ != NULL); 754 if (!compression_helper_->HandleMessage(&msg)) return; 755 } 756 msg.Append('\n'); 757 msg.WriteToLogFile(); 758#endif 759} 760 761 762void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, String* name) { 763#ifdef ENABLE_LOGGING_AND_PROFILING 764 if (!Log::IsEnabled() || !FLAG_log_code) return; 765 LogMessageBuilder msg; 766 SmartPointer<char> str = 767 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 768 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]); 769 msg.AppendAddress(code->address()); 770 msg.Append(",%d,\"%s\"", code->ExecutableSize(), *str); 771 if (FLAG_compress_log) { 772 ASSERT(compression_helper_ != NULL); 773 if (!compression_helper_->HandleMessage(&msg)) return; 774 } 775 msg.Append('\n'); 776 msg.WriteToLogFile(); 777#endif 778} 779 780 781void Logger::CodeCreateEvent(LogEventsAndTags tag, 782 Code* code, String* name, 783 String* source, int line) { 784#ifdef ENABLE_LOGGING_AND_PROFILING 785 if (!Log::IsEnabled() || !FLAG_log_code) return; 786 LogMessageBuilder msg; 787 SmartPointer<char> str = 788 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 789 SmartPointer<char> sourcestr = 790 source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 791 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]); 792 msg.AppendAddress(code->address()); 793 msg.Append(",%d,\"%s %s:%d\"", 794 code->ExecutableSize(), *str, *sourcestr, line); 795 if (FLAG_compress_log) { 796 ASSERT(compression_helper_ != NULL); 797 if (!compression_helper_->HandleMessage(&msg)) return; 798 } 799 msg.Append('\n'); 800 msg.WriteToLogFile(); 801#endif 802} 803 804 805void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) { 806#ifdef ENABLE_LOGGING_AND_PROFILING 807 if (!Log::IsEnabled() || !FLAG_log_code) return; 808 LogMessageBuilder msg; 809 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]); 810 msg.AppendAddress(code->address()); 811 msg.Append(",%d,\"args_count: %d\"", code->ExecutableSize(), args_count); 812 if (FLAG_compress_log) { 813 ASSERT(compression_helper_ != NULL); 814 if (!compression_helper_->HandleMessage(&msg)) return; 815 } 816 msg.Append('\n'); 817 msg.WriteToLogFile(); 818#endif 819} 820 821 822void Logger::RegExpCodeCreateEvent(Code* code, String* source) { 823#ifdef ENABLE_LOGGING_AND_PROFILING 824 if (!Log::IsEnabled() || !FLAG_log_code) return; 825 LogMessageBuilder msg; 826 msg.Append("%s,%s,", 827 log_events_[CODE_CREATION_EVENT], log_events_[REG_EXP_TAG]); 828 msg.AppendAddress(code->address()); 829 msg.Append(",%d,\"", code->ExecutableSize()); 830 msg.AppendDetailed(source, false); 831 msg.Append('\"'); 832 if (FLAG_compress_log) { 833 ASSERT(compression_helper_ != NULL); 834 if (!compression_helper_->HandleMessage(&msg)) return; 835 } 836 msg.Append('\n'); 837 msg.WriteToLogFile(); 838#endif 839} 840 841 842void Logger::CodeMoveEvent(Address from, Address to) { 843#ifdef ENABLE_LOGGING_AND_PROFILING 844 MoveEventInternal(CODE_MOVE_EVENT, from, to); 845#endif 846} 847 848 849void Logger::CodeDeleteEvent(Address from) { 850#ifdef ENABLE_LOGGING_AND_PROFILING 851 DeleteEventInternal(CODE_DELETE_EVENT, from); 852#endif 853} 854 855 856void Logger::SnapshotPositionEvent(Address addr, int pos) { 857#ifdef ENABLE_LOGGING_AND_PROFILING 858 if (!Log::IsEnabled() || !FLAG_log_snapshot_positions) return; 859 LogMessageBuilder msg; 860 msg.Append("%s,", log_events_[SNAPSHOT_POSITION_EVENT]); 861 msg.AppendAddress(addr); 862 msg.Append(",%d", pos); 863 if (FLAG_compress_log) { 864 ASSERT(compression_helper_ != NULL); 865 if (!compression_helper_->HandleMessage(&msg)) return; 866 } 867 msg.Append('\n'); 868 msg.WriteToLogFile(); 869#endif 870} 871 872 873void Logger::FunctionCreateEvent(JSFunction* function) { 874#ifdef ENABLE_LOGGING_AND_PROFILING 875 static Address prev_code = NULL; 876 if (!Log::IsEnabled() || !FLAG_log_code) return; 877 LogMessageBuilder msg; 878 msg.Append("%s,", log_events_[FUNCTION_CREATION_EVENT]); 879 msg.AppendAddress(function->address()); 880 msg.Append(','); 881 msg.AppendAddress(function->code()->address(), prev_code); 882 prev_code = function->code()->address(); 883 if (FLAG_compress_log) { 884 ASSERT(compression_helper_ != NULL); 885 if (!compression_helper_->HandleMessage(&msg)) return; 886 } 887 msg.Append('\n'); 888 msg.WriteToLogFile(); 889#endif 890} 891 892 893void Logger::FunctionMoveEvent(Address from, Address to) { 894#ifdef ENABLE_LOGGING_AND_PROFILING 895 MoveEventInternal(FUNCTION_MOVE_EVENT, from, to); 896#endif 897} 898 899 900void Logger::FunctionDeleteEvent(Address from) { 901#ifdef ENABLE_LOGGING_AND_PROFILING 902 DeleteEventInternal(FUNCTION_DELETE_EVENT, from); 903#endif 904} 905 906 907#ifdef ENABLE_LOGGING_AND_PROFILING 908void Logger::MoveEventInternal(LogEventsAndTags event, 909 Address from, 910 Address to) { 911 static Address prev_to_ = NULL; 912 if (!Log::IsEnabled() || !FLAG_log_code) return; 913 LogMessageBuilder msg; 914 msg.Append("%s,", log_events_[event]); 915 msg.AppendAddress(from); 916 msg.Append(','); 917 msg.AppendAddress(to, prev_to_); 918 prev_to_ = to; 919 if (FLAG_compress_log) { 920 ASSERT(compression_helper_ != NULL); 921 if (!compression_helper_->HandleMessage(&msg)) return; 922 } 923 msg.Append('\n'); 924 msg.WriteToLogFile(); 925} 926#endif 927 928 929#ifdef ENABLE_LOGGING_AND_PROFILING 930void Logger::DeleteEventInternal(LogEventsAndTags event, Address from) { 931 if (!Log::IsEnabled() || !FLAG_log_code) return; 932 LogMessageBuilder msg; 933 msg.Append("%s,", log_events_[event]); 934 msg.AppendAddress(from); 935 if (FLAG_compress_log) { 936 ASSERT(compression_helper_ != NULL); 937 if (!compression_helper_->HandleMessage(&msg)) return; 938 } 939 msg.Append('\n'); 940 msg.WriteToLogFile(); 941} 942#endif 943 944 945void Logger::ResourceEvent(const char* name, const char* tag) { 946#ifdef ENABLE_LOGGING_AND_PROFILING 947 if (!Log::IsEnabled() || !FLAG_log) return; 948 LogMessageBuilder msg; 949 msg.Append("%s,%s,", name, tag); 950 951 uint32_t sec, usec; 952 if (OS::GetUserTime(&sec, &usec) != -1) { 953 msg.Append("%d,%d,", sec, usec); 954 } 955 msg.Append("%.0f", OS::TimeCurrentMillis()); 956 957 msg.Append('\n'); 958 msg.WriteToLogFile(); 959#endif 960} 961 962 963void Logger::SuspectReadEvent(String* name, Object* obj) { 964#ifdef ENABLE_LOGGING_AND_PROFILING 965 if (!Log::IsEnabled() || !FLAG_log_suspect) return; 966 LogMessageBuilder msg; 967 String* class_name = obj->IsJSObject() 968 ? JSObject::cast(obj)->class_name() 969 : Heap::empty_string(); 970 msg.Append("suspect-read,"); 971 msg.Append(class_name); 972 msg.Append(','); 973 msg.Append('"'); 974 msg.Append(name); 975 msg.Append('"'); 976 msg.Append('\n'); 977 msg.WriteToLogFile(); 978#endif 979} 980 981 982void Logger::HeapSampleBeginEvent(const char* space, const char* kind) { 983#ifdef ENABLE_LOGGING_AND_PROFILING 984 if (!Log::IsEnabled() || !FLAG_log_gc) return; 985 LogMessageBuilder msg; 986 // Using non-relative system time in order to be able to synchronize with 987 // external memory profiling events (e.g. DOM memory size). 988 msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f\n", 989 space, kind, OS::TimeCurrentMillis()); 990 msg.WriteToLogFile(); 991#endif 992} 993 994 995void Logger::HeapSampleStats(const char* space, const char* kind, 996 int capacity, int used) { 997#ifdef ENABLE_LOGGING_AND_PROFILING 998 if (!Log::IsEnabled() || !FLAG_log_gc) return; 999 LogMessageBuilder msg; 1000 msg.Append("heap-sample-stats,\"%s\",\"%s\",%d,%d\n", 1001 space, kind, capacity, used); 1002 msg.WriteToLogFile(); 1003#endif 1004} 1005 1006 1007void Logger::HeapSampleEndEvent(const char* space, const char* kind) { 1008#ifdef ENABLE_LOGGING_AND_PROFILING 1009 if (!Log::IsEnabled() || !FLAG_log_gc) return; 1010 LogMessageBuilder msg; 1011 msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind); 1012 msg.WriteToLogFile(); 1013#endif 1014} 1015 1016 1017void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) { 1018#ifdef ENABLE_LOGGING_AND_PROFILING 1019 if (!Log::IsEnabled() || !FLAG_log_gc) return; 1020 LogMessageBuilder msg; 1021 msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes); 1022 msg.WriteToLogFile(); 1023#endif 1024} 1025 1026 1027void Logger::HeapSampleJSConstructorEvent(const char* constructor, 1028 int number, int bytes) { 1029#ifdef ENABLE_LOGGING_AND_PROFILING 1030 if (!Log::IsEnabled() || !FLAG_log_gc) return; 1031 LogMessageBuilder msg; 1032 msg.Append("heap-js-cons-item,%s,%d,%d\n", constructor, number, bytes); 1033 msg.WriteToLogFile(); 1034#endif 1035} 1036 1037 1038void Logger::HeapSampleJSRetainersEvent( 1039 const char* constructor, const char* event) { 1040#ifdef ENABLE_LOGGING_AND_PROFILING 1041 if (!Log::IsEnabled() || !FLAG_log_gc) return; 1042 // Event starts with comma, so we don't have it in the format string. 1043 static const char* event_text = "heap-js-ret-item,%s"; 1044 // We take placeholder strings into account, but it's OK to be conservative. 1045 static const int event_text_len = StrLength(event_text); 1046 const int cons_len = StrLength(constructor); 1047 const int event_len = StrLength(event); 1048 int pos = 0; 1049 // Retainer lists can be long. We may need to split them into multiple events. 1050 do { 1051 LogMessageBuilder msg; 1052 msg.Append(event_text, constructor); 1053 int to_write = event_len - pos; 1054 if (to_write > Log::kMessageBufferSize - (cons_len + event_text_len)) { 1055 int cut_pos = pos + Log::kMessageBufferSize - (cons_len + event_text_len); 1056 ASSERT(cut_pos < event_len); 1057 while (cut_pos > pos && event[cut_pos] != ',') --cut_pos; 1058 if (event[cut_pos] != ',') { 1059 // Crash in debug mode, skip in release mode. 1060 ASSERT(false); 1061 return; 1062 } 1063 // Append a piece of event that fits, without trailing comma. 1064 msg.AppendStringPart(event + pos, cut_pos - pos); 1065 // Start next piece with comma. 1066 pos = cut_pos; 1067 } else { 1068 msg.Append("%s", event + pos); 1069 pos += event_len; 1070 } 1071 msg.Append('\n'); 1072 msg.WriteToLogFile(); 1073 } while (pos < event_len); 1074#endif 1075} 1076 1077 1078void Logger::HeapSampleJSProducerEvent(const char* constructor, 1079 Address* stack) { 1080#ifdef ENABLE_LOGGING_AND_PROFILING 1081 if (!Log::IsEnabled() || !FLAG_log_gc) return; 1082 LogMessageBuilder msg; 1083 msg.Append("heap-js-prod-item,%s", constructor); 1084 while (*stack != NULL) { 1085 msg.Append(",0x%" V8PRIxPTR, *stack++); 1086 } 1087 msg.Append("\n"); 1088 msg.WriteToLogFile(); 1089#endif 1090} 1091 1092 1093void Logger::DebugTag(const char* call_site_tag) { 1094#ifdef ENABLE_LOGGING_AND_PROFILING 1095 if (!Log::IsEnabled() || !FLAG_log) return; 1096 LogMessageBuilder msg; 1097 msg.Append("debug-tag,%s\n", call_site_tag); 1098 msg.WriteToLogFile(); 1099#endif 1100} 1101 1102 1103void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) { 1104#ifdef ENABLE_LOGGING_AND_PROFILING 1105 if (!Log::IsEnabled() || !FLAG_log) return; 1106 StringBuilder s(parameter.length() + 1); 1107 for (int i = 0; i < parameter.length(); ++i) { 1108 s.AddCharacter(static_cast<char>(parameter[i])); 1109 } 1110 char* parameter_string = s.Finalize(); 1111 LogMessageBuilder msg; 1112 msg.Append("debug-queue-event,%s,%15.3f,%s\n", 1113 event_type, 1114 OS::TimeCurrentMillis(), 1115 parameter_string); 1116 DeleteArray(parameter_string); 1117 msg.WriteToLogFile(); 1118#endif 1119} 1120 1121 1122#ifdef ENABLE_LOGGING_AND_PROFILING 1123void Logger::TickEvent(TickSample* sample, bool overflow) { 1124 if (!Log::IsEnabled() || !FLAG_prof) return; 1125 static Address prev_sp = NULL; 1126 static Address prev_function = NULL; 1127 LogMessageBuilder msg; 1128 msg.Append("%s,", log_events_[TICK_EVENT]); 1129 Address prev_addr = sample->pc; 1130 msg.AppendAddress(prev_addr); 1131 msg.Append(','); 1132 msg.AppendAddress(sample->sp, prev_sp); 1133 prev_sp = sample->sp; 1134 msg.Append(','); 1135 msg.AppendAddress(sample->function, prev_function); 1136 prev_function = sample->function; 1137 msg.Append(",%d", static_cast<int>(sample->state)); 1138 if (overflow) { 1139 msg.Append(",overflow"); 1140 } 1141 for (int i = 0; i < sample->frames_count; ++i) { 1142 msg.Append(','); 1143 msg.AppendAddress(sample->stack[i], prev_addr); 1144 prev_addr = sample->stack[i]; 1145 } 1146 if (FLAG_compress_log) { 1147 ASSERT(compression_helper_ != NULL); 1148 if (!compression_helper_->HandleMessage(&msg)) return; 1149 } 1150 msg.Append('\n'); 1151 msg.WriteToLogFile(); 1152} 1153 1154 1155int Logger::GetActiveProfilerModules() { 1156 int result = PROFILER_MODULE_NONE; 1157 if (!profiler_->paused()) { 1158 result |= PROFILER_MODULE_CPU; 1159 } 1160 if (FLAG_log_gc) { 1161 result |= PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS; 1162 } 1163 return result; 1164} 1165 1166 1167void Logger::PauseProfiler(int flags) { 1168 if (!Log::IsEnabled()) return; 1169 const int active_modules = GetActiveProfilerModules(); 1170 const int modules_to_disable = active_modules & flags; 1171 if (modules_to_disable == PROFILER_MODULE_NONE) return; 1172 1173 if (modules_to_disable & PROFILER_MODULE_CPU) { 1174 profiler_->pause(); 1175 if (FLAG_prof_lazy) { 1176 if (!FLAG_sliding_state_window) ticker_->Stop(); 1177 FLAG_log_code = false; 1178 // Must be the same message as Log::kDynamicBufferSeal. 1179 LOG(UncheckedStringEvent("profiler", "pause")); 1180 } 1181 } 1182 if (modules_to_disable & 1183 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) { 1184 FLAG_log_gc = false; 1185 } 1186 // Turn off logging if no active modules remain. 1187 if ((active_modules & ~flags) == PROFILER_MODULE_NONE) { 1188 is_logging_ = false; 1189 } 1190} 1191 1192 1193void Logger::ResumeProfiler(int flags) { 1194 if (!Log::IsEnabled()) return; 1195 const int modules_to_enable = ~GetActiveProfilerModules() & flags; 1196 if (modules_to_enable != PROFILER_MODULE_NONE) { 1197 is_logging_ = true; 1198 } 1199 if (modules_to_enable & PROFILER_MODULE_CPU) { 1200 if (FLAG_prof_lazy) { 1201 profiler_->Engage(); 1202 LOG(UncheckedStringEvent("profiler", "resume")); 1203 FLAG_log_code = true; 1204 LogCompiledFunctions(); 1205 LogFunctionObjects(); 1206 LogAccessorCallbacks(); 1207 if (!FLAG_sliding_state_window) ticker_->Start(); 1208 } 1209 profiler_->resume(); 1210 } 1211 if (modules_to_enable & 1212 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) { 1213 FLAG_log_gc = true; 1214 } 1215} 1216 1217 1218// This function can be called when Log's mutex is acquired, 1219// either from main or Profiler's thread. 1220void Logger::StopLoggingAndProfiling() { 1221 Log::stop(); 1222 PauseProfiler(PROFILER_MODULE_CPU); 1223} 1224 1225 1226bool Logger::IsProfilerSamplerActive() { 1227 return ticker_->IsActive(); 1228} 1229 1230 1231int Logger::GetLogLines(int from_pos, char* dest_buf, int max_size) { 1232 return Log::GetLogLines(from_pos, dest_buf, max_size); 1233} 1234 1235 1236static int EnumerateCompiledFunctions(Handle<SharedFunctionInfo>* sfis) { 1237 AssertNoAllocation no_alloc; 1238 int compiled_funcs_count = 0; 1239 HeapIterator iterator; 1240 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) { 1241 if (!obj->IsSharedFunctionInfo()) continue; 1242 SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj); 1243 if (sfi->is_compiled() 1244 && (!sfi->script()->IsScript() 1245 || Script::cast(sfi->script())->HasValidSource())) { 1246 if (sfis != NULL) 1247 sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi); 1248 ++compiled_funcs_count; 1249 } 1250 } 1251 return compiled_funcs_count; 1252} 1253 1254 1255void Logger::LogCodeObject(Object* object) { 1256 if (FLAG_log_code) { 1257 Code* code_object = Code::cast(object); 1258 LogEventsAndTags tag = Logger::STUB_TAG; 1259 const char* description = "Unknown code from the snapshot"; 1260 switch (code_object->kind()) { 1261 case Code::FUNCTION: 1262 return; // We log this later using LogCompiledFunctions. 1263 case Code::STUB: 1264 description = CodeStub::MajorName(code_object->major_key()); 1265 tag = Logger::STUB_TAG; 1266 break; 1267 case Code::BUILTIN: 1268 description = "A builtin from the snapshot"; 1269 tag = Logger::BUILTIN_TAG; 1270 break; 1271 case Code::KEYED_LOAD_IC: 1272 description = "A keyed load IC from the snapshot"; 1273 tag = Logger::KEYED_LOAD_IC_TAG; 1274 break; 1275 case Code::LOAD_IC: 1276 description = "A load IC from the snapshot"; 1277 tag = Logger::LOAD_IC_TAG; 1278 break; 1279 case Code::STORE_IC: 1280 description = "A store IC from the snapshot"; 1281 tag = Logger::STORE_IC_TAG; 1282 break; 1283 case Code::KEYED_STORE_IC: 1284 description = "A keyed store IC from the snapshot"; 1285 tag = Logger::KEYED_STORE_IC_TAG; 1286 break; 1287 case Code::CALL_IC: 1288 description = "A call IC from the snapshot"; 1289 tag = Logger::CALL_IC_TAG; 1290 break; 1291 } 1292 LOG(CodeCreateEvent(tag, code_object, description)); 1293 } 1294} 1295 1296 1297void Logger::LogCompiledFunctions() { 1298 HandleScope scope; 1299 const int compiled_funcs_count = EnumerateCompiledFunctions(NULL); 1300 Handle<SharedFunctionInfo>* sfis = 1301 NewArray< Handle<SharedFunctionInfo> >(compiled_funcs_count); 1302 EnumerateCompiledFunctions(sfis); 1303 1304 // During iteration, there can be heap allocation due to 1305 // GetScriptLineNumber call. 1306 for (int i = 0; i < compiled_funcs_count; ++i) { 1307 Handle<SharedFunctionInfo> shared = sfis[i]; 1308 Handle<String> name(String::cast(shared->name())); 1309 Handle<String> func_name(name->length() > 0 ? 1310 *name : shared->inferred_name()); 1311 if (shared->script()->IsScript()) { 1312 Handle<Script> script(Script::cast(shared->script())); 1313 if (script->name()->IsString()) { 1314 Handle<String> script_name(String::cast(script->name())); 1315 int line_num = GetScriptLineNumber(script, shared->start_position()); 1316 if (line_num > 0) { 1317 LOG(CodeCreateEvent(Logger::LAZY_COMPILE_TAG, 1318 shared->code(), *func_name, 1319 *script_name, line_num + 1)); 1320 } else { 1321 // Can't distinguish enum and script here, so always use Script. 1322 LOG(CodeCreateEvent(Logger::SCRIPT_TAG, 1323 shared->code(), *script_name)); 1324 } 1325 } else { 1326 LOG(CodeCreateEvent( 1327 Logger::LAZY_COMPILE_TAG, shared->code(), *func_name)); 1328 } 1329 } else if (shared->function_data()->IsFunctionTemplateInfo()) { 1330 // API function. 1331 FunctionTemplateInfo* fun_data = 1332 FunctionTemplateInfo::cast(shared->function_data()); 1333 Object* raw_call_data = fun_data->call_code(); 1334 if (!raw_call_data->IsUndefined()) { 1335 CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data); 1336 Object* callback_obj = call_data->callback(); 1337 Address entry_point = v8::ToCData<Address>(callback_obj); 1338 LOG(CallbackEvent(*func_name, entry_point)); 1339 } 1340 } else { 1341 LOG(CodeCreateEvent( 1342 Logger::LAZY_COMPILE_TAG, shared->code(), *func_name)); 1343 } 1344 } 1345 1346 DeleteArray(sfis); 1347} 1348 1349 1350void Logger::LogFunctionObjects() { 1351 AssertNoAllocation no_alloc; 1352 HeapIterator iterator; 1353 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) { 1354 if (!obj->IsJSFunction()) continue; 1355 JSFunction* jsf = JSFunction::cast(obj); 1356 if (!jsf->is_compiled()) continue; 1357 LOG(FunctionCreateEvent(jsf)); 1358 } 1359} 1360 1361 1362void Logger::LogAccessorCallbacks() { 1363 AssertNoAllocation no_alloc; 1364 HeapIterator iterator; 1365 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) { 1366 if (!obj->IsAccessorInfo()) continue; 1367 AccessorInfo* ai = AccessorInfo::cast(obj); 1368 if (!ai->name()->IsString()) continue; 1369 String* name = String::cast(ai->name()); 1370 Address getter_entry = v8::ToCData<Address>(ai->getter()); 1371 if (getter_entry != 0) { 1372 LOG(GetterCallbackEvent(name, getter_entry)); 1373 } 1374 Address setter_entry = v8::ToCData<Address>(ai->setter()); 1375 if (setter_entry != 0) { 1376 LOG(SetterCallbackEvent(name, setter_entry)); 1377 } 1378 } 1379} 1380 1381#endif 1382 1383 1384bool Logger::Setup() { 1385#ifdef ENABLE_LOGGING_AND_PROFILING 1386 // --log-all enables all the log flags. 1387 if (FLAG_log_all) { 1388 FLAG_log_runtime = true; 1389 FLAG_log_api = true; 1390 FLAG_log_code = true; 1391 FLAG_log_gc = true; 1392 FLAG_log_suspect = true; 1393 FLAG_log_handles = true; 1394 FLAG_log_regexp = true; 1395 } 1396 1397 // --prof implies --log-code. 1398 if (FLAG_prof) FLAG_log_code = true; 1399 1400 // --prof_lazy controls --log-code, implies --noprof_auto. 1401 if (FLAG_prof_lazy) { 1402 FLAG_log_code = false; 1403 FLAG_prof_auto = false; 1404 } 1405 1406 bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api 1407 || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect 1408 || FLAG_log_regexp || FLAG_log_state_changes; 1409 1410 bool open_log_file = start_logging || FLAG_prof_lazy; 1411 1412 // If we're logging anything, we need to open the log file. 1413 if (open_log_file) { 1414 if (strcmp(FLAG_logfile, "-") == 0) { 1415 Log::OpenStdout(); 1416 } else if (strcmp(FLAG_logfile, "*") == 0) { 1417 Log::OpenMemoryBuffer(); 1418 } else if (strchr(FLAG_logfile, '%') != NULL) { 1419 // If there's a '%' in the log file name we have to expand 1420 // placeholders. 1421 HeapStringAllocator allocator; 1422 StringStream stream(&allocator); 1423 for (const char* p = FLAG_logfile; *p; p++) { 1424 if (*p == '%') { 1425 p++; 1426 switch (*p) { 1427 case '\0': 1428 // If there's a % at the end of the string we back up 1429 // one character so we can escape the loop properly. 1430 p--; 1431 break; 1432 case 't': { 1433 // %t expands to the current time in milliseconds. 1434 double time = OS::TimeCurrentMillis(); 1435 stream.Add("%.0f", FmtElm(time)); 1436 break; 1437 } 1438 case '%': 1439 // %% expands (contracts really) to %. 1440 stream.Put('%'); 1441 break; 1442 default: 1443 // All other %'s expand to themselves. 1444 stream.Put('%'); 1445 stream.Put(*p); 1446 break; 1447 } 1448 } else { 1449 stream.Put(*p); 1450 } 1451 } 1452 SmartPointer<const char> expanded = stream.ToCString(); 1453 Log::OpenFile(*expanded); 1454 } else { 1455 Log::OpenFile(FLAG_logfile); 1456 } 1457 } 1458 1459 current_state_ = &bottom_state_; 1460 1461 ticker_ = new Ticker(kSamplingIntervalMs); 1462 1463 if (FLAG_sliding_state_window && sliding_state_window_ == NULL) { 1464 sliding_state_window_ = new SlidingStateWindow(); 1465 } 1466 1467 log_events_ = FLAG_compress_log ? 1468 kCompressedLogEventsNames : kLongLogEventsNames; 1469 if (FLAG_compress_log) { 1470 compression_helper_ = new CompressionHelper(kCompressionWindowSize); 1471 } 1472 1473 is_logging_ = start_logging; 1474 1475 if (FLAG_prof) { 1476 profiler_ = new Profiler(); 1477 if (!FLAG_prof_auto) { 1478 profiler_->pause(); 1479 } else { 1480 is_logging_ = true; 1481 } 1482 if (!FLAG_prof_lazy) { 1483 profiler_->Engage(); 1484 } 1485 } 1486 1487 LogMessageBuilder::set_write_failure_handler(StopLoggingAndProfiling); 1488 1489 return true; 1490 1491#else 1492 return false; 1493#endif 1494} 1495 1496 1497void Logger::TearDown() { 1498#ifdef ENABLE_LOGGING_AND_PROFILING 1499 LogMessageBuilder::set_write_failure_handler(NULL); 1500 1501 // Stop the profiler before closing the file. 1502 if (profiler_ != NULL) { 1503 profiler_->Disengage(); 1504 delete profiler_; 1505 profiler_ = NULL; 1506 } 1507 1508 delete compression_helper_; 1509 compression_helper_ = NULL; 1510 1511 delete sliding_state_window_; 1512 sliding_state_window_ = NULL; 1513 1514 delete ticker_; 1515 ticker_ = NULL; 1516 1517 Log::Close(); 1518#endif 1519} 1520 1521 1522void Logger::EnableSlidingStateWindow() { 1523#ifdef ENABLE_LOGGING_AND_PROFILING 1524 // If the ticker is NULL, Logger::Setup has not been called yet. In 1525 // that case, we set the sliding_state_window flag so that the 1526 // sliding window computation will be started when Logger::Setup is 1527 // called. 1528 if (ticker_ == NULL) { 1529 FLAG_sliding_state_window = true; 1530 return; 1531 } 1532 // Otherwise, if the sliding state window computation has not been 1533 // started we do it now. 1534 if (sliding_state_window_ == NULL) { 1535 sliding_state_window_ = new SlidingStateWindow(); 1536 } 1537#endif 1538} 1539 1540 1541} } // namespace v8::internal 1542