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/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...) Loading... |
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...) Loading... |
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...) Loading... |
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...) Loading... |
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...) Loading... |
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 |
OLD | NEW |