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