| 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 1358 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 1399 } | 1400 } |
| 1400 | 1401 |
| 1401 void TraceLog::SetEnabled(const CategoryFilter& category_filter, | 1402 void TraceLog::SetEnabled(const CategoryFilter& category_filter, |
| 1402 Mode mode, | 1403 Mode mode, |
| 1403 const TraceOptions& options) { | 1404 const TraceOptions& options) { |
| 1404 std::vector<EnabledStateObserver*> observer_list; | 1405 std::vector<EnabledStateObserver*> observer_list; |
| 1405 { | 1406 { |
| 1406 AutoLock lock(lock_); | 1407 AutoLock lock(lock_); |
| 1407 | 1408 |
| 1408 // Can't enable tracing when Flush() is in progress. | 1409 // Can't enable tracing when Flush() is in progress. |
| 1409 DCHECK(!flush_message_loop_proxy_.get()); | 1410 DCHECK(!flush_task_runner_); |
| 1410 | 1411 |
| 1411 InternalTraceOptions new_options = | 1412 InternalTraceOptions new_options = |
| 1412 GetInternalOptionsFromTraceOptions(options); | 1413 GetInternalOptionsFromTraceOptions(options); |
| 1413 | 1414 |
| 1414 InternalTraceOptions old_options = trace_options(); | 1415 InternalTraceOptions old_options = trace_options(); |
| 1415 | 1416 |
| 1416 if (IsEnabled()) { | 1417 if (IsEnabled()) { |
| 1417 if (new_options != old_options) { | 1418 if (new_options != old_options) { |
| 1418 DLOG(ERROR) << "Attempting to re-enable tracing with a different " | 1419 DLOG(ERROR) << "Attempting to re-enable tracing with a different " |
| 1419 << "set of options."; | 1420 << "set of options."; |
| (...skipping 253 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 1673 UpdateCategoryGroupEnabledFlags(); | 1674 UpdateCategoryGroupEnabledFlags(); |
| 1674 }; | 1675 }; |
| 1675 | 1676 |
| 1676 void TraceLog::SetEventCallbackDisabled() { | 1677 void TraceLog::SetEventCallbackDisabled() { |
| 1677 AutoLock lock(lock_); | 1678 AutoLock lock(lock_); |
| 1678 subtle::NoBarrier_Store(&event_callback_, 0); | 1679 subtle::NoBarrier_Store(&event_callback_, 0); |
| 1679 UpdateCategoryGroupEnabledFlags(); | 1680 UpdateCategoryGroupEnabledFlags(); |
| 1680 } | 1681 } |
| 1681 | 1682 |
| 1682 // Flush() works as the following: | 1683 // Flush() works as the following: |
| 1683 // 1. Flush() is called in threadA whose message loop is saved in | 1684 // 1. Flush() is called in thread A whose task runner is saved in |
| 1684 // flush_message_loop_proxy_; | 1685 // flush_task_runner_; |
| 1685 // 2. If thread_message_loops_ is not empty, threadA posts task to each message | 1686 // 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; | 1687 // loop to flush the thread local buffers; otherwise finish the flush; |
| 1687 // 3. FlushCurrentThread() deletes the thread local event buffer: | 1688 // 3. FlushCurrentThread() deletes the thread local event buffer: |
| 1688 // - The last batch of events of the thread are flushed into the main buffer; | 1689 // - 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_; | 1690 // - The message loop will be removed from thread_message_loops_; |
| 1690 // If this is the last message loop, finish the flush; | 1691 // 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. | 1692 // 4. If any thread hasn't finish its flush in time, finish the flush. |
| 1692 void TraceLog::Flush(const TraceLog::OutputCallback& cb, | 1693 void TraceLog::Flush(const TraceLog::OutputCallback& cb, |
| 1693 bool use_worker_thread) { | 1694 bool use_worker_thread) { |
| 1694 use_worker_thread_ = use_worker_thread; | 1695 use_worker_thread_ = use_worker_thread; |
| 1695 if (IsEnabled()) { | 1696 if (IsEnabled()) { |
| 1696 // Can't flush when tracing is enabled because otherwise PostTask would | 1697 // Can't flush when tracing is enabled because otherwise PostTask would |
| 1697 // - generate more trace events; | 1698 // - generate more trace events; |
| 1698 // - deschedule the calling thread on some platforms causing inaccurate | 1699 // - deschedule the calling thread on some platforms causing inaccurate |
| 1699 // timing of the trace events. | 1700 // timing of the trace events. |
| 1700 scoped_refptr<RefCountedString> empty_result = new RefCountedString; | 1701 scoped_refptr<RefCountedString> empty_result = new RefCountedString; |
| 1701 if (!cb.is_null()) | 1702 if (!cb.is_null()) |
| 1702 cb.Run(empty_result, false); | 1703 cb.Run(empty_result, false); |
| 1703 LOG(WARNING) << "Ignored TraceLog::Flush called when tracing is enabled"; | 1704 LOG(WARNING) << "Ignored TraceLog::Flush called when tracing is enabled"; |
| 1704 return; | 1705 return; |
| 1705 } | 1706 } |
| 1706 | 1707 |
| 1707 int generation = this->generation(); | 1708 int generation = this->generation(); |
| 1708 // Copy of thread_message_loops_ to be used without locking. | 1709 // Copy of thread_message_loops_ to be used without locking. |
| 1709 std::vector<scoped_refptr<SingleThreadTaskRunner> > | 1710 std::vector<scoped_refptr<SingleThreadTaskRunner> > |
| 1710 thread_message_loop_task_runners; | 1711 thread_message_loop_task_runners; |
| 1711 { | 1712 { |
| 1712 AutoLock lock(lock_); | 1713 AutoLock lock(lock_); |
| 1713 DCHECK(!flush_message_loop_proxy_.get()); | 1714 DCHECK(!flush_task_runner_); |
| 1714 flush_message_loop_proxy_ = MessageLoopProxy::current(); | 1715 flush_task_runner_ = ThreadTaskRunnerHandle::IsSet() |
| 1715 DCHECK(!thread_message_loops_.size() || flush_message_loop_proxy_.get()); | 1716 ? ThreadTaskRunnerHandle::Get() |
| 1717 : nullptr; |
| 1718 DCHECK_IMPLIES(thread_message_loops_.size(), flush_task_runner_); |
| 1716 flush_output_callback_ = cb; | 1719 flush_output_callback_ = cb; |
| 1717 | 1720 |
| 1718 if (thread_shared_chunk_) { | 1721 if (thread_shared_chunk_) { |
| 1719 logged_events_->ReturnChunk(thread_shared_chunk_index_, | 1722 logged_events_->ReturnChunk(thread_shared_chunk_index_, |
| 1720 thread_shared_chunk_.Pass()); | 1723 thread_shared_chunk_.Pass()); |
| 1721 } | 1724 } |
| 1722 | 1725 |
| 1723 if (thread_message_loops_.size()) { | 1726 if (thread_message_loops_.size()) { |
| 1724 for (hash_set<MessageLoop*>::const_iterator it = | 1727 for (hash_set<MessageLoop*>::const_iterator it = |
| 1725 thread_message_loops_.begin(); | 1728 thread_message_loops_.begin(); |
| 1726 it != thread_message_loops_.end(); ++it) { | 1729 it != thread_message_loops_.end(); ++it) { |
| 1727 thread_message_loop_task_runners.push_back((*it)->task_runner()); | 1730 thread_message_loop_task_runners.push_back((*it)->task_runner()); |
| 1728 } | 1731 } |
| 1729 } | 1732 } |
| 1730 } | 1733 } |
| 1731 | 1734 |
| 1732 if (thread_message_loop_task_runners.size()) { | 1735 if (thread_message_loop_task_runners.size()) { |
| 1733 for (size_t i = 0; i < thread_message_loop_task_runners.size(); ++i) { | 1736 for (size_t i = 0; i < thread_message_loop_task_runners.size(); ++i) { |
| 1734 thread_message_loop_task_runners[i]->PostTask( | 1737 thread_message_loop_task_runners[i]->PostTask( |
| 1735 FROM_HERE, | 1738 FROM_HERE, |
| 1736 Bind(&TraceLog::FlushCurrentThread, Unretained(this), generation)); | 1739 Bind(&TraceLog::FlushCurrentThread, Unretained(this), generation)); |
| 1737 } | 1740 } |
| 1738 flush_message_loop_proxy_->PostDelayedTask( | 1741 flush_task_runner_->PostDelayedTask( |
| 1739 FROM_HERE, | 1742 FROM_HERE, |
| 1740 Bind(&TraceLog::OnFlushTimeout, Unretained(this), generation), | 1743 Bind(&TraceLog::OnFlushTimeout, Unretained(this), generation), |
| 1741 TimeDelta::FromMilliseconds(kThreadFlushTimeoutMs)); | 1744 TimeDelta::FromMilliseconds(kThreadFlushTimeoutMs)); |
| 1742 return; | 1745 return; |
| 1743 } | 1746 } |
| 1744 | 1747 |
| 1745 FinishFlush(generation); | 1748 FinishFlush(generation); |
| 1746 } | 1749 } |
| 1747 | 1750 |
| 1748 // Usually it runs on a different thread. | 1751 // Usually it runs on a different thread. |
| (...skipping 33 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 1782 if (!CheckGeneration(generation)) | 1785 if (!CheckGeneration(generation)) |
| 1783 return; | 1786 return; |
| 1784 | 1787 |
| 1785 { | 1788 { |
| 1786 AutoLock lock(lock_); | 1789 AutoLock lock(lock_); |
| 1787 | 1790 |
| 1788 previous_logged_events.swap(logged_events_); | 1791 previous_logged_events.swap(logged_events_); |
| 1789 UseNextTraceBuffer(); | 1792 UseNextTraceBuffer(); |
| 1790 thread_message_loops_.clear(); | 1793 thread_message_loops_.clear(); |
| 1791 | 1794 |
| 1792 flush_message_loop_proxy_ = NULL; | 1795 flush_task_runner_ = NULL; |
| 1793 flush_output_callback = flush_output_callback_; | 1796 flush_output_callback = flush_output_callback_; |
| 1794 flush_output_callback_.Reset(); | 1797 flush_output_callback_.Reset(); |
| 1795 } | 1798 } |
| 1796 | 1799 |
| 1797 if (use_worker_thread_ && | 1800 if (use_worker_thread_ && |
| 1798 WorkerPool::PostTask( | 1801 WorkerPool::PostTask( |
| 1799 FROM_HERE, | 1802 FROM_HERE, |
| 1800 Bind(&TraceLog::ConvertTraceEventsToTraceFormat, | 1803 Bind(&TraceLog::ConvertTraceEventsToTraceFormat, |
| 1801 Passed(&previous_logged_events), | 1804 Passed(&previous_logged_events), |
| 1802 flush_output_callback), | 1805 flush_output_callback), |
| 1803 true)) { | 1806 true)) { |
| 1804 return; | 1807 return; |
| 1805 } | 1808 } |
| 1806 | 1809 |
| 1807 ConvertTraceEventsToTraceFormat(previous_logged_events.Pass(), | 1810 ConvertTraceEventsToTraceFormat(previous_logged_events.Pass(), |
| 1808 flush_output_callback); | 1811 flush_output_callback); |
| 1809 } | 1812 } |
| 1810 | 1813 |
| 1811 // Run in each thread holding a local event buffer. | 1814 // Run in each thread holding a local event buffer. |
| 1812 void TraceLog::FlushCurrentThread(int generation) { | 1815 void TraceLog::FlushCurrentThread(int generation) { |
| 1813 { | 1816 { |
| 1814 AutoLock lock(lock_); | 1817 AutoLock lock(lock_); |
| 1815 if (!CheckGeneration(generation) || !flush_message_loop_proxy_.get()) { | 1818 if (!CheckGeneration(generation) || !flush_task_runner_) { |
| 1816 // This is late. The corresponding flush has finished. | 1819 // This is late. The corresponding flush has finished. |
| 1817 return; | 1820 return; |
| 1818 } | 1821 } |
| 1819 } | 1822 } |
| 1820 | 1823 |
| 1821 // This will flush the thread local buffer. | 1824 // This will flush the thread local buffer. |
| 1822 delete thread_local_event_buffer_.Get(); | 1825 delete thread_local_event_buffer_.Get(); |
| 1823 | 1826 |
| 1824 AutoLock lock(lock_); | 1827 AutoLock lock(lock_); |
| 1825 if (!CheckGeneration(generation) || !flush_message_loop_proxy_.get() || | 1828 if (!CheckGeneration(generation) || !flush_task_runner_ || |
| 1826 thread_message_loops_.size()) | 1829 thread_message_loops_.size()) |
| 1827 return; | 1830 return; |
| 1828 | 1831 |
| 1829 flush_message_loop_proxy_->PostTask( | 1832 flush_task_runner_->PostTask( |
| 1830 FROM_HERE, | 1833 FROM_HERE, Bind(&TraceLog::FinishFlush, Unretained(this), generation)); |
| 1831 Bind(&TraceLog::FinishFlush, Unretained(this), generation)); | |
| 1832 } | 1834 } |
| 1833 | 1835 |
| 1834 void TraceLog::OnFlushTimeout(int generation) { | 1836 void TraceLog::OnFlushTimeout(int generation) { |
| 1835 { | 1837 { |
| 1836 AutoLock lock(lock_); | 1838 AutoLock lock(lock_); |
| 1837 if (!CheckGeneration(generation) || !flush_message_loop_proxy_.get()) { | 1839 if (!CheckGeneration(generation) || !flush_task_runner_) { |
| 1838 // Flush has finished before timeout. | 1840 // Flush has finished before timeout. |
| 1839 return; | 1841 return; |
| 1840 } | 1842 } |
| 1841 | 1843 |
| 1842 LOG(WARNING) << | 1844 LOG(WARNING) << |
| 1843 "The following threads haven't finished flush in time. " | 1845 "The following threads haven't finished flush in time. " |
| 1844 "If this happens stably for some thread, please call " | 1846 "If this happens stably for some thread, please call " |
| 1845 "TraceLog::GetInstance()->SetCurrentThreadBlocksMessageLoop() from " | 1847 "TraceLog::GetInstance()->SetCurrentThreadBlocksMessageLoop() from " |
| 1846 "the thread to avoid its trace events from being lost."; | 1848 "the thread to avoid its trace events from being lost."; |
| 1847 for (hash_set<MessageLoop*>::const_iterator it = | 1849 for (hash_set<MessageLoop*>::const_iterator it = |
| (...skipping 786 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 2634 } | 2636 } |
| 2635 | 2637 |
| 2636 ScopedTraceBinaryEfficient::~ScopedTraceBinaryEfficient() { | 2638 ScopedTraceBinaryEfficient::~ScopedTraceBinaryEfficient() { |
| 2637 if (*category_group_enabled_) { | 2639 if (*category_group_enabled_) { |
| 2638 TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION(category_group_enabled_, | 2640 TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION(category_group_enabled_, |
| 2639 name_, event_handle_); | 2641 name_, event_handle_); |
| 2640 } | 2642 } |
| 2641 } | 2643 } |
| 2642 | 2644 |
| 2643 } // namespace trace_event_internal | 2645 } // namespace trace_event_internal |
| OLD | NEW |