| OLD | NEW |
| 1 // Copyright (c) 2012 The Chromium Authors. All rights reserved. | 1 // Copyright (c) 2012 The Chromium Authors. All rights reserved. |
| 2 // Use of this source code is governed by a BSD-style license that can be | 2 // Use of this source code is governed by a BSD-style license that can be |
| 3 // found in the LICENSE file. | 3 // found in the LICENSE file. |
| 4 | 4 |
| 5 #include "base/debug/trace_event_impl.h" | 5 #include "base/debug/trace_event_impl.h" |
| 6 | 6 |
| 7 #include <algorithm> | 7 #include <algorithm> |
| 8 | 8 |
| 9 #include "base/base_switches.h" | 9 #include "base/base_switches.h" |
| 10 #include "base/bind.h" | 10 #include "base/bind.h" |
| (...skipping 14 matching lines...) Expand all Loading... |
| 25 #include "base/strings/string_tokenizer.h" | 25 #include "base/strings/string_tokenizer.h" |
| 26 #include "base/strings/string_util.h" | 26 #include "base/strings/string_util.h" |
| 27 #include "base/strings/stringprintf.h" | 27 #include "base/strings/stringprintf.h" |
| 28 #include "base/strings/utf_string_conversions.h" | 28 #include "base/strings/utf_string_conversions.h" |
| 29 #include "base/synchronization/cancellation_flag.h" | 29 #include "base/synchronization/cancellation_flag.h" |
| 30 #include "base/synchronization/waitable_event.h" | 30 #include "base/synchronization/waitable_event.h" |
| 31 #include "base/sys_info.h" | 31 #include "base/sys_info.h" |
| 32 #include "base/third_party/dynamic_annotations/dynamic_annotations.h" | 32 #include "base/third_party/dynamic_annotations/dynamic_annotations.h" |
| 33 #include "base/threading/platform_thread.h" | 33 #include "base/threading/platform_thread.h" |
| 34 #include "base/threading/thread_id_name_manager.h" | 34 #include "base/threading/thread_id_name_manager.h" |
| 35 #include "base/threading/worker_pool.h" |
| 35 #include "base/time/time.h" | 36 #include "base/time/time.h" |
| 36 | 37 |
| 37 #if defined(OS_WIN) | 38 #if defined(OS_WIN) |
| 38 #include "base/debug/trace_event_win.h" | 39 #include "base/debug/trace_event_win.h" |
| 39 #endif | 40 #endif |
| 40 | 41 |
| 41 class DeleteTraceLogForTesting { | 42 class DeleteTraceLogForTesting { |
| 42 public: | 43 public: |
| 43 static void Delete() { | 44 static void Delete() { |
| 44 Singleton<base::debug::TraceLog, | 45 Singleton<base::debug::TraceLog, |
| (...skipping 21 matching lines...) Expand all Loading... |
| 66 const char kEnableSampling[] = "enable-sampling"; | 67 const char kEnableSampling[] = "enable-sampling"; |
| 67 const char kEnableSystrace[] = "enable-systrace"; | 68 const char kEnableSystrace[] = "enable-systrace"; |
| 68 | 69 |
| 69 // Controls the number of trace events we will buffer in-memory | 70 // Controls the number of trace events we will buffer in-memory |
| 70 // before throwing them away. | 71 // before throwing them away. |
| 71 const size_t kTraceBufferChunkSize = TraceBufferChunk::kTraceBufferChunkSize; | 72 const size_t kTraceBufferChunkSize = TraceBufferChunk::kTraceBufferChunkSize; |
| 72 const size_t kTraceEventVectorBigBufferChunks = | 73 const size_t kTraceEventVectorBigBufferChunks = |
| 73 512000000 / kTraceBufferChunkSize; | 74 512000000 / kTraceBufferChunkSize; |
| 74 const size_t kTraceEventVectorBufferChunks = 256000 / kTraceBufferChunkSize; | 75 const size_t kTraceEventVectorBufferChunks = 256000 / kTraceBufferChunkSize; |
| 75 const size_t kTraceEventRingBufferChunks = kTraceEventVectorBufferChunks / 4; | 76 const size_t kTraceEventRingBufferChunks = kTraceEventVectorBufferChunks / 4; |
| 76 const size_t kTraceEventBatchChunks = 1000 / kTraceBufferChunkSize; | 77 const size_t kTraceEventBufferSizeInBytes = 10 * 1024 * 1024; |
| 77 // Can store results for 30 seconds with 1 ms sampling interval. | 78 // Can store results for 30 seconds with 1 ms sampling interval. |
| 78 const size_t kMonitorTraceEventBufferChunks = 30000 / kTraceBufferChunkSize; | 79 const size_t kMonitorTraceEventBufferChunks = 30000 / kTraceBufferChunkSize; |
| 79 // ECHO_TO_CONSOLE needs a small buffer to hold the unfinished COMPLETE events. | 80 // ECHO_TO_CONSOLE needs a small buffer to hold the unfinished COMPLETE events. |
| 80 const size_t kEchoToConsoleTraceEventBufferChunks = 256; | 81 const size_t kEchoToConsoleTraceEventBufferChunks = 256; |
| 81 | 82 |
| 82 const int kThreadFlushTimeoutMs = 3000; | 83 const int kThreadFlushTimeoutMs = 3000; |
| 83 | 84 |
| 84 #if !defined(OS_NACL) | 85 #if !defined(OS_NACL) |
| 85 // These categories will cause deadlock when ECHO_TO_CONSOLE. crbug.com/325575. | 86 // These categories will cause deadlock when ECHO_TO_CONSOLE. crbug.com/325575. |
| 86 const char kEchoToConsoleCategoryFilter[] = "-ipc,-task"; | 87 const char kEchoToConsoleCategoryFilter[] = "-ipc,-task"; |
| (...skipping 1117 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 1204 process_sort_index_(0), | 1205 process_sort_index_(0), |
| 1205 process_id_hash_(0), | 1206 process_id_hash_(0), |
| 1206 process_id_(0), | 1207 process_id_(0), |
| 1207 watch_category_(0), | 1208 watch_category_(0), |
| 1208 trace_options_(kInternalRecordUntilFull), | 1209 trace_options_(kInternalRecordUntilFull), |
| 1209 sampling_thread_handle_(0), | 1210 sampling_thread_handle_(0), |
| 1210 category_filter_(CategoryFilter::kDefaultCategoryFilterString), | 1211 category_filter_(CategoryFilter::kDefaultCategoryFilterString), |
| 1211 event_callback_category_filter_( | 1212 event_callback_category_filter_( |
| 1212 CategoryFilter::kDefaultCategoryFilterString), | 1213 CategoryFilter::kDefaultCategoryFilterString), |
| 1213 thread_shared_chunk_index_(0), | 1214 thread_shared_chunk_index_(0), |
| 1214 generation_(0) { | 1215 generation_(0), |
| 1216 use_worker_thread_(false) { |
| 1215 // Trace is enabled or disabled on one thread while other threads are | 1217 // Trace is enabled or disabled on one thread while other threads are |
| 1216 // accessing the enabled flag. We don't care whether edge-case events are | 1218 // accessing the enabled flag. We don't care whether edge-case events are |
| 1217 // traced or not, so we allow races on the enabled flag to keep the trace | 1219 // traced or not, so we allow races on the enabled flag to keep the trace |
| 1218 // macros fast. | 1220 // macros fast. |
| 1219 // TODO(jbates): ANNOTATE_BENIGN_RACE_SIZED crashes windows TSAN bots: | 1221 // TODO(jbates): ANNOTATE_BENIGN_RACE_SIZED crashes windows TSAN bots: |
| 1220 // ANNOTATE_BENIGN_RACE_SIZED(g_category_group_enabled, | 1222 // ANNOTATE_BENIGN_RACE_SIZED(g_category_group_enabled, |
| 1221 // sizeof(g_category_group_enabled), | 1223 // sizeof(g_category_group_enabled), |
| 1222 // "trace_event category enabled"); | 1224 // "trace_event category enabled"); |
| 1223 for (int i = 0; i < MAX_CATEGORY_GROUPS; ++i) { | 1225 for (int i = 0; i < MAX_CATEGORY_GROUPS; ++i) { |
| 1224 ANNOTATE_BENIGN_RACE(&g_category_group_enabled[i], | 1226 ANNOTATE_BENIGN_RACE(&g_category_group_enabled[i], |
| (...skipping 452 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 1677 // Flush() works as the following: | 1679 // Flush() works as the following: |
| 1678 // 1. Flush() is called in threadA whose message loop is saved in | 1680 // 1. Flush() is called in threadA whose message loop is saved in |
| 1679 // flush_message_loop_proxy_; | 1681 // flush_message_loop_proxy_; |
| 1680 // 2. If thread_message_loops_ is not empty, threadA posts task to each message | 1682 // 2. If thread_message_loops_ is not empty, threadA posts task to each message |
| 1681 // loop to flush the thread local buffers; otherwise finish the flush; | 1683 // loop to flush the thread local buffers; otherwise finish the flush; |
| 1682 // 3. FlushCurrentThread() deletes the thread local event buffer: | 1684 // 3. FlushCurrentThread() deletes the thread local event buffer: |
| 1683 // - The last batch of events of the thread are flushed into the main buffer; | 1685 // - The last batch of events of the thread are flushed into the main buffer; |
| 1684 // - The message loop will be removed from thread_message_loops_; | 1686 // - The message loop will be removed from thread_message_loops_; |
| 1685 // If this is the last message loop, finish the flush; | 1687 // If this is the last message loop, finish the flush; |
| 1686 // 4. If any thread hasn't finish its flush in time, finish the flush. | 1688 // 4. If any thread hasn't finish its flush in time, finish the flush. |
| 1687 void TraceLog::Flush(const TraceLog::OutputCallback& cb) { | 1689 void TraceLog::Flush(const TraceLog::OutputCallback& cb, |
| 1690 bool use_worker_thread) { |
| 1691 use_worker_thread_ = use_worker_thread; |
| 1688 if (IsEnabled()) { | 1692 if (IsEnabled()) { |
| 1689 // Can't flush when tracing is enabled because otherwise PostTask would | 1693 // Can't flush when tracing is enabled because otherwise PostTask would |
| 1690 // - generate more trace events; | 1694 // - generate more trace events; |
| 1691 // - deschedule the calling thread on some platforms causing inaccurate | 1695 // - deschedule the calling thread on some platforms causing inaccurate |
| 1692 // timing of the trace events. | 1696 // timing of the trace events. |
| 1693 scoped_refptr<RefCountedString> empty_result = new RefCountedString; | 1697 scoped_refptr<RefCountedString> empty_result = new RefCountedString; |
| 1694 if (!cb.is_null()) | 1698 if (!cb.is_null()) |
| 1695 cb.Run(empty_result, false); | 1699 cb.Run(empty_result, false); |
| 1696 LOG(WARNING) << "Ignored TraceLog::Flush called when tracing is enabled"; | 1700 LOG(WARNING) << "Ignored TraceLog::Flush called when tracing is enabled"; |
| 1697 return; | 1701 return; |
| (...skipping 33 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 1731 flush_message_loop_proxy_->PostDelayedTask( | 1735 flush_message_loop_proxy_->PostDelayedTask( |
| 1732 FROM_HERE, | 1736 FROM_HERE, |
| 1733 Bind(&TraceLog::OnFlushTimeout, Unretained(this), generation), | 1737 Bind(&TraceLog::OnFlushTimeout, Unretained(this), generation), |
| 1734 TimeDelta::FromMilliseconds(kThreadFlushTimeoutMs)); | 1738 TimeDelta::FromMilliseconds(kThreadFlushTimeoutMs)); |
| 1735 return; | 1739 return; |
| 1736 } | 1740 } |
| 1737 | 1741 |
| 1738 FinishFlush(generation); | 1742 FinishFlush(generation); |
| 1739 } | 1743 } |
| 1740 | 1744 |
| 1745 // Usually it runs on a different thread. |
| 1741 void TraceLog::ConvertTraceEventsToTraceFormat( | 1746 void TraceLog::ConvertTraceEventsToTraceFormat( |
| 1742 scoped_ptr<TraceBuffer> logged_events, | 1747 scoped_ptr<TraceBuffer> logged_events, |
| 1743 const TraceLog::OutputCallback& flush_output_callback) { | 1748 const TraceLog::OutputCallback& flush_output_callback) { |
| 1744 | 1749 |
| 1745 if (flush_output_callback.is_null()) | 1750 if (flush_output_callback.is_null()) |
| 1746 return; | 1751 return; |
| 1747 | 1752 |
| 1748 // The callback need to be called at least once even if there is no events | 1753 // The callback need to be called at least once even if there is no events |
| 1749 // to let the caller know the completion of flush. | 1754 // to let the caller know the completion of flush. |
| 1750 bool has_more_events = true; | 1755 bool has_more_events = true; |
| 1751 do { | 1756 do { |
| 1752 scoped_refptr<RefCountedString> json_events_str_ptr = | 1757 scoped_refptr<RefCountedString> json_events_str_ptr = |
| 1753 new RefCountedString(); | 1758 new RefCountedString(); |
| 1754 | 1759 |
| 1755 for (size_t i = 0; i < kTraceEventBatchChunks; ++i) { | 1760 while (json_events_str_ptr->size() < kTraceEventBufferSizeInBytes) { |
| 1756 const TraceBufferChunk* chunk = logged_events->NextChunk(); | 1761 const TraceBufferChunk* chunk = logged_events->NextChunk(); |
| 1757 if (!chunk) { | 1762 has_more_events = chunk != NULL; |
| 1758 has_more_events = false; | 1763 if (!chunk) |
| 1759 break; | 1764 break; |
| 1760 } | |
| 1761 for (size_t j = 0; j < chunk->size(); ++j) { | 1765 for (size_t j = 0; j < chunk->size(); ++j) { |
| 1762 if (i > 0 || j > 0) | 1766 if (json_events_str_ptr->size()) |
| 1763 json_events_str_ptr->data().append(","); | 1767 json_events_str_ptr->data().append(","); |
| 1764 chunk->GetEventAt(j)->AppendAsJSON(&(json_events_str_ptr->data())); | 1768 chunk->GetEventAt(j)->AppendAsJSON(&(json_events_str_ptr->data())); |
| 1765 } | 1769 } |
| 1766 } | 1770 } |
| 1767 | |
| 1768 flush_output_callback.Run(json_events_str_ptr, has_more_events); | 1771 flush_output_callback.Run(json_events_str_ptr, has_more_events); |
| 1769 } while (has_more_events); | 1772 } while (has_more_events); |
| 1770 } | 1773 } |
| 1771 | 1774 |
| 1772 void TraceLog::FinishFlush(int generation) { | 1775 void TraceLog::FinishFlush(int generation) { |
| 1773 scoped_ptr<TraceBuffer> previous_logged_events; | 1776 scoped_ptr<TraceBuffer> previous_logged_events; |
| 1774 OutputCallback flush_output_callback; | 1777 OutputCallback flush_output_callback; |
| 1775 | 1778 |
| 1776 if (!CheckGeneration(generation)) | 1779 if (!CheckGeneration(generation)) |
| 1777 return; | 1780 return; |
| 1778 | 1781 |
| 1779 { | 1782 { |
| 1780 AutoLock lock(lock_); | 1783 AutoLock lock(lock_); |
| 1781 | 1784 |
| 1782 previous_logged_events.swap(logged_events_); | 1785 previous_logged_events.swap(logged_events_); |
| 1783 UseNextTraceBuffer(); | 1786 UseNextTraceBuffer(); |
| 1784 thread_message_loops_.clear(); | 1787 thread_message_loops_.clear(); |
| 1785 | 1788 |
| 1786 flush_message_loop_proxy_ = NULL; | 1789 flush_message_loop_proxy_ = NULL; |
| 1787 flush_output_callback = flush_output_callback_; | 1790 flush_output_callback = flush_output_callback_; |
| 1788 flush_output_callback_.Reset(); | 1791 flush_output_callback_.Reset(); |
| 1789 } | 1792 } |
| 1790 | 1793 |
| 1794 if (use_worker_thread_ && |
| 1795 WorkerPool::PostTask( |
| 1796 FROM_HERE, |
| 1797 Bind(&TraceLog::ConvertTraceEventsToTraceFormat, |
| 1798 Passed(&previous_logged_events), |
| 1799 flush_output_callback), |
| 1800 true)) { |
| 1801 return; |
| 1802 } |
| 1803 |
| 1791 ConvertTraceEventsToTraceFormat(previous_logged_events.Pass(), | 1804 ConvertTraceEventsToTraceFormat(previous_logged_events.Pass(), |
| 1792 flush_output_callback); | 1805 flush_output_callback); |
| 1793 } | 1806 } |
| 1794 | 1807 |
| 1795 // Run in each thread holding a local event buffer. | 1808 // Run in each thread holding a local event buffer. |
| 1796 void TraceLog::FlushCurrentThread(int generation) { | 1809 void TraceLog::FlushCurrentThread(int generation) { |
| 1797 { | 1810 { |
| 1798 AutoLock lock(lock_); | 1811 AutoLock lock(lock_); |
| 1799 if (!CheckGeneration(generation) || !flush_message_loop_proxy_.get()) { | 1812 if (!CheckGeneration(generation) || !flush_message_loop_proxy_.get()) { |
| 1800 // This is late. The corresponding flush has finished. | 1813 // This is late. The corresponding flush has finished. |
| (...skipping 784 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 2585 } | 2598 } |
| 2586 | 2599 |
| 2587 ScopedTraceBinaryEfficient::~ScopedTraceBinaryEfficient() { | 2600 ScopedTraceBinaryEfficient::~ScopedTraceBinaryEfficient() { |
| 2588 if (*category_group_enabled_) { | 2601 if (*category_group_enabled_) { |
| 2589 TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION(category_group_enabled_, | 2602 TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION(category_group_enabled_, |
| 2590 name_, event_handle_); | 2603 name_, event_handle_); |
| 2591 } | 2604 } |
| 2592 } | 2605 } |
| 2593 | 2606 |
| 2594 } // namespace trace_event_internal | 2607 } // namespace trace_event_internal |
| OLD | NEW |