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 : //
15 : // Profiler unittests.
16 : #include "syzygy/agent/profiler/profiler.h"
17 :
18 : #include <intrin.h>
19 : #include <psapi.h>
20 :
21 : #include "base/bind.h"
22 : #include "base/file_util.h"
23 : #include "base/message_loop.h"
24 : #include "base/scoped_temp_dir.h"
25 : #include "base/threading/platform_thread.h"
26 : #include "base/threading/thread.h"
27 : #include "gmock/gmock.h"
28 : #include "gtest/gtest.h"
29 : #include "syzygy/agent/common/process_utils.h"
30 : #include "syzygy/core/unittest_util.h"
31 : #include "syzygy/trace/common/unittest_util.h"
32 : #include "syzygy/trace/parse/parser.h"
33 : #include "syzygy/trace/parse/unittest_util.h"
34 : #include "syzygy/trace/protocol/call_trace_defs.h"
35 : #include "syzygy/trace/service/service.h"
36 : #include "syzygy/trace/service/service_rpc_impl.h"
37 : #include "syzygy/trace/service/trace_file_writer_factory.h"
38 :
39 : extern "C" {
40 :
41 : // We register a TLS callback to test TLS thread notifications.
42 : extern PIMAGE_TLS_CALLBACK profiler_test_tls_callback_entry;
43 : void WINAPI ProfilerTestTlsCallback(PVOID h, DWORD reason, PVOID reserved);
44 :
45 : // Force the linker to include the TLS entry.
46 : #pragma comment(linker, "/INCLUDE:__tls_used")
47 : #pragma comment(linker, "/INCLUDE:_profiler_test_tls_callback_entry")
48 :
49 : #pragma data_seg(push, old_seg)
50 : // Use a typical possible name in the .CRT$XL? list of segments.
51 : #pragma data_seg(".CRT$XLB")
52 : PIMAGE_TLS_CALLBACK profiler_test_tls_callback_entry =
53 : &ProfilerTestTlsCallback;
54 : #pragma data_seg(pop, old_seg)
55 :
56 : PIMAGE_TLS_CALLBACK tls_action = NULL;
57 :
58 E : void WINAPI ProfilerTestTlsCallback(PVOID h, DWORD reason, PVOID reserved) {
59 E : if (tls_action)
60 E : tls_action(h, reason, reserved);
61 E : }
62 :
63 : } // extern "C"
64 :
65 : namespace agent {
66 : namespace profiler {
67 :
68 : namespace {
69 :
70 : using agent::common::GetProcessModules;
71 : using agent::common::ModuleVector;
72 : using file_util::FileEnumerator;
73 : using testing::_;
74 : using testing::Return;
75 : using testing::StrictMockParseEventHandler;
76 : using trace::service::RpcServiceInstanceManager;
77 : using trace::service::TraceFileWriterFactory;
78 : using trace::service::Service;
79 : using trace::parser::Parser;
80 : using trace::parser::ParseEventHandler;
81 :
82 : // The information on how to set the thread name comes from
83 : // a MSDN article: http://msdn2.microsoft.com/en-us/library/xcb2z8hs.aspx
84 : const DWORD kVCThreadNameException = 0x406D1388;
85 :
86 : typedef struct tagTHREADNAME_INFO {
87 : DWORD dwType; // Must be 0x1000.
88 : LPCSTR szName; // Pointer to name (in user addr space).
89 : DWORD dwThreadID; // Thread ID (-1=caller thread).
90 : DWORD dwFlags; // Reserved for future use, must be zero.
91 : } THREADNAME_INFO;
92 :
93 : // This function has try handling, so it is separated out of its caller.
94 E : void SetNameInternal(const char* name) {
95 : THREADNAME_INFO info;
96 E : info.dwType = 0x1000;
97 E : info.szName = name;
98 E : info.dwThreadID = -1;
99 E : info.dwFlags = 0;
100 :
101 E : __try {
102 : RaiseException(kVCThreadNameException, 0, sizeof(info)/sizeof(DWORD),
103 E : reinterpret_cast<DWORD_PTR*>(&info));
104 E : } __except(EXCEPTION_CONTINUE_EXECUTION) {
105 i : }
106 E : }
107 :
108 : // Return address location resolution function.
109 : typedef uintptr_t (__cdecl *ResolveReturnAddressLocationFunc)(
110 : uintptr_t pc_location);
111 :
112 E : MATCHER_P(ModuleAtAddress, module, "") {
113 E : return arg->module_base_addr == module;
114 E : }
115 :
116 : // TODO(rogerm): Create a base fixture (perhaps templatized) to factor out
117 : // the common bits of testing various clients with the call trace service.
118 : class ProfilerTest : public testing::Test {
119 : public:
120 : ProfilerTest()
121 : : module_(NULL),
122 E : resolution_func_(NULL) {
123 E : }
124 :
125 E : virtual void SetUp() OVERRIDE {
126 E : testing::Test::SetUp();
127 :
128 : // Create a temporary directory for the call trace files.
129 E : ASSERT_TRUE(temp_dir_.CreateUniqueTempDir());
130 :
131 E : service_.SetEnvironment();
132 E : }
133 :
134 E : virtual void TearDown() OVERRIDE {
135 E : tls_action = NULL;
136 :
137 E : UnloadDll();
138 :
139 : // Stop the call trace service.
140 E : service_.Stop();
141 E : }
142 :
143 E : void StartService() {
144 E : service_.Start(temp_dir_.path());
145 E : }
146 :
147 E : void StopService() {
148 E : service_.Stop();
149 E : }
150 :
151 E : void ReplayLogs() {
152 : // Stop the service if it's running.
153 E : ASSERT_NO_FATAL_FAILURE(StopService());
154 :
155 E : Parser parser;
156 E : ASSERT_TRUE(parser.Init(&handler_));
157 :
158 : // Queue up the trace file(s) we engendered.
159 : file_util::FileEnumerator enumerator(temp_dir_.path(),
160 : false,
161 E : FileEnumerator::FILES);
162 E : size_t num_files = 0;
163 E : while (true) {
164 E : FilePath trace_file = enumerator.Next();
165 E : if (trace_file.empty())
166 E : break;
167 E : ASSERT_TRUE(parser.OpenTraceFile(trace_file));
168 E : ++num_files;
169 E : }
170 E : EXPECT_GT(num_files, 0U);
171 E : ASSERT_TRUE(parser.Consume());
172 E : }
173 :
174 : // TODO(siggi): These are shareable with the other instrumentation DLL tests.
175 : // Move them to a shared fixture superclass.
176 E : void LoadDll() {
177 E : ASSERT_TRUE(module_ == NULL);
178 : static const wchar_t kCallTraceDll[] = L"profile_client.dll";
179 E : ASSERT_EQ(NULL, ::GetModuleHandle(kCallTraceDll));
180 E : module_ = ::LoadLibrary(kCallTraceDll);
181 E : ASSERT_TRUE(module_ != NULL);
182 : _indirect_penter_dllmain_ =
183 E : ::GetProcAddress(module_, "_indirect_penter_dllmain");
184 E : _indirect_penter_ = ::GetProcAddress(module_, "_indirect_penter");
185 :
186 E : ASSERT_TRUE(_indirect_penter_dllmain_ != NULL);
187 E : ASSERT_TRUE(_indirect_penter_ != NULL);
188 :
189 : resolution_func_ = reinterpret_cast<ResolveReturnAddressLocationFunc>(
190 E : ::GetProcAddress(module_, "ResolveReturnAddressLocation"));
191 E : ASSERT_TRUE(resolution_func_ != NULL);
192 E : }
193 :
194 E : void UnloadDll() {
195 E : if (module_ != NULL) {
196 E : ASSERT_TRUE(::FreeLibrary(module_));
197 E : module_ = NULL;
198 E : _indirect_penter_ = NULL;
199 E : _indirect_penter_dllmain_ = NULL;
200 : }
201 E : }
202 :
203 : static BOOL WINAPI IndirectDllMain(HMODULE module,
204 : DWORD reason,
205 : LPVOID reserved);
206 : static BOOL WINAPI DllMainThunk(HMODULE module,
207 : DWORD reason,
208 : LPVOID reserved);
209 :
210 : static int IndirectFunctionA(int param1, const void* param2);
211 : static int FunctionAThunk(int param1, const void* param2);
212 : static int TestResolutionFuncThunk(ResolveReturnAddressLocationFunc resolver);
213 : static int TestResolutionFuncNestedThunk(
214 : ResolveReturnAddressLocationFunc resolver);
215 :
216 : protected:
217 : // The directory where trace file output will be written.
218 : ScopedTempDir temp_dir_;
219 :
220 : // The handler to which the trace file parser will delegate events.
221 : StrictMockParseEventHandler handler_;
222 :
223 : // The address resolution function exported from the profiler dll.
224 : ResolveReturnAddressLocationFunc resolution_func_;
225 :
226 : // Our call trace service process instance.
227 : testing::CallTraceService service_;
228 :
229 : private:
230 : HMODULE module_;
231 : static FARPROC _indirect_penter_;
232 : static FARPROC _indirect_penter_dllmain_;
233 : };
234 :
235 : FARPROC ProfilerTest::_indirect_penter_ = NULL;
236 : FARPROC ProfilerTest::_indirect_penter_dllmain_ = NULL;
237 :
238 : BOOL WINAPI ProfilerTest::IndirectDllMain(HMODULE module,
239 : DWORD reason,
240 E : LPVOID reserved) {
241 E : return TRUE;
242 E : }
243 :
244 : BOOL __declspec(naked) WINAPI ProfilerTest::DllMainThunk(HMODULE module,
245 : DWORD reason,
246 E : LPVOID reserved) {
247 : __asm {
248 E : push IndirectDllMain
249 E : jmp _indirect_penter_dllmain_
250 : }
251 : }
252 :
253 : int ProfilerTest::IndirectFunctionA(int param1,
254 E : const void* param2) {
255 E : return param1 + reinterpret_cast<int>(param2);
256 E : }
257 :
258 : int __declspec(naked) ProfilerTest::FunctionAThunk(int param1,
259 E : const void* param2) {
260 : __asm {
261 E : push IndirectFunctionA
262 E : jmp _indirect_penter_
263 : }
264 : }
265 :
266 E : void TestResolutionFunc(ResolveReturnAddressLocationFunc resolver) {
267 : uintptr_t pc_location =
268 E : reinterpret_cast<uintptr_t>(_AddressOfReturnAddress());
269 E : ASSERT_NE(pc_location, resolver(pc_location));
270 :
271 : // Make sure we unwind thunk chains.
272 E : pc_location = resolver(pc_location);
273 E : ASSERT_EQ(pc_location, resolver(pc_location));
274 E : }
275 :
276 : int __declspec(naked) ProfilerTest::TestResolutionFuncThunk(
277 E : ResolveReturnAddressLocationFunc resolver) {
278 : __asm {
279 E : push TestResolutionFunc
280 E : jmp _indirect_penter_
281 : }
282 : }
283 :
284 : int __declspec(naked) ProfilerTest::TestResolutionFuncNestedThunk(
285 E : ResolveReturnAddressLocationFunc resolver) {
286 : // This will make like tail call elimination and create nested thunks.
287 : __asm {
288 E : push TestResolutionFuncThunk
289 E : jmp _indirect_penter_
290 : }
291 : }
292 :
293 : } // namespace
294 :
295 E : TEST_F(ProfilerTest, NoServerNoCrash) {
296 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
297 :
298 E : EXPECT_TRUE(DllMainThunk(NULL, DLL_PROCESS_ATTACH, NULL));
299 E : }
300 :
301 E : TEST_F(ProfilerTest, ResolveReturnAddressLocation) {
302 : // Spin up the RPC service.
303 E : ASSERT_NO_FATAL_FAILURE(StartService());
304 :
305 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
306 :
307 : // Test the return address resolution function.
308 E : ASSERT_NO_FATAL_FAILURE(TestResolutionFuncThunk(resolution_func_));
309 :
310 : // And with a nested thunk.
311 E : ASSERT_NO_FATAL_FAILURE(TestResolutionFuncNestedThunk(resolution_func_));
312 E : }
313 :
314 E : TEST_F(ProfilerTest, RecordsAllModulesAndFunctions) {
315 : // Spin up the RPC service.
316 E : ASSERT_NO_FATAL_FAILURE(StartService());
317 :
318 : // Get our own module handle.
319 E : HMODULE self_module = ::GetModuleHandle(NULL);
320 :
321 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
322 : // TODO(rogerm): This generates spurious error logs at higher log levels
323 : // because the module paths are different when depending on who infers
324 : // them (one is drive letter based and the other is device based).
325 E : EXPECT_TRUE(DllMainThunk(self_module, DLL_PROCESS_ATTACH, NULL));
326 :
327 : // Get the module list prior to unloading the profile DLL.
328 E : ModuleVector modules;
329 E : GetProcessModules(&modules);
330 :
331 E : ASSERT_NO_FATAL_FAILURE(UnloadDll());
332 :
333 : // Set up expectations for what should be in the trace.
334 E : EXPECT_CALL(handler_, OnProcessStarted(_, ::GetCurrentProcessId(), _));
335 E : for (size_t i = 0; i < modules.size(); ++i) {
336 : EXPECT_CALL(handler_, OnProcessAttach(_,
337 : ::GetCurrentProcessId(),
338 : ::GetCurrentThreadId(),
339 E : ModuleAtAddress(modules[i])));
340 E : }
341 :
342 : // TODO(siggi): Match harder here.
343 : EXPECT_CALL(handler_, OnInvocationBatch(_,
344 : ::GetCurrentProcessId(),
345 : ::GetCurrentThreadId(),
346 : 1,
347 E : _));
348 E : EXPECT_CALL(handler_, OnProcessEnded(_, ::GetCurrentProcessId()));
349 :
350 : // Replay the log.
351 E : ASSERT_NO_FATAL_FAILURE(ReplayLogs());
352 E : }
353 :
354 : namespace {
355 :
356 : // We invoke the thunks through these intermediate functions to make sure
357 : // we can generate two or more identical invocation records, e.g. same
358 : // call site, same callee. We turn off inlining to make sure the functions
359 : // aren't assimilated into the callsite by the compiler or linker, thus
360 : // defeating our intent.
361 : #pragma auto_inline(off)
362 E : void InvokeDllMainThunk(HMODULE module) {
363 E : EXPECT_TRUE(ProfilerTest::DllMainThunk(module, DLL_PROCESS_ATTACH, NULL));
364 E : }
365 :
366 E : void InvokeFunctionAThunk() {
367 E : const int kParam1 = 0xFAB;
368 E : const void* kParam2 = &kParam1;
369 E : const int kExpected = kParam1 + reinterpret_cast<int>(kParam2);
370 E : EXPECT_EQ(kExpected, ProfilerTest::FunctionAThunk(kParam1, kParam2));
371 E : }
372 : #pragma auto_inline(on)
373 :
374 : } // namespace
375 :
376 E : TEST_F(ProfilerTest, RecordsOneEntryPerModuleAndFunction) {
377 : // Spin up the RPC service.
378 E : ASSERT_NO_FATAL_FAILURE(StartService());
379 :
380 : // Get our own module handle.
381 E : HMODULE self_module = ::GetModuleHandle(NULL);
382 :
383 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
384 :
385 : // Record the module load twice.
386 E : EXPECT_NO_FATAL_FAILURE(InvokeDllMainThunk(self_module));
387 E : EXPECT_NO_FATAL_FAILURE(InvokeDllMainThunk(self_module));
388 :
389 : // And invoke Function A twice.
390 E : ASSERT_NO_FATAL_FAILURE(InvokeFunctionAThunk());
391 E : ASSERT_NO_FATAL_FAILURE(InvokeFunctionAThunk());
392 :
393 : // Get the module list prior to unloading the profile DLL.
394 E : ModuleVector modules;
395 E : GetProcessModules(&modules);
396 :
397 E : ASSERT_NO_FATAL_FAILURE(UnloadDll());
398 :
399 E : EXPECT_CALL(handler_, OnProcessStarted(_, ::GetCurrentProcessId(), _));
400 :
401 : // We should only have one event per module,
402 : // despite the double DllMain invocation.
403 E : for (size_t i = 0; i < modules.size(); ++i) {
404 : EXPECT_CALL(handler_, OnProcessAttach(_,
405 : ::GetCurrentProcessId(),
406 : ::GetCurrentThreadId(),
407 E : ModuleAtAddress(modules[i])));
408 E : }
409 :
410 : // TODO(siggi): Match harder here.
411 : // We should only have two distinct invocation records,
412 : // despite calling each function twice.
413 : EXPECT_CALL(handler_, OnInvocationBatch(_,
414 : ::GetCurrentProcessId(),
415 : ::GetCurrentThreadId(),
416 : 2,
417 E : _));
418 E : EXPECT_CALL(handler_, OnProcessEnded(_, ::GetCurrentProcessId()));
419 :
420 : // Replay the log.
421 E : ASSERT_NO_FATAL_FAILURE(ReplayLogs());
422 E : }
423 :
424 E : TEST_F(ProfilerTest, RecordsThreadName) {
425 E : if (::IsDebuggerPresent()) {
426 i : LOG(WARNING) << "This test fails under debugging.";
427 i : return;
428 : }
429 :
430 : // Spin up the RPC service.
431 E : ASSERT_NO_FATAL_FAILURE(StartService());
432 :
433 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
434 :
435 : // And invoke a function to get things initialized.
436 E : ASSERT_NO_FATAL_FAILURE(InvokeFunctionAThunk());
437 :
438 : // Beware that this test will fail under debugging, as the
439 : // debugger by default swallows the exception.
440 : static const char kThreadName[] = "Profiler Test Thread";
441 E : SetNameInternal(kThreadName);
442 :
443 E : ASSERT_NO_FATAL_FAILURE(UnloadDll());
444 :
445 E : EXPECT_CALL(handler_, OnProcessStarted(_, ::GetCurrentProcessId(), _));
446 : EXPECT_CALL(handler_, OnProcessAttach(_,
447 : ::GetCurrentProcessId(),
448 : ::GetCurrentThreadId(),
449 : _))
450 E : .Times(testing::AnyNumber());
451 : EXPECT_CALL(handler_, OnInvocationBatch(_,
452 : ::GetCurrentProcessId(),
453 : ::GetCurrentThreadId(),
454 E : _ ,_));
455 : EXPECT_CALL(handler_, OnThreadName(_,
456 : ::GetCurrentProcessId(),
457 : ::GetCurrentThreadId(),
458 E : base::StringPiece(kThreadName)));
459 E : EXPECT_CALL(handler_, OnProcessEnded(_, ::GetCurrentProcessId()));
460 :
461 : // Replay the log.
462 E : ASSERT_NO_FATAL_FAILURE(ReplayLogs());
463 E : }
464 :
465 : namespace {
466 :
467 E : void WINAPI TlsAction(PVOID h, DWORD reason, PVOID reserved) {
468 E : InvokeFunctionAThunk();
469 E : }
470 :
471 : } // namespace
472 :
473 E : TEST_F(ProfilerTest, ReleasesBufferOnThreadExit) {
474 : // Spin up the RPC service.
475 E : ASSERT_NO_FATAL_FAILURE(StartService());
476 :
477 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
478 :
479 E : tls_action = TlsAction;
480 :
481 : // Spinning 400 * 8 threads should exhaust the address
482 : // space if we're leaking a buffer for each thread.
483 E : for (size_t i = 0; i < 400; ++i) {
484 E : base::Thread thread1("one");
485 E : base::Thread thread2("two");
486 E : base::Thread thread3("three");
487 E : base::Thread thread4("four");
488 E : base::Thread thread5("five");
489 E : base::Thread thread6("six");
490 E : base::Thread thread7("seven");
491 E : base::Thread thread8("eight");
492 :
493 E : base::Thread* threads[8] = { &thread1, &thread2, &thread3, &thread4,
494 E : &thread5, &thread6, &thread7, &thread8};
495 :
496 : // Start all the threads, and make them do some work.
497 E : for (size_t j = 0; j < arraysize(threads); ++j) {
498 E : base::Thread* thread = threads[j];
499 E : thread->Start();
500 : thread->message_loop()->PostTask(
501 E : FROM_HERE, base::Bind(InvokeFunctionAThunk));
502 E : }
503 :
504 : // This will implicitly wind down all the threads.
505 E : }
506 :
507 E : ASSERT_NO_FATAL_FAILURE(UnloadDll());
508 E : }
509 :
510 : } // namespace profiler
511 : } // namespace agent
|