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