1 : // Copyright 2012 Google Inc. All Rights Reserved.
2 : //
3 : // Licensed under the Apache License, Version 2.0 (the "License");
4 : // you may not use this file except in compliance with the License.
5 : // You may obtain a copy of the License at
6 : //
7 : // http://www.apache.org/licenses/LICENSE-2.0
8 : //
9 : // Unless required by applicable law or agreed to in writing, software
10 : // distributed under the License is distributed on an "AS IS" BASIS,
11 : // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12 : // See the License for the specific language governing permissions and
13 : // limitations under the License.
14 :
15 : #include <windows.h> // NOLINT
16 :
17 : #include "base/at_exit.h"
18 : #include "base/command_line.h"
19 : #include "base/logging.h"
20 : #include "base/string_number_conversions.h"
21 : #include "base/debug/trace_event_win.h"
22 : #include "base/files/file_path.h"
23 : #include "base/win/event_trace_controller.h"
24 : #include "sawbuck/common/com_utils.h"
25 : #include "syzygy/trace/protocol/call_trace_defs.h"
26 :
27 m : using base::win::EtwTraceController;
28 m : using base::win::EtwTraceProperties;
29 :
30 m : namespace {
31 :
32 m : static const wchar_t kCallTraceSessionName[] = L"Call Trace Logger";
33 m : static const wchar_t kChromeSessionName[] = L"Chrome Event Logger";
34 m : static const wchar_t kDefaultCallTraceFile[] = L"call_trace.etl";
35 m : static const wchar_t kDefaultKernelFile[] = L"kernel.etl";
36 :
37 m : enum FileMode {
38 m : kFileOverwrite,
39 m : kFileAppend
40 m : };
41 :
42 m : struct CallTraceOptions {
43 m : base::FilePath call_trace_file;
44 m : base::FilePath kernel_file;
45 m : base::FilePath chrome_file;
46 m : FileMode file_mode;
47 m : int flags;
48 m : int min_buffers;
49 m : };
50 :
51 : // Initializes the command-line and logging for functions called via rundll32.
52 m : static void Init() {
53 m : CommandLine::Init(0, NULL);
54 m : logging::InitLogging(L"",
55 m : logging::LOG_ONLY_TO_SYSTEM_DEBUG_LOG,
56 m : logging::DONT_LOCK_LOG_FILE,
57 m : logging::APPEND_TO_OLD_LOG_FILE,
58 m : logging::ENABLE_DCHECK_FOR_NON_OFFICIAL_RELEASE_BUILDS);
59 m : }
60 :
61 : // Parses command-line options for StartCallTrace.
62 m : static bool ParseOptions(CallTraceOptions* options) {
63 m : DCHECK(options != NULL);
64 :
65 m : CommandLine* cmd_line = CommandLine::ForCurrentProcess();
66 :
67 m : options->call_trace_file = cmd_line->GetSwitchValuePath("call-trace-file");
68 m : if (options->call_trace_file.empty())
69 m : options->call_trace_file = base::FilePath(kDefaultCallTraceFile);
70 :
71 m : options->kernel_file = cmd_line->GetSwitchValuePath("kernel-file");
72 m : if (options->kernel_file.empty())
73 m : options->kernel_file = base::FilePath(kDefaultKernelFile);
74 :
75 : // This is an optional argument. If specified, it must be different from
76 : // call-trace-file and kernel-file.
77 m : options->chrome_file = cmd_line->GetSwitchValuePath("chrome-file");
78 m : if (!options->chrome_file.empty()) {
79 m : if (options->chrome_file == options->call_trace_file ||
80 m : options->chrome_file == options->kernel_file) {
81 m : LOG(ERROR) << "chrome-file must be different from call-trace-file "
82 m : "and kernel-file.";
83 m : return false;
84 m : }
85 m : }
86 :
87 m : if (options->call_trace_file == options->kernel_file) {
88 m : LOG(ERROR) << "call-trace-file and kernel-file must be different.";
89 m : return false;
90 m : }
91 :
92 m : if (!base::StringToInt(cmd_line->GetSwitchValueASCII("kernel-flags"),
93 m : &options->flags)) {
94 m : options->flags = kDefaultEtwKernelFlags;
95 m : }
96 :
97 m : if (!base::StringToInt(cmd_line->GetSwitchValueASCII("min-buffers"),
98 m : &options->min_buffers)) {
99 m : options->min_buffers = 0;
100 m : }
101 :
102 m : if (cmd_line->HasSwitch("append"))
103 m : options->file_mode = kFileAppend;
104 m : else
105 m : options->file_mode = kFileOverwrite;
106 :
107 m : return true;
108 m : }
109 :
110 m : enum EtwTraceType {
111 m : kKernelType,
112 m : kCallTraceType,
113 m : kChromeType,
114 m : };
115 :
116 : // Sets up basic ETW trace properties.
117 m : static void SetupEtwProperties(EtwTraceType trace_type,
118 m : const CallTraceOptions& options,
119 m : EtwTraceProperties* properties) {
120 m : EVENT_TRACE_PROPERTIES* p = properties->get();
121 :
122 m : SYSTEM_INFO sysinfo = { 0 };
123 m : GetSystemInfo(&sysinfo);
124 :
125 : // Use the CPU cycle counter.
126 m : p->Wnode.ClientContext = 3;
127 : // The buffer size caps out at 1 MB, so we set it to the maximum. The value
128 : // here is in KB.
129 m : p->BufferSize = 1024;
130 :
131 : // We'll manually flush things in EndCallTrace.
132 m : p->FlushTimer = 0;
133 :
134 m : switch (trace_type) {
135 m : case kKernelType: {
136 m : properties->SetLoggerFileName(options.kernel_file.value().c_str());
137 :
138 m : p->Wnode.Guid = kSystemTraceControlGuid;
139 m : p->EnableFlags = options.flags;
140 :
141 : // Kernel traces need two buffers per CPU: one flushing to disk, the other
142 : // being used for live events. This has been sufficient in all situations
143 : // we've seen thus far.
144 m : p->MinimumBuffers = 2 * sysinfo.dwNumberOfProcessors;
145 m : p->MaximumBuffers = 4 * sysinfo.dwNumberOfProcessors;
146 m : break;
147 m : }
148 :
149 m : case kCallTraceType: {
150 m : properties->SetLoggerFileName(options.call_trace_file.value().c_str());
151 :
152 m : p->EnableFlags = 0;
153 :
154 : // The call_trace library seems to settle out anywhere from 7 to 12
155 : // buffers per CPU under heavy usage. We provide roughly half that to
156 : // start, with a hefty margin.
157 m : p->MinimumBuffers =
158 m : kMinEtwBuffersPerProcessor * sysinfo.dwNumberOfProcessors;
159 m : if (p->MinimumBuffers < kMinEtwBuffers)
160 m : p->MinimumBuffers = kMinEtwBuffers;
161 m : if (options.min_buffers > signed(p->MinimumBuffers))
162 m : p->MinimumBuffers = options.min_buffers;
163 m : p->MaximumBuffers = kEtwBufferMultiplier * p->MinimumBuffers;
164 :
165 m : break;
166 m : }
167 :
168 m : case kChromeType: {
169 : // This should never be called with an empty file name.
170 m : DCHECK(!options.chrome_file.empty());
171 :
172 m : properties->SetLoggerFileName(options.chrome_file.value().c_str());
173 :
174 : // Chrome is quite low volume.
175 m : p->EnableFlags = 0;
176 m : p->MinimumBuffers = 1;
177 m : p->MaximumBuffers = 5;
178 :
179 m : break;
180 m : }
181 :
182 m : default: {
183 m : NOTREACHED() << "Invalid EtwTraceType.";
184 m : }
185 m : }
186 :
187 : // Set the logging mode.
188 m : switch (options.file_mode) {
189 m : case kFileAppend: {
190 m : p->LogFileMode = EVENT_TRACE_FILE_MODE_APPEND;
191 m : break;
192 m : }
193 :
194 m : case kFileOverwrite: {
195 m : p->LogFileMode = EVENT_TRACE_FILE_MODE_NONE;
196 m : break;
197 m : }
198 :
199 m : default: {
200 m : NOTREACHED() << "Invalid FileMode.";
201 m : }
202 m : }
203 m : }
204 :
205 m : enum StartSessionResult {
206 m : kStarted,
207 m : kAlreadyStarted,
208 m : kError
209 m : };
210 :
211 : // Logs some summary information about a trace given its properties.
212 m : static void DumpEtwTraceProperties(const wchar_t* session_name,
213 m : EtwTraceProperties& props) {
214 m : LOG(INFO) << "Session '" << session_name << "' is logging to '"
215 m : << props.GetLoggerFileName() << "'.";
216 m : LOG(INFO) << " BufferSize = " << props.get()->BufferSize << " Kb";
217 m : LOG(INFO) << " BuffersWritten = " << props.get()->BuffersWritten;
218 m : LOG(INFO) << " EventsLost = " << props.get()->EventsLost;
219 m : LOG(INFO) << " NumberOfBuffers = " << props.get()->NumberOfBuffers;
220 m : }
221 :
222 : // Attempts to start an ETW trace with the given properties, returning a
223 : // handle to it via @p session_handle.
224 m : static StartSessionResult StartSession(const wchar_t* session_name,
225 m : EtwTraceProperties* props,
226 m : TRACEHANDLE* session_handle) {
227 m : DCHECK(session_name != NULL);
228 m : DCHECK(props != NULL);
229 m : DCHECK(session_handle != NULL);
230 :
231 m : *session_handle = NULL;
232 :
233 m : LOG(INFO) << "Starting '" << session_name
234 m : << "' session with output '" << props->GetLoggerFileName() << "'.";
235 m : HRESULT hr = EtwTraceController::Start(session_name,
236 m : props,
237 m : session_handle);
238 m : if (HRESULT_CODE(hr) == ERROR_ALREADY_EXISTS) {
239 m : LOG(WARNING) << "Session '" << session_name << "' already exists.";
240 m : return kAlreadyStarted;
241 m : }
242 m : if (FAILED(hr)) {
243 m : LOG(ERROR) << "Failed to start call trace session: "
244 m : << com::LogHr(hr) << ".";
245 m : return kError;
246 m : }
247 :
248 m : DumpEtwTraceProperties(session_name, *props);
249 :
250 m : return kStarted;
251 m : }
252 :
253 : // Logs information about a running ETW trace given its session name.
254 m : static bool DumpSessionStatus(const wchar_t* session_name) {
255 m : EtwTraceProperties props;
256 m : LOG(INFO) << "Querying session '" << session_name << "'.";
257 m : HRESULT hr = EtwTraceController::Query(session_name, &props);
258 m : if (HRESULT_CODE(hr) == ERROR_WMI_INSTANCE_NOT_FOUND) {
259 m : LOG(ERROR) << "Session '" << session_name << "' does not exist.";
260 m : return true;
261 m : }
262 m : if (FAILED(hr)) {
263 m : LOG(ERROR) << "Failed to query '" << session_name << "' session: "
264 m : << com::LogHr(hr) << ".";
265 m : return false;
266 m : }
267 :
268 m : DumpEtwTraceProperties(session_name, props);
269 :
270 m : return true;
271 m : }
272 :
273 : // Stops the given ETW logging session given its name and properties.
274 : // Returns true on success, false otherwise.
275 m : static bool StopSession(const wchar_t* session_name,
276 m : EtwTraceProperties* props) {
277 m : LOG(INFO) << "Stopping session '" << session_name << "'.";
278 m : HRESULT hr = EtwTraceController::Stop(session_name, props);
279 m : if (FAILED(hr)) {
280 m : LOG(ERROR) << "Failed to stop '" << session_name << "' session: "
281 m : << com::LogHr(hr) << ".";
282 m : return false;
283 m : }
284 :
285 m : return true;
286 m : }
287 :
288 : // Flushes and closes the trace with the given session name, returning
289 : // its file name via @p file_name. Returns true on success, false otherwise.
290 m : static bool FlushAndStopSession(const wchar_t* session_name,
291 m : std::wstring* file_name) {
292 m : DCHECK(file_name != NULL);
293 :
294 m : EtwTraceProperties props;
295 m : LOG(INFO) << "Querying session '" << session_name << "'.";
296 m : HRESULT hr = EtwTraceController::Query(session_name, &props);
297 m : if (FAILED(hr)) {
298 m : LOG(ERROR) << "Failed to query '" << session_name << "' session: "
299 m : << com::LogHr(hr) << ".";
300 m : return false;
301 m : }
302 :
303 m : *file_name = props.GetLoggerFileName();
304 :
305 m : LOG(INFO) << "Flushing session '" << session_name << "'.";
306 m : hr = EtwTraceController::Flush(session_name, &props);
307 m : if (FAILED(hr)) {
308 m : LOG(ERROR) << "Failed to flush '" << session_name << "' session: "
309 m : << com::LogHr(hr) << ".";
310 m : return false;
311 m : }
312 :
313 m : if (!StopSession(session_name, &props))
314 m : return false;
315 :
316 : // Log some information about the trace.
317 m : DumpEtwTraceProperties(session_name, props);
318 :
319 m : return true;
320 m : }
321 :
322 m : class ScopedSession {
323 m : public:
324 m : ScopedSession(const wchar_t* session_name,
325 m : EtwTraceProperties* properties)
326 m : : name_(session_name), props_(properties) {
327 m : DCHECK(session_name != NULL);
328 m : DCHECK(properties != NULL);
329 m : }
330 :
331 m : ~ScopedSession() {
332 m : DCHECK((name_ == NULL) == (props_ == NULL));
333 m : if (name_) {
334 m : StopSession(name_, props_);
335 m : }
336 m : }
337 :
338 m : void Release() {
339 m : name_ = NULL;
340 m : props_ = NULL;
341 m : }
342 :
343 m : private:
344 m : const wchar_t* name_;
345 m : EtwTraceProperties* props_;
346 m : };
347 :
348 m : } // namespace
349 :
350 m : bool StartCallTraceImpl() {
351 m : CallTraceOptions options;
352 m : if (!ParseOptions(&options))
353 m : return false;
354 :
355 : // Start the call-trace ETW session.
356 m : EtwTraceProperties call_trace_props;
357 m : SetupEtwProperties(kCallTraceType, options, &call_trace_props);
358 m : TRACEHANDLE session_handle = NULL;
359 m : StartSessionResult result = StartSession(kCallTraceSessionName,
360 m : &call_trace_props,
361 m : &session_handle);
362 m : if (result == kError)
363 m : return false;
364 :
365 : // Automatically clean up this session if we exit early.
366 m : ScopedSession call_trace_session(kCallTraceSessionName, &call_trace_props);
367 :
368 : // If we started the session (it wasn't already running), enable batch
369 : // entry logging. If we received kAlreadyStarted, session_handle is invalid
370 : // so we're can't call EnableTrace.
371 m : if (result == kStarted) {
372 : // Enable batch entry logging.
373 m : ULONG err = ::EnableTrace(TRUE,
374 m : TRACE_FLAG_BATCH_ENTER,
375 m : CALL_TRACE_LEVEL,
376 m : &kCallTraceProvider,
377 m : session_handle);
378 m : if (err != ERROR_SUCCESS) {
379 m : LOG(ERROR) << "Failed to enable call trace batch logging: "
380 m : << com::LogWe(err) << ".";
381 m : return false;
382 m : }
383 m : }
384 :
385 : // Start the kernel ETW session.
386 m : EtwTraceProperties kernel_props;
387 m : SetupEtwProperties(kKernelType, options, &kernel_props);
388 m : result = StartSession(KERNEL_LOGGER_NAMEW, &kernel_props, &session_handle);
389 m : if (result == kError) {
390 m : LOG(INFO) << "Failed to start '" << KERNEL_LOGGER_NAMEW << "' session, "
391 m : << "shutting down '" << kCallTraceSessionName << "' sesion.";
392 m : return false;
393 m : }
394 :
395 : // Automatically clean up this session if we exit early.
396 m : ScopedSession kernel_session(KERNEL_LOGGER_NAMEW, &kernel_props);
397 :
398 : // If a chrome file name has been provided, enable it as well.
399 m : if (!options.chrome_file.empty()) {
400 m : EtwTraceProperties chrome_props;
401 m : SetupEtwProperties(kChromeType, options, &chrome_props);
402 m : result = StartSession(kChromeSessionName, &chrome_props, &session_handle);
403 m : if (result == kError) {
404 m : LOG(INFO) << "Failed to start '" << kChromeSessionName << "' session, "
405 m : << "shutting down other session.";
406 m : return false;
407 m : }
408 :
409 : // Automatically clean up this session if we exit early.
410 m : ScopedSession chrome_session(kChromeSessionName, &chrome_props);
411 :
412 m : if (result == kStarted) {
413 : // Enable Chrome trace events.
414 m : ULONG err = ::EnableTrace(TRUE,
415 m : 0,
416 m : TRACE_LEVEL_INFORMATION,
417 m : &base::debug::kChromeTraceProviderName,
418 m : session_handle);
419 m : if (err != ERROR_SUCCESS) {
420 m : LOG(ERROR) << "Failed to enable Chrome logging: " << com::LogWe(err)
421 m : << ".";
422 m : return false;
423 m : }
424 m : }
425 :
426 : // Release the ScopedSession so it doesn't get torn down.
427 m : chrome_session.Release();
428 m : }
429 :
430 : // Release the ScopedSessions so that they don't get torn down as we're
431 : // exiting successfully.
432 m : kernel_session.Release();
433 m : call_trace_session.Release();
434 :
435 : // Sleep a bit to allow the call-trace session to settle down. When the
436 : // kernel trace is started, all running processes and modules in memory are
437 : // enumerated.
438 : // TODO(chrisha): Be a little smarter here, and continuously monitor the
439 : // event rate for each session, and wait until the initial spurt of
440 : // activity is finished.
441 m : ::Sleep(2500);
442 :
443 m : return true;
444 m : }
445 :
446 m : bool QueryCallTraceImpl() {
447 m : bool success = true;
448 :
449 m : if (!DumpSessionStatus(kCallTraceSessionName))
450 m : success = false;
451 :
452 m : if (!DumpSessionStatus(KERNEL_LOGGER_NAMEW))
453 m : success = false;
454 :
455 m : if (!DumpSessionStatus(kChromeSessionName))
456 m : success = false;
457 :
458 m : return success;
459 m : }
460 :
461 m : bool StopCallTraceImpl() {
462 : // Always try stopping both traces before exiting on error. It may be that
463 : // one of them was already stopped manually and FlushAndStopSession will
464 : // return failure.
465 m : std::wstring call_trace_file;
466 m : std::wstring kernel_file;
467 m : std::wstring chrome_file;
468 m : bool success = true;
469 m : if (!FlushAndStopSession(kCallTraceSessionName, &call_trace_file))
470 m : success = false;
471 m : if (!FlushAndStopSession(KERNEL_LOGGER_NAMEW, &kernel_file))
472 m : success = false;
473 :
474 m : EtwTraceProperties props;
475 m : HRESULT hr = EtwTraceController::Query(kChromeSessionName, &props);
476 m : if (SUCCEEDED(hr)) {
477 m : LOG(INFO) << "Detected optional session: '" << kChromeSessionName << "'.";
478 m : if (!FlushAndStopSession(kChromeSessionName, &chrome_file))
479 m : success = false;
480 m : }
481 :
482 : // TODO(chrisha): Add ETL file merging support here.
483 m : return success;
484 m : }
485 :
486 m : void CALLBACK StartCallTrace(HWND unused_window,
487 m : HINSTANCE unused_instance,
488 m : LPSTR unused_cmd_line,
489 m : int unused_show) {
490 m : Init();
491 m : StartCallTraceImpl();
492 m : }
493 :
494 m : void CALLBACK StopCallTrace(HWND unused_window,
495 m : HINSTANCE unused_instance,
496 m : LPSTR unused_cmd_line,
497 m : int unused_show) {
498 m : Init();
499 m : StopCallTraceImpl();
500 m : }
|