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