OLD | NEW |
1 // Copyright (c) 2006-2008 The Chromium Authors. All rights reserved. | 1 // Copyright (c) 2009 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 <limits> | 5 #include <limits> |
6 | 6 |
7 #include "chrome/browser/jankometer.h" | 7 #include "chrome/browser/jankometer.h" |
8 | 8 |
9 #include "base/basictypes.h" | 9 #include "base/basictypes.h" |
10 #include "base/command_line.h" | 10 #include "base/command_line.h" |
11 #include "base/histogram.h" | 11 #include "base/histogram.h" |
12 #include "base/message_loop.h" | 12 #include "base/message_loop.h" |
13 #include "base/ref_counted.h" | 13 #include "base/ref_counted.h" |
14 #include "base/stats_counters.h" | 14 #include "base/stats_counters.h" |
15 #include "base/string_util.h" | 15 #include "base/string_util.h" |
16 #include "base/thread.h" | 16 #include "base/thread.h" |
17 #include "base/time.h" | 17 #include "base/time.h" |
18 #include "base/watchdog.h" | 18 #include "base/watchdog.h" |
| 19 #include "build/build_config.h" |
19 #include "chrome/browser/browser_process.h" | 20 #include "chrome/browser/browser_process.h" |
20 #include "chrome/common/chrome_switches.h" | 21 #include "chrome/common/chrome_switches.h" |
21 | 22 |
| 23 #if defined(OS_LINUX) |
| 24 #include "chrome/common/gtk_util.h" |
| 25 #endif |
| 26 |
22 using base::TimeDelta; | 27 using base::TimeDelta; |
23 using base::TimeTicks; | 28 using base::TimeTicks; |
24 | 29 |
25 namespace { | 30 namespace { |
26 | 31 |
27 // The maximum threshold of delay of the message before considering it a delay. | 32 // The maximum threshold of delay of the message before considering it a delay. |
28 // For a debug build, you may want to set IO delay around 500ms. | 33 // For a debug build, you may want to set IO delay around 500ms. |
29 // For a release build, setting it around 350ms is sensible. | 34 // For a release build, setting it around 350ms is sensible. |
30 // Visit about:histograms to see what the distribution is on your system, with | 35 // Visit about:histograms to see what the distribution is on your system, with |
31 // your build. Be sure to do some work to get interesting stats. | 36 // your build. Be sure to do some work to get interesting stats. |
(...skipping 70 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
102 if (MessageLoop::current()->type() == MessageLoop::TYPE_UI) | 107 if (MessageLoop::current()->type() == MessageLoop::TYPE_UI) |
103 MessageLoopForUI::current()->AddObserver(this); | 108 MessageLoopForUI::current()->AddObserver(this); |
104 } | 109 } |
105 | 110 |
106 // Detaches the observer to the current thread's message loop. | 111 // Detaches the observer to the current thread's message loop. |
107 void DetachFromCurrentThread() { | 112 void DetachFromCurrentThread() { |
108 if (MessageLoop::current()->type() == MessageLoop::TYPE_UI) | 113 if (MessageLoop::current()->type() == MessageLoop::TYPE_UI) |
109 MessageLoopForUI::current()->RemoveObserver(this); | 114 MessageLoopForUI::current()->RemoveObserver(this); |
110 } | 115 } |
111 | 116 |
112 void WillProcessMessage(const MSG& msg) { | 117 void StartProcessingTimers() { |
113 begin_process_message_ = TimeTicks::Now(); | |
114 | |
115 // GetMessageTime returns a LONG (signed 32-bit) and GetTickCount returns | |
116 // a DWORD (unsigned 32-bit). They both wrap around when the time is longer | |
117 // than they can hold. I'm not sure if GetMessageTime wraps around to 0, | |
118 // or if the original time comes from GetTickCount, it might wrap around | |
119 // to -1. | |
120 // | |
121 // Therefore, I cast to DWORD so if it wraps to -1 we will correct it. If | |
122 // it doesn't, then our time delta will be negative if a message happens | |
123 // to straddle the wraparound point, it will still be OK. | |
124 DWORD cur_message_issue_time = static_cast<DWORD>(msg.time); | |
125 DWORD cur_time = GetTickCount(); | |
126 queueing_time_ = TimeDelta::FromMilliseconds(cur_time | |
127 - cur_message_issue_time); | |
128 // Simulate arming when the message entered the queue. | 118 // Simulate arming when the message entered the queue. |
129 total_time_watchdog_.ArmSomeTimeDeltaAgo(queueing_time_); | 119 total_time_watchdog_.ArmSomeTimeDeltaAgo(queueing_time_); |
130 if (queueing_time_ > MaxMessageDelay_) { | 120 if (queueing_time_ > MaxMessageDelay_) { |
131 // Message is too delayed. | 121 // Message is too delayed. |
132 queueing_delay_counter_.Increment(); | 122 queueing_delay_counter_.Increment(); |
| 123 #if defined(OS_WIN) |
133 if (kPlaySounds) | 124 if (kPlaySounds) |
134 MessageBeep(MB_ICONASTERISK); | 125 MessageBeep(MB_ICONASTERISK); |
| 126 #endif |
135 } | 127 } |
136 } | 128 } |
137 | 129 |
138 void DidProcessMessage(const MSG& msg) { | 130 void EndProcessingTimers() { |
139 total_time_watchdog_.Disarm(); | 131 total_time_watchdog_.Disarm(); |
140 TimeTicks now = TimeTicks::Now(); | 132 TimeTicks now = TimeTicks::Now(); |
141 if (begin_process_message_ != TimeTicks()) { | 133 if (begin_process_message_ != TimeTicks()) { |
142 TimeDelta processing_time = now - begin_process_message_; | 134 TimeDelta processing_time = now - begin_process_message_; |
143 process_times_.AddTime(processing_time); | 135 process_times_.AddTime(processing_time); |
144 total_times_.AddTime(queueing_time_ + processing_time); | 136 total_times_.AddTime(queueing_time_ + processing_time); |
145 } | 137 } |
146 if (now - begin_process_message_ > | 138 if (now - begin_process_message_ > |
147 TimeDelta::FromMilliseconds(kMaxMessageProcessingMs)) { | 139 TimeDelta::FromMilliseconds(kMaxMessageProcessingMs)) { |
148 // Message took too long to process. | 140 // Message took too long to process. |
149 slow_processing_counter_.Increment(); | 141 slow_processing_counter_.Increment(); |
| 142 #if defined(OS_WIN) |
150 if (kPlaySounds) | 143 if (kPlaySounds) |
151 MessageBeep(MB_ICONHAND); | 144 MessageBeep(MB_ICONHAND); |
| 145 #endif |
152 } | 146 } |
153 } | 147 } |
154 | 148 |
| 149 #if defined(OS_WIN) |
| 150 void WillProcessMessage(const MSG& msg) { |
| 151 begin_process_message_ = TimeTicks::Now(); |
| 152 |
| 153 // GetMessageTime returns a LONG (signed 32-bit) and GetTickCount returns |
| 154 // a DWORD (unsigned 32-bit). They both wrap around when the time is longer |
| 155 // than they can hold. I'm not sure if GetMessageTime wraps around to 0, |
| 156 // or if the original time comes from GetTickCount, it might wrap around |
| 157 // to -1. |
| 158 // |
| 159 // Therefore, I cast to DWORD so if it wraps to -1 we will correct it. If |
| 160 // it doesn't, then our time delta will be negative if a message happens |
| 161 // to straddle the wraparound point, it will still be OK. |
| 162 DWORD cur_message_issue_time = static_cast<DWORD>(msg.time); |
| 163 DWORD cur_time = GetTickCount(); |
| 164 queueing_time_ = |
| 165 base::TimeDelta::FromMilliseconds(cur_time - cur_message_issue_time); |
| 166 |
| 167 StartProcessingTimers(); |
| 168 } |
| 169 |
| 170 void DidProcessMessage(const MSG& msg) { |
| 171 EndProcessingTimers(); |
| 172 } |
| 173 |
| 174 #elif defined(OS_LINUX) |
| 175 void WillProcessEvent(GdkEvent* event) { |
| 176 begin_process_message_ = TimeTicks::Now(); |
| 177 guint event_time = event_utils::GetGdkEventTime(event); |
| 178 // TODO(evanm): it is not clear what that event_time is relative to! |
| 179 queueing_time_ = false // TODO: We ignore event_time for now. |
| 180 ? base::TimeDelta::FromMilliseconds(event_time) |
| 181 : base::TimeDelta::FromMilliseconds(0); |
| 182 StartProcessingTimers(); |
| 183 } |
| 184 |
| 185 void DidProcessEvent(GdkEvent* event) { |
| 186 EndProcessingTimers(); |
| 187 } |
| 188 #endif |
| 189 |
155 private: | 190 private: |
156 const TimeDelta MaxMessageDelay_; | 191 const TimeDelta MaxMessageDelay_; |
| 192 |
| 193 // Time at which the current message processing began. |
157 TimeTicks begin_process_message_; | 194 TimeTicks begin_process_message_; |
| 195 |
| 196 // Time the current message spent in the queue -- delta between message |
| 197 // construction time and message processing time. |
158 TimeDelta queueing_time_; | 198 TimeDelta queueing_time_; |
159 | 199 |
160 // Counters for the two types of jank we measure. | 200 // Counters for the two types of jank we measure. |
161 StatsCounter slow_processing_counter_; // Messages with long processing time. | 201 StatsCounter slow_processing_counter_; // Messages with long processing time. |
162 StatsCounter queueing_delay_counter_; // Messages with long queueing delay. | 202 StatsCounter queueing_delay_counter_; // Messages with long queueing delay. |
163 Histogram process_times_; // Time spent processing task. | 203 Histogram process_times_; // Time spent processing task. |
164 Histogram total_times_; // Total of queueing plus processing time. | 204 Histogram total_times_; // Total of queueing plus processing time. |
165 JankWatchdog total_time_watchdog_; // Watching for excessive total_time. | 205 JankWatchdog total_time_watchdog_; // Watching for excessive total_time. |
166 | 206 |
167 DISALLOW_EVIL_CONSTRUCTORS(JankObserver); | 207 DISALLOW_EVIL_CONSTRUCTORS(JankObserver); |
168 }; | 208 }; |
169 | 209 |
170 // These objects are created by InstallJankometer and leaked. | 210 // These objects are created by InstallJankometer and leaked. |
171 JankObserver* ui_observer = NULL; | 211 JankObserver* ui_observer = NULL; |
172 JankObserver* io_observer = NULL; | 212 JankObserver* io_observer = NULL; |
173 | 213 |
174 } // namespace | 214 } // namespace |
175 | 215 |
176 void InstallJankometer(const CommandLine &parsed_command_line) { | 216 void InstallJankometer(const CommandLine& parsed_command_line) { |
177 if (ui_observer || io_observer) { | 217 if (ui_observer || io_observer) { |
178 NOTREACHED() << "Initializing jank-o-meter twice"; | 218 NOTREACHED() << "Initializing jank-o-meter twice"; |
179 return; | 219 return; |
180 } | 220 } |
181 | 221 |
182 bool ui_watchdog_enabled = false; | 222 bool ui_watchdog_enabled = false; |
183 bool io_watchdog_enabled = false; | 223 bool io_watchdog_enabled = false; |
184 if (parsed_command_line.HasSwitch(switches::kEnableWatchdog)) { | 224 if (parsed_command_line.HasSwitch(switches::kEnableWatchdog)) { |
185 std::wstring list = | 225 std::wstring list = |
186 parsed_command_line.GetSwitchValue(switches::kEnableWatchdog); | 226 parsed_command_line.GetSwitchValue(switches::kEnableWatchdog); |
(...skipping 33 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
220 ui_observer->Release(); | 260 ui_observer->Release(); |
221 ui_observer = NULL; | 261 ui_observer = NULL; |
222 } | 262 } |
223 if (io_observer) { | 263 if (io_observer) { |
224 // IO thread can't be running when we remove observers. | 264 // IO thread can't be running when we remove observers. |
225 DCHECK((!g_browser_process) || !(g_browser_process->io_thread())); | 265 DCHECK((!g_browser_process) || !(g_browser_process->io_thread())); |
226 io_observer->Release(); | 266 io_observer->Release(); |
227 io_observer = NULL; | 267 io_observer = NULL; |
228 } | 268 } |
229 } | 269 } |
OLD | NEW |