Chromium Code Reviews

Side by Side Diff: base/trace_event/trace_event_impl.cc

Issue 1128733002: Update from https://crrev.com/328418 (Closed) Base URL: git@github.com:domokit/mojo.git@master
Patch Set: Created 5 years, 7 months ago
Use n/p to move between diff chunks; N/P to move between comments.
Jump to:
View unified diff |
« no previous file with comments | « base/trace_event/trace_event_impl.h ('k') | base/trace_event/trace_event_memory.h » ('j') | no next file with comments »
Toggle Intra-line Diffs ('i') | Expand Comments ('e') | Collapse Comments ('c') | Show Comments Hide Comments ('s')
OLDNEW
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/trace_event/trace_event_impl.h" 5 #include "base/trace_event/trace_event_impl.h"
6 6
7 #include <algorithm> 7 #include <algorithm>
8 #include <cmath> 8 #include <cmath>
9 9
10 #include "base/base_switches.h" 10 #include "base/base_switches.h"
11 #include "base/bind.h" 11 #include "base/bind.h"
12 #include "base/command_line.h" 12 #include "base/command_line.h"
13 #include "base/debug/leak_annotations.h" 13 #include "base/debug/leak_annotations.h"
14 #include "base/format_macros.h" 14 #include "base/format_macros.h"
15 #include "base/json/string_escape.h" 15 #include "base/json/string_escape.h"
16 #include "base/lazy_instance.h" 16 #include "base/lazy_instance.h"
17 #include "base/location.h"
17 #include "base/memory/singleton.h" 18 #include "base/memory/singleton.h"
18 #include "base/message_loop/message_loop.h"
19 #include "base/process/process_metrics.h" 19 #include "base/process/process_metrics.h"
20 #include "base/stl_util.h" 20 #include "base/stl_util.h"
21 #include "base/strings/string_number_conversions.h" 21 #include "base/strings/string_number_conversions.h"
22 #include "base/strings/string_split.h" 22 #include "base/strings/string_split.h"
23 #include "base/strings/string_tokenizer.h" 23 #include "base/strings/string_tokenizer.h"
24 #include "base/strings/string_util.h" 24 #include "base/strings/string_util.h"
25 #include "base/strings/stringprintf.h" 25 #include "base/strings/stringprintf.h"
26 #include "base/strings/utf_string_conversions.h" 26 #include "base/strings/utf_string_conversions.h"
27 #include "base/synchronization/cancellation_flag.h" 27 #include "base/synchronization/cancellation_flag.h"
28 #include "base/synchronization/waitable_event.h" 28 #include "base/synchronization/waitable_event.h"
29 #include "base/sys_info.h" 29 #include "base/sys_info.h"
30 #include "base/third_party/dynamic_annotations/dynamic_annotations.h" 30 #include "base/third_party/dynamic_annotations/dynamic_annotations.h"
31 #include "base/thread_task_runner_handle.h"
31 #include "base/threading/platform_thread.h" 32 #include "base/threading/platform_thread.h"
32 #include "base/threading/thread_id_name_manager.h" 33 #include "base/threading/thread_id_name_manager.h"
33 #include "base/threading/worker_pool.h" 34 #include "base/threading/worker_pool.h"
34 #include "base/time/time.h" 35 #include "base/time/time.h"
35 #include "base/trace_event/trace_event.h" 36 #include "base/trace_event/trace_event.h"
36 #include "base/trace_event/trace_event_synthetic_delay.h" 37 #include "base/trace_event/trace_event_synthetic_delay.h"
37 38
38 #if defined(OS_WIN) 39 #if defined(OS_WIN)
39 #include "base/trace_event/trace_event_etw_export_win.h" 40 #include "base/trace_event/trace_event_etw_export_win.h"
40 #include "base/trace_event/trace_event_win.h" 41 #include "base/trace_event/trace_event_win.h"
(...skipping 693 matching lines...)
734 StringAppendF(out, ",\"tdur\":%" PRId64, thread_duration); 735 StringAppendF(out, ",\"tdur\":%" PRId64, thread_duration);
735 } 736 }
736 } 737 }
737 738
738 // Output tts if thread_timestamp is valid. 739 // Output tts if thread_timestamp is valid.
739 if (!thread_timestamp_.is_null()) { 740 if (!thread_timestamp_.is_null()) {
740 int64 thread_time_int64 = thread_timestamp_.ToInternalValue(); 741 int64 thread_time_int64 = thread_timestamp_.ToInternalValue();
741 StringAppendF(out, ",\"tts\":%" PRId64, thread_time_int64); 742 StringAppendF(out, ",\"tts\":%" PRId64, thread_time_int64);
742 } 743 }
743 744
745 // Output async tts marker field if flag is set.
746 if (flags_ & TRACE_EVENT_FLAG_ASYNC_TTS) {
747 StringAppendF(out, ", \"use_async_tts\":1");
748 }
749
744 // If id_ is set, print it out as a hex string so we don't loose any 750 // If id_ is set, print it out as a hex string so we don't loose any
745 // bits (it might be a 64-bit pointer). 751 // bits (it might be a 64-bit pointer).
746 if (flags_ & TRACE_EVENT_FLAG_HAS_ID) 752 if (flags_ & TRACE_EVENT_FLAG_HAS_ID)
747 StringAppendF(out, ",\"id\":\"0x%" PRIx64 "\"", static_cast<uint64>(id_)); 753 StringAppendF(out, ",\"id\":\"0x%" PRIx64 "\"", static_cast<uint64>(id_));
748 754
749 // Instant events also output their scope. 755 // Instant events also output their scope.
750 if (phase_ == TRACE_EVENT_PHASE_INSTANT) { 756 if (phase_ == TRACE_EVENT_PHASE_INSTANT) {
751 char scope = '?'; 757 char scope = '?';
752 switch (flags_ & TRACE_EVENT_FLAG_SCOPE_MASK) { 758 switch (flags_ & TRACE_EVENT_FLAG_SCOPE_MASK) {
753 case TRACE_EVENT_SCOPE_GLOBAL: 759 case TRACE_EVENT_SCOPE_GLOBAL:
(...skipping 645 matching lines...)
1399 } 1405 }
1400 1406
1401 void TraceLog::SetEnabled(const CategoryFilter& category_filter, 1407 void TraceLog::SetEnabled(const CategoryFilter& category_filter,
1402 Mode mode, 1408 Mode mode,
1403 const TraceOptions& options) { 1409 const TraceOptions& options) {
1404 std::vector<EnabledStateObserver*> observer_list; 1410 std::vector<EnabledStateObserver*> observer_list;
1405 { 1411 {
1406 AutoLock lock(lock_); 1412 AutoLock lock(lock_);
1407 1413
1408 // Can't enable tracing when Flush() is in progress. 1414 // Can't enable tracing when Flush() is in progress.
1409 DCHECK(!flush_message_loop_proxy_.get()); 1415 DCHECK(!flush_task_runner_);
1410 1416
1411 InternalTraceOptions new_options = 1417 InternalTraceOptions new_options =
1412 GetInternalOptionsFromTraceOptions(options); 1418 GetInternalOptionsFromTraceOptions(options);
1413 1419
1414 InternalTraceOptions old_options = trace_options(); 1420 InternalTraceOptions old_options = trace_options();
1415 1421
1416 if (IsEnabled()) { 1422 if (IsEnabled()) {
1417 if (new_options != old_options) { 1423 if (new_options != old_options) {
1418 DLOG(ERROR) << "Attempting to re-enable tracing with a different " 1424 DLOG(ERROR) << "Attempting to re-enable tracing with a different "
1419 << "set of options."; 1425 << "set of options.";
(...skipping 253 matching lines...)
1673 UpdateCategoryGroupEnabledFlags(); 1679 UpdateCategoryGroupEnabledFlags();
1674 }; 1680 };
1675 1681
1676 void TraceLog::SetEventCallbackDisabled() { 1682 void TraceLog::SetEventCallbackDisabled() {
1677 AutoLock lock(lock_); 1683 AutoLock lock(lock_);
1678 subtle::NoBarrier_Store(&event_callback_, 0); 1684 subtle::NoBarrier_Store(&event_callback_, 0);
1679 UpdateCategoryGroupEnabledFlags(); 1685 UpdateCategoryGroupEnabledFlags();
1680 } 1686 }
1681 1687
1682 // Flush() works as the following: 1688 // Flush() works as the following:
1683 // 1. Flush() is called in threadA whose message loop is saved in 1689 // 1. Flush() is called in thread A whose task runner is saved in
1684 // flush_message_loop_proxy_; 1690 // flush_task_runner_;
1685 // 2. If thread_message_loops_ is not empty, threadA posts task to each message 1691 // 2. If thread_message_loops_ is not empty, thread A posts task to each message
1686 // loop to flush the thread local buffers; otherwise finish the flush; 1692 // loop to flush the thread local buffers; otherwise finish the flush;
1687 // 3. FlushCurrentThread() deletes the thread local event buffer: 1693 // 3. FlushCurrentThread() deletes the thread local event buffer:
1688 // - The last batch of events of the thread are flushed into the main buffer; 1694 // - The last batch of events of the thread are flushed into the main buffer;
1689 // - The message loop will be removed from thread_message_loops_; 1695 // - The message loop will be removed from thread_message_loops_;
1690 // If this is the last message loop, finish the flush; 1696 // If this is the last message loop, finish the flush;
1691 // 4. If any thread hasn't finish its flush in time, finish the flush. 1697 // 4. If any thread hasn't finish its flush in time, finish the flush.
1692 void TraceLog::Flush(const TraceLog::OutputCallback& cb, 1698 void TraceLog::Flush(const TraceLog::OutputCallback& cb,
1693 bool use_worker_thread) { 1699 bool use_worker_thread) {
1694 use_worker_thread_ = use_worker_thread; 1700 use_worker_thread_ = use_worker_thread;
1695 if (IsEnabled()) { 1701 if (IsEnabled()) {
1696 // Can't flush when tracing is enabled because otherwise PostTask would 1702 // Can't flush when tracing is enabled because otherwise PostTask would
1697 // - generate more trace events; 1703 // - generate more trace events;
1698 // - deschedule the calling thread on some platforms causing inaccurate 1704 // - deschedule the calling thread on some platforms causing inaccurate
1699 // timing of the trace events. 1705 // timing of the trace events.
1700 scoped_refptr<RefCountedString> empty_result = new RefCountedString; 1706 scoped_refptr<RefCountedString> empty_result = new RefCountedString;
1701 if (!cb.is_null()) 1707 if (!cb.is_null())
1702 cb.Run(empty_result, false); 1708 cb.Run(empty_result, false);
1703 LOG(WARNING) << "Ignored TraceLog::Flush called when tracing is enabled"; 1709 LOG(WARNING) << "Ignored TraceLog::Flush called when tracing is enabled";
1704 return; 1710 return;
1705 } 1711 }
1706 1712
1707 int generation = this->generation(); 1713 int generation = this->generation();
1708 // Copy of thread_message_loops_ to be used without locking. 1714 // Copy of thread_message_loops_ to be used without locking.
1709 std::vector<scoped_refptr<SingleThreadTaskRunner> > 1715 std::vector<scoped_refptr<SingleThreadTaskRunner> >
1710 thread_message_loop_task_runners; 1716 thread_message_loop_task_runners;
1711 { 1717 {
1712 AutoLock lock(lock_); 1718 AutoLock lock(lock_);
1713 DCHECK(!flush_message_loop_proxy_.get()); 1719 DCHECK(!flush_task_runner_);
1714 flush_message_loop_proxy_ = MessageLoopProxy::current(); 1720 flush_task_runner_ = ThreadTaskRunnerHandle::IsSet()
1715 DCHECK(!thread_message_loops_.size() || flush_message_loop_proxy_.get()); 1721 ? ThreadTaskRunnerHandle::Get()
1722 : nullptr;
1723 DCHECK_IMPLIES(thread_message_loops_.size(), flush_task_runner_);
1716 flush_output_callback_ = cb; 1724 flush_output_callback_ = cb;
1717 1725
1718 if (thread_shared_chunk_) { 1726 if (thread_shared_chunk_) {
1719 logged_events_->ReturnChunk(thread_shared_chunk_index_, 1727 logged_events_->ReturnChunk(thread_shared_chunk_index_,
1720 thread_shared_chunk_.Pass()); 1728 thread_shared_chunk_.Pass());
1721 } 1729 }
1722 1730
1723 if (thread_message_loops_.size()) { 1731 if (thread_message_loops_.size()) {
1724 for (hash_set<MessageLoop*>::const_iterator it = 1732 for (hash_set<MessageLoop*>::const_iterator it =
1725 thread_message_loops_.begin(); 1733 thread_message_loops_.begin();
1726 it != thread_message_loops_.end(); ++it) { 1734 it != thread_message_loops_.end(); ++it) {
1727 thread_message_loop_task_runners.push_back((*it)->task_runner()); 1735 thread_message_loop_task_runners.push_back((*it)->task_runner());
1728 } 1736 }
1729 } 1737 }
1730 } 1738 }
1731 1739
1732 if (thread_message_loop_task_runners.size()) { 1740 if (thread_message_loop_task_runners.size()) {
1733 for (size_t i = 0; i < thread_message_loop_task_runners.size(); ++i) { 1741 for (size_t i = 0; i < thread_message_loop_task_runners.size(); ++i) {
1734 thread_message_loop_task_runners[i]->PostTask( 1742 thread_message_loop_task_runners[i]->PostTask(
1735 FROM_HERE, 1743 FROM_HERE,
1736 Bind(&TraceLog::FlushCurrentThread, Unretained(this), generation)); 1744 Bind(&TraceLog::FlushCurrentThread, Unretained(this), generation));
1737 } 1745 }
1738 flush_message_loop_proxy_->PostDelayedTask( 1746 flush_task_runner_->PostDelayedTask(
1739 FROM_HERE, 1747 FROM_HERE,
1740 Bind(&TraceLog::OnFlushTimeout, Unretained(this), generation), 1748 Bind(&TraceLog::OnFlushTimeout, Unretained(this), generation),
1741 TimeDelta::FromMilliseconds(kThreadFlushTimeoutMs)); 1749 TimeDelta::FromMilliseconds(kThreadFlushTimeoutMs));
1742 return; 1750 return;
1743 } 1751 }
1744 1752
1745 FinishFlush(generation); 1753 FinishFlush(generation);
1746 } 1754 }
1747 1755
1748 // Usually it runs on a different thread. 1756 // Usually it runs on a different thread.
(...skipping 33 matching lines...)
1782 if (!CheckGeneration(generation)) 1790 if (!CheckGeneration(generation))
1783 return; 1791 return;
1784 1792
1785 { 1793 {
1786 AutoLock lock(lock_); 1794 AutoLock lock(lock_);
1787 1795
1788 previous_logged_events.swap(logged_events_); 1796 previous_logged_events.swap(logged_events_);
1789 UseNextTraceBuffer(); 1797 UseNextTraceBuffer();
1790 thread_message_loops_.clear(); 1798 thread_message_loops_.clear();
1791 1799
1792 flush_message_loop_proxy_ = NULL; 1800 flush_task_runner_ = NULL;
1793 flush_output_callback = flush_output_callback_; 1801 flush_output_callback = flush_output_callback_;
1794 flush_output_callback_.Reset(); 1802 flush_output_callback_.Reset();
1795 } 1803 }
1796 1804
1797 if (use_worker_thread_ && 1805 if (use_worker_thread_ &&
1798 WorkerPool::PostTask( 1806 WorkerPool::PostTask(
1799 FROM_HERE, 1807 FROM_HERE,
1800 Bind(&TraceLog::ConvertTraceEventsToTraceFormat, 1808 Bind(&TraceLog::ConvertTraceEventsToTraceFormat,
1801 Passed(&previous_logged_events), 1809 Passed(&previous_logged_events),
1802 flush_output_callback), 1810 flush_output_callback),
1803 true)) { 1811 true)) {
1804 return; 1812 return;
1805 } 1813 }
1806 1814
1807 ConvertTraceEventsToTraceFormat(previous_logged_events.Pass(), 1815 ConvertTraceEventsToTraceFormat(previous_logged_events.Pass(),
1808 flush_output_callback); 1816 flush_output_callback);
1809 } 1817 }
1810 1818
1811 // Run in each thread holding a local event buffer. 1819 // Run in each thread holding a local event buffer.
1812 void TraceLog::FlushCurrentThread(int generation) { 1820 void TraceLog::FlushCurrentThread(int generation) {
1813 { 1821 {
1814 AutoLock lock(lock_); 1822 AutoLock lock(lock_);
1815 if (!CheckGeneration(generation) || !flush_message_loop_proxy_.get()) { 1823 if (!CheckGeneration(generation) || !flush_task_runner_) {
1816 // This is late. The corresponding flush has finished. 1824 // This is late. The corresponding flush has finished.
1817 return; 1825 return;
1818 } 1826 }
1819 } 1827 }
1820 1828
1821 // This will flush the thread local buffer. 1829 // This will flush the thread local buffer.
1822 delete thread_local_event_buffer_.Get(); 1830 delete thread_local_event_buffer_.Get();
1823 1831
1824 AutoLock lock(lock_); 1832 AutoLock lock(lock_);
1825 if (!CheckGeneration(generation) || !flush_message_loop_proxy_.get() || 1833 if (!CheckGeneration(generation) || !flush_task_runner_ ||
1826 thread_message_loops_.size()) 1834 thread_message_loops_.size())
1827 return; 1835 return;
1828 1836
1829 flush_message_loop_proxy_->PostTask( 1837 flush_task_runner_->PostTask(
1830 FROM_HERE, 1838 FROM_HERE, Bind(&TraceLog::FinishFlush, Unretained(this), generation));
1831 Bind(&TraceLog::FinishFlush, Unretained(this), generation));
1832 } 1839 }
1833 1840
1834 void TraceLog::OnFlushTimeout(int generation) { 1841 void TraceLog::OnFlushTimeout(int generation) {
1835 { 1842 {
1836 AutoLock lock(lock_); 1843 AutoLock lock(lock_);
1837 if (!CheckGeneration(generation) || !flush_message_loop_proxy_.get()) { 1844 if (!CheckGeneration(generation) || !flush_task_runner_) {
1838 // Flush has finished before timeout. 1845 // Flush has finished before timeout.
1839 return; 1846 return;
1840 } 1847 }
1841 1848
1842 LOG(WARNING) << 1849 LOG(WARNING) <<
1843 "The following threads haven't finished flush in time. " 1850 "The following threads haven't finished flush in time. "
1844 "If this happens stably for some thread, please call " 1851 "If this happens stably for some thread, please call "
1845 "TraceLog::GetInstance()->SetCurrentThreadBlocksMessageLoop() from " 1852 "TraceLog::GetInstance()->SetCurrentThreadBlocksMessageLoop() from "
1846 "the thread to avoid its trace events from being lost."; 1853 "the thread to avoid its trace events from being lost.";
1847 for (hash_set<MessageLoop*>::const_iterator it = 1854 for (hash_set<MessageLoop*>::const_iterator it =
(...skipping 786 matching lines...)
2634 } 2641 }
2635 2642
2636 ScopedTraceBinaryEfficient::~ScopedTraceBinaryEfficient() { 2643 ScopedTraceBinaryEfficient::~ScopedTraceBinaryEfficient() {
2637 if (*category_group_enabled_) { 2644 if (*category_group_enabled_) {
2638 TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION(category_group_enabled_, 2645 TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION(category_group_enabled_,
2639 name_, event_handle_); 2646 name_, event_handle_);
2640 } 2647 }
2641 } 2648 }
2642 2649
2643 } // namespace trace_event_internal 2650 } // namespace trace_event_internal
OLDNEW
« no previous file with comments | « base/trace_event/trace_event_impl.h ('k') | base/trace_event/trace_event_memory.h » ('j') | no next file with comments »

Powered by Google App Engine