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 : // 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/scoped_native_library.h"
24 : #include "base/files/file_enumerator.h"
25 : #include "base/files/scoped_temp_dir.h"
26 : #include "base/message_loop/message_loop.h"
27 : #include "base/threading/platform_thread.h"
28 : #include "base/threading/thread.h"
29 : #include "gmock/gmock.h"
30 : #include "gtest/gtest.h"
31 : #include "syzygy/agent/common/process_utils.h"
32 : #include "syzygy/core/unittest_util.h"
33 : #include "syzygy/pe/unittest_util.h"
34 : #include "syzygy/trace/common/unittest_util.h"
35 : #include "syzygy/trace/parse/parser.h"
36 : #include "syzygy/trace/parse/unittest_util.h"
37 : #include "syzygy/trace/protocol/call_trace_defs.h"
38 : #include "syzygy/trace/service/service.h"
39 : #include "syzygy/trace/service/service_rpc_impl.h"
40 :
41 : extern "C" {
42 :
43 : typedef void (__cdecl *AddDynamicSymbolFunc)(
44 : const void* address, size_t length, const char* name, size_t name_len);
45 : typedef void (__cdecl *MoveDynamicSymbolFunc)(
46 : const void* old_address, const void* new_address);
47 : typedef void (__cdecl *OnDynamicFunctionEntryFunc)(
48 : uintptr_t function, uintptr_t return_addr_location);
49 :
50 : // We register a TLS callback to test TLS thread notifications.
51 : extern PIMAGE_TLS_CALLBACK profiler_test_tls_callback_entry;
52 : void WINAPI ProfilerTestTlsCallback(PVOID h, DWORD reason, PVOID reserved);
53 :
54 : // Force the linker to include the TLS entry.
55 : #pragma comment(linker, "/INCLUDE:__tls_used")
56 : #pragma comment(linker, "/INCLUDE:_profiler_test_tls_callback_entry")
57 :
58 : #pragma data_seg(push, old_seg)
59 : // Use a typical possible name in the .CRT$XL? list of segments.
60 : #pragma data_seg(".CRT$XLB")
61 : PIMAGE_TLS_CALLBACK profiler_test_tls_callback_entry =
62 : &ProfilerTestTlsCallback;
63 : #pragma data_seg(pop, old_seg)
64 :
65 : PIMAGE_TLS_CALLBACK tls_action = NULL;
66 :
67 E : void WINAPI ProfilerTestTlsCallback(PVOID h, DWORD reason, PVOID reserved) {
68 E : if (tls_action)
69 E : tls_action(h, reason, reserved);
70 E : }
71 :
72 : } // extern "C"
73 :
74 : namespace agent {
75 : namespace profiler {
76 :
77 : namespace {
78 :
79 : using agent::common::GetProcessModules;
80 : using agent::common::ModuleVector;
81 : using testing::_;
82 : using testing::AllOf;
83 : using testing::Return;
84 : using testing::StrictMockParseEventHandler;
85 : using trace::service::RpcServiceInstanceManager;
86 : using trace::service::Service;
87 : using trace::parser::Parser;
88 : using trace::parser::ParseEventHandler;
89 :
90 : // The information on how to set the thread name comes from
91 : // a MSDN article: http://msdn2.microsoft.com/en-us/library/xcb2z8hs.aspx
92 : const DWORD kVCThreadNameException = 0x406D1388;
93 :
94 : typedef struct tagTHREADNAME_INFO {
95 : DWORD dwType; // Must be 0x1000.
96 : LPCSTR szName; // Pointer to name (in user addr space).
97 : DWORD dwThreadID; // Thread ID (-1=caller thread).
98 : DWORD dwFlags; // Reserved for future use, must be zero.
99 : } THREADNAME_INFO;
100 :
101 : // This function has try handling, so it is separated out of its caller.
102 i : void SetNameInternal(const char* name) {
103 : THREADNAME_INFO info;
104 i : info.dwType = 0x1000;
105 i : info.szName = name;
106 i : info.dwThreadID = -1;
107 i : info.dwFlags = 0;
108 :
109 i : __try {
110 : RaiseException(kVCThreadNameException, 0, sizeof(info)/sizeof(DWORD),
111 i : reinterpret_cast<DWORD_PTR*>(&info));
112 i : } __except(EXCEPTION_CONTINUE_EXECUTION) {
113 i : }
114 i : }
115 :
116 : // Return address location resolution function.
117 : typedef uintptr_t (__cdecl *ResolveReturnAddressLocationFunc)(
118 : uintptr_t pc_location);
119 :
120 E : MATCHER_P(ModuleAtAddress, module, "") {
121 E : return arg->module_base_addr == module;
122 E : }
123 :
124 E : MATCHER_P2(InvocationInfoHasCallerSymbol, symbol_id, symbol_len, "") {
125 E : for (size_t i = 0; i < 1; ++i) {
126 E : const InvocationInfo& invocation = arg->invocations[i];
127 : // Test that we have the symbol as caller.
128 : if (invocation.flags & kCallerIsSymbol &&
129 E : invocation.caller_symbol_id == symbol_id) {
130 : // We found the desired symbol, now check that caller offset
131 : // is in bounds of the symbol length, but larger than 0, as we know
132 : // the return address will be to a location after a call instruction,
133 : // which has to be some amount of distance into the caller.
134 : if (invocation.caller_offset >= symbol_len ||
135 E : invocation.caller_offset == 0) {
136 i : return false;
137 : }
138 :
139 E : return true;
140 : }
141 E : }
142 :
143 E : return false;
144 E : }
145 :
146 E : MATCHER_P(InvocationInfoHasFunctionSymbol, symbol_id, "") {
147 E : for (size_t i = 0; i < 1; ++i) {
148 E : const InvocationInfo& invocation = arg->invocations[i];
149 : // Test that we have the symbol as caller.
150 : if ((invocation.flags & kFunctionIsSymbol) == kFunctionIsSymbol &&
151 E : invocation.function_symbol_id == symbol_id) {
152 E : return true;
153 : }
154 i : }
155 :
156 i : return false;
157 E : }
158 :
159 : // This needs to be declared at file scope for the benefit of __asm code.
160 : enum CallerAction {
161 : CALL_THROUGH,
162 : CALL_V8_ENTRY_HOOK,
163 : RETURN_LENGTH,
164 : RETURN_ADDR
165 : };
166 :
167 : // TODO(rogerm): Create a base fixture (perhaps templatized) to factor out
168 : // the common bits of testing various clients with the call trace service.
169 : class ProfilerTest : public testing::Test {
170 : public:
171 : ProfilerTest()
172 : : module_(NULL),
173 : resolution_func_(NULL),
174 : add_symbol_func_(NULL),
175 : move_symbol_func_(NULL),
176 E : on_v8_function_entry_(NULL) {
177 E : }
178 :
179 E : virtual void SetUp() OVERRIDE {
180 E : testing::Test::SetUp();
181 :
182 : // Create a temporary directory for the call trace files.
183 E : ASSERT_TRUE(temp_dir_.CreateUniqueTempDir());
184 :
185 E : service_.SetEnvironment();
186 E : }
187 :
188 E : virtual void TearDown() OVERRIDE {
189 E : tls_action = NULL;
190 :
191 E : UnloadDll();
192 :
193 : // Stop the call trace service.
194 E : service_.Stop();
195 E : }
196 :
197 E : void StartService() {
198 E : service_.Start(temp_dir_.path());
199 E : }
200 :
201 E : void StopService() {
202 E : service_.Stop();
203 E : }
204 :
205 E : void ReplayLogs() {
206 : // Stop the service if it's running.
207 E : ASSERT_NO_FATAL_FAILURE(StopService());
208 :
209 E : Parser parser;
210 E : ASSERT_TRUE(parser.Init(&handler_));
211 :
212 : // Queue up the trace file(s) we engendered.
213 : base::FileEnumerator enumerator(temp_dir_.path(),
214 : false,
215 E : base::FileEnumerator::FILES);
216 E : size_t num_files = 0;
217 E : while (true) {
218 E : base::FilePath trace_file = enumerator.Next();
219 E : if (trace_file.empty())
220 E : break;
221 E : ASSERT_TRUE(parser.OpenTraceFile(trace_file));
222 E : ++num_files;
223 E : }
224 E : EXPECT_GT(num_files, 0U);
225 E : ASSERT_TRUE(parser.Consume());
226 E : }
227 :
228 : // TODO(siggi): These are shareable with the other instrumentation DLL tests.
229 : // Move them to a shared fixture superclass.
230 E : void LoadDll() {
231 E : ASSERT_TRUE(module_ == NULL);
232 : static const wchar_t kCallTraceDll[] = L"profile_client.dll";
233 E : ASSERT_EQ(NULL, ::GetModuleHandle(kCallTraceDll));
234 E : module_ = ::LoadLibrary(kCallTraceDll);
235 E : ASSERT_TRUE(module_ != NULL);
236 : _indirect_penter_dllmain_ =
237 E : ::GetProcAddress(module_, "_indirect_penter_dllmain");
238 E : _indirect_penter_ = ::GetProcAddress(module_, "_indirect_penter");
239 :
240 E : ASSERT_TRUE(_indirect_penter_dllmain_ != NULL);
241 E : ASSERT_TRUE(_indirect_penter_ != NULL);
242 :
243 : resolution_func_ = reinterpret_cast<ResolveReturnAddressLocationFunc>(
244 E : ::GetProcAddress(module_, "ResolveReturnAddressLocation"));
245 E : ASSERT_TRUE(resolution_func_ != NULL);
246 :
247 : add_symbol_func_ = reinterpret_cast<AddDynamicSymbolFunc>(
248 E : ::GetProcAddress(module_, "AddDynamicSymbol"));
249 E : ASSERT_TRUE(add_symbol_func_ != NULL);
250 :
251 : move_symbol_func_ = reinterpret_cast<MoveDynamicSymbolFunc>(
252 E : ::GetProcAddress(module_, "MoveDynamicSymbol"));
253 E : ASSERT_TRUE(add_symbol_func_ != NULL);
254 :
255 : on_v8_function_entry_ = reinterpret_cast<OnDynamicFunctionEntryFunc>(
256 E : ::GetProcAddress(module_, "OnDynamicFunctionEntry"));
257 E : ASSERT_TRUE(on_v8_function_entry_ != NULL);
258 E : }
259 :
260 E : void UnloadDll() {
261 E : if (module_ != NULL) {
262 E : ASSERT_TRUE(::FreeLibrary(module_));
263 E : module_ = NULL;
264 E : _indirect_penter_ = NULL;
265 E : _indirect_penter_dllmain_ = NULL;
266 : }
267 E : }
268 :
269 : static BOOL WINAPI IndirectDllMain(HMODULE module,
270 : DWORD reason,
271 : LPVOID reserved);
272 : static BOOL WINAPI DllMainThunk(HMODULE module,
273 : DWORD reason,
274 : LPVOID reserved);
275 : // This function has a curious construct to work around incremental linking.
276 : // It can be called in three modes, to:
277 : // 1. Call through to DllMainThunk.
278 : // 2. Call the supplied v8 entry hook.
279 : // 3. Return it's own length.
280 : // 4. Return it's own address.
281 : // The last is necessary because &DllMainCaller will return the address of
282 : // a trampoline in incremental builds, whereas we need the address of the
283 : // function's implementation for the test.
284 : static intptr_t WINAPI DllMainCaller(CallerAction action,
285 : OnDynamicFunctionEntryFunc hook);
286 :
287 : static int IndirectFunctionA(int param1, const void* param2);
288 : static int FunctionAThunk(int param1, const void* param2);
289 : static int TestResolutionFuncThunk(ResolveReturnAddressLocationFunc resolver);
290 : static int TestResolutionFuncNestedThunk(
291 : ResolveReturnAddressLocationFunc resolver);
292 :
293 : protected:
294 : // The directory where trace file output will be written.
295 : base::ScopedTempDir temp_dir_;
296 :
297 : // The handler to which the trace file parser will delegate events.
298 : StrictMockParseEventHandler handler_;
299 :
300 : // Functions exported from the profiler dll.
301 : ResolveReturnAddressLocationFunc resolution_func_;
302 : AddDynamicSymbolFunc add_symbol_func_;
303 : MoveDynamicSymbolFunc move_symbol_func_;
304 : OnDynamicFunctionEntryFunc on_v8_function_entry_;
305 :
306 : // Our call trace service process instance.
307 : testing::CallTraceService service_;
308 :
309 : private:
310 : HMODULE module_;
311 :
312 : static FARPROC _indirect_penter_;
313 : static FARPROC _indirect_penter_dllmain_;
314 : };
315 :
316 : FARPROC ProfilerTest::_indirect_penter_ = NULL;
317 : FARPROC ProfilerTest::_indirect_penter_dllmain_ = NULL;
318 :
319 : BOOL WINAPI ProfilerTest::IndirectDllMain(HMODULE module,
320 : DWORD reason,
321 E : LPVOID reserved) {
322 E : return TRUE;
323 E : }
324 :
325 : BOOL __declspec(naked) WINAPI ProfilerTest::DllMainThunk(HMODULE module,
326 : DWORD reason,
327 i : LPVOID reserved) {
328 : __asm {
329 i : push IndirectDllMain
330 i : jmp _indirect_penter_dllmain_
331 : }
332 : }
333 :
334 : intptr_t __declspec(naked) WINAPI ProfilerTest::DllMainCaller(
335 i : CallerAction action, OnDynamicFunctionEntryFunc hook) {
336 : __asm {
337 : start:
338 i : mov eax, dword ptr[esp + 4] // get action
339 i : cmp eax, CALL_THROUGH
340 i : je call_through
341 :
342 i : cmp eax, CALL_V8_ENTRY_HOOK
343 i : je call_v8_entry_hook
344 :
345 i : cmp eax, RETURN_LENGTH
346 i : je return_length
347 :
348 i : cmp eax, RETURN_ADDR
349 i : je return_addr
350 :
351 i : xor eax, eax
352 i : ret 8
353 :
354 : return_length:
355 : // You'd think this could be phrased as:
356 : // mov eax, OFFSET end - OFFSET start
357 : // but alas it appears that this assembler is single-pass, and so does not
358 : // support arithmetic on labels.
359 i : mov eax, OFFSET end
360 i : sub eax, OFFSET start
361 i : ret 8
362 :
363 : return_addr:
364 i : mov eax, OFFSET start
365 i : ret 8
366 :
367 : call_through:
368 i : xor eax, eax
369 i : push eax
370 i : push eax
371 i : push eax
372 i : call DllMainThunk
373 i : ret 8
374 :
375 : call_v8_entry_hook:
376 i : push esp
377 : // Push the start label rather than the address of the function,
378 : // as the latter resolves to a thunk under incremental linking.
379 i : push OFFSET start
380 i : call [esp + 0x10]
381 i : add esp, 8
382 i : ret 8
383 :
384 : end:
385 : }
386 : }
387 :
388 : int ProfilerTest::IndirectFunctionA(int param1,
389 E : const void* param2) {
390 E : return param1 + reinterpret_cast<int>(param2);
391 E : }
392 :
393 : int __declspec(naked) ProfilerTest::FunctionAThunk(int param1,
394 i : const void* param2) {
395 : __asm {
396 i : push IndirectFunctionA
397 i : jmp _indirect_penter_
398 : }
399 : }
400 :
401 E : void TestResolutionFunc(ResolveReturnAddressLocationFunc resolver) {
402 : uintptr_t pc_location =
403 E : reinterpret_cast<uintptr_t>(_AddressOfReturnAddress());
404 E : ASSERT_NE(pc_location, resolver(pc_location));
405 :
406 : // Make sure we unwind thunk chains.
407 E : pc_location = resolver(pc_location);
408 E : ASSERT_EQ(pc_location, resolver(pc_location));
409 E : }
410 :
411 : int __declspec(naked) ProfilerTest::TestResolutionFuncThunk(
412 i : ResolveReturnAddressLocationFunc resolver) {
413 : __asm {
414 i : push TestResolutionFunc
415 i : jmp _indirect_penter_
416 : }
417 : }
418 :
419 : int __declspec(naked) ProfilerTest::TestResolutionFuncNestedThunk(
420 i : ResolveReturnAddressLocationFunc resolver) {
421 : // This will make like tail call elimination and create nested thunks.
422 : __asm {
423 i : push TestResolutionFuncThunk
424 i : jmp _indirect_penter_
425 : }
426 : }
427 :
428 : } // namespace
429 :
430 E : TEST_F(ProfilerTest, NoServerNoCrash) {
431 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
432 :
433 E : EXPECT_TRUE(DllMainThunk(NULL, DLL_PROCESS_ATTACH, NULL));
434 E : }
435 :
436 E : TEST_F(ProfilerTest, ResolveReturnAddressLocation) {
437 : // Spin up the RPC service.
438 E : ASSERT_NO_FATAL_FAILURE(StartService());
439 :
440 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
441 :
442 : // Test the return address resolution function.
443 E : ASSERT_NO_FATAL_FAILURE(TestResolutionFuncThunk(resolution_func_));
444 :
445 : // And with a nested thunk.
446 E : ASSERT_NO_FATAL_FAILURE(TestResolutionFuncNestedThunk(resolution_func_));
447 E : }
448 :
449 E : TEST_F(ProfilerTest, RecordsAllModulesAndFunctions) {
450 : // Spin up the RPC service.
451 E : ASSERT_NO_FATAL_FAILURE(StartService());
452 :
453 : // Get our own module handle.
454 E : HMODULE self_module = ::GetModuleHandle(NULL);
455 :
456 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
457 : // TODO(rogerm): This generates spurious error logs at higher log levels
458 : // because the module paths are different when depending on who infers
459 : // them (one is drive letter based and the other is device based).
460 E : EXPECT_TRUE(DllMainThunk(self_module, DLL_PROCESS_ATTACH, NULL));
461 :
462 : // Get the module list prior to unloading the profile DLL.
463 E : ModuleVector modules;
464 E : GetProcessModules(&modules);
465 :
466 E : ASSERT_NO_FATAL_FAILURE(UnloadDll());
467 :
468 : // Set up expectations for what should be in the trace.
469 E : EXPECT_CALL(handler_, OnProcessStarted(_, ::GetCurrentProcessId(), _));
470 E : for (size_t i = 0; i < modules.size(); ++i) {
471 : EXPECT_CALL(handler_, OnProcessAttach(_,
472 : ::GetCurrentProcessId(),
473 : ::GetCurrentThreadId(),
474 E : ModuleAtAddress(modules[i])));
475 E : }
476 :
477 : // TODO(siggi): Match harder here.
478 : EXPECT_CALL(handler_, OnInvocationBatch(_,
479 : ::GetCurrentProcessId(),
480 : ::GetCurrentThreadId(),
481 : 1,
482 E : _));
483 E : EXPECT_CALL(handler_, OnProcessEnded(_, ::GetCurrentProcessId()));
484 :
485 : // Replay the log.
486 E : ASSERT_NO_FATAL_FAILURE(ReplayLogs());
487 E : }
488 :
489 : namespace {
490 :
491 : // We invoke the thunks through these intermediate functions to make sure
492 : // we can generate two or more identical invocation records, e.g. same
493 : // call site, same callee. We turn off inlining to make sure the functions
494 : // aren't assimilated into the callsite by the compiler or linker, thus
495 : // defeating our intent.
496 : #pragma auto_inline(off)
497 E : void InvokeDllMainThunk(HMODULE module) {
498 E : EXPECT_TRUE(ProfilerTest::DllMainThunk(module, DLL_PROCESS_ATTACH, NULL));
499 E : }
500 :
501 E : void InvokeFunctionAThunk() {
502 E : const int kParam1 = 0xFAB;
503 E : const void* kParam2 = &kParam1;
504 E : const int kExpected = kParam1 + reinterpret_cast<int>(kParam2);
505 E : EXPECT_EQ(kExpected, ProfilerTest::FunctionAThunk(kParam1, kParam2));
506 E : }
507 : #pragma auto_inline(on)
508 :
509 : } // namespace
510 :
511 E : TEST_F(ProfilerTest, RecordsOneEntryPerModuleAndFunction) {
512 : // Spin up the RPC service.
513 E : ASSERT_NO_FATAL_FAILURE(StartService());
514 :
515 : // Get our own module handle.
516 E : HMODULE self_module = ::GetModuleHandle(NULL);
517 :
518 : // Make sure the test DLL isn't already loaded.
519 E : ASSERT_EQ(NULL, ::GetModuleHandle(testing::kTestDllName));
520 :
521 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
522 :
523 : // Record the module load twice.
524 E : EXPECT_NO_FATAL_FAILURE(InvokeDllMainThunk(self_module));
525 E : EXPECT_NO_FATAL_FAILURE(InvokeDllMainThunk(self_module));
526 :
527 : // And invoke Function A twice.
528 E : ASSERT_NO_FATAL_FAILURE(InvokeFunctionAThunk());
529 E : ASSERT_NO_FATAL_FAILURE(InvokeFunctionAThunk());
530 :
531 : // Load this module late to verify it's included in the module list.
532 E : base::ScopedNativeLibrary test_dll(::LoadLibrary(testing::kTestDllName));
533 E : ASSERT_TRUE(test_dll.is_valid());
534 :
535 : // Get the module list prior to unloading the profile DLL.
536 E : ModuleVector modules;
537 E : GetProcessModules(&modules);
538 :
539 E : ASSERT_NO_FATAL_FAILURE(UnloadDll());
540 :
541 E : EXPECT_CALL(handler_, OnProcessStarted(_, ::GetCurrentProcessId(), _));
542 :
543 : // We should only have one event per module,
544 : // despite the double DllMain invocation.
545 E : for (size_t i = 0; i < modules.size(); ++i) {
546 : EXPECT_CALL(handler_, OnProcessAttach(_,
547 : ::GetCurrentProcessId(),
548 : ::GetCurrentThreadId(),
549 E : ModuleAtAddress(modules[i])));
550 E : }
551 :
552 : // TODO(siggi): Match harder here.
553 : // We should only have two distinct invocation records,
554 : // despite calling each function twice.
555 : EXPECT_CALL(handler_, OnInvocationBatch(_,
556 : ::GetCurrentProcessId(),
557 : ::GetCurrentThreadId(),
558 : 2,
559 E : _));
560 E : EXPECT_CALL(handler_, OnProcessEnded(_, ::GetCurrentProcessId()));
561 :
562 : // Replay the log.
563 E : ASSERT_NO_FATAL_FAILURE(ReplayLogs());
564 E : }
565 :
566 E : TEST_F(ProfilerTest, RecordsThreadName) {
567 E : if (::IsDebuggerPresent()) {
568 i : LOG(WARNING) << "This test fails under debugging.";
569 i : return;
570 : }
571 :
572 : // Spin up the RPC service.
573 E : ASSERT_NO_FATAL_FAILURE(StartService());
574 :
575 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
576 :
577 : // And invoke a function to get things initialized.
578 E : ASSERT_NO_FATAL_FAILURE(InvokeFunctionAThunk());
579 :
580 : // Beware that this test will fail under debugging, as the
581 : // debugger by default swallows the exception.
582 : static const char kThreadName[] = "Profiler Test Thread";
583 E : SetNameInternal(kThreadName);
584 :
585 E : ASSERT_NO_FATAL_FAILURE(UnloadDll());
586 :
587 E : EXPECT_CALL(handler_, OnProcessStarted(_, ::GetCurrentProcessId(), _));
588 : EXPECT_CALL(handler_, OnProcessAttach(_,
589 : ::GetCurrentProcessId(),
590 : ::GetCurrentThreadId(),
591 : _))
592 E : .Times(testing::AnyNumber());
593 : EXPECT_CALL(handler_, OnInvocationBatch(_,
594 : ::GetCurrentProcessId(),
595 : ::GetCurrentThreadId(),
596 E : _, _));
597 : EXPECT_CALL(handler_, OnThreadName(_,
598 : ::GetCurrentProcessId(),
599 : ::GetCurrentThreadId(),
600 E : base::StringPiece(kThreadName)));
601 E : EXPECT_CALL(handler_, OnProcessEnded(_, ::GetCurrentProcessId()));
602 :
603 : // Replay the log.
604 E : ASSERT_NO_FATAL_FAILURE(ReplayLogs());
605 E : }
606 :
607 E : TEST_F(ProfilerTest, RecordsUsedSymbols) {
608 : // Spin up the RPC service.
609 E : ASSERT_NO_FATAL_FAILURE(StartService());
610 :
611 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
612 :
613 : // Add a dynamic symbol for the DllMain and a hypothetical bogus function.
614 E : base::StringPiece dll_main_caller_name("DllMainCaller");
615 : const uint8* dll_main_addr =
616 E : reinterpret_cast<const uint8*>(DllMainCaller(RETURN_ADDR, NULL));
617 E : size_t dll_main_len = DllMainCaller(RETURN_LENGTH, NULL);
618 : add_symbol_func_(dll_main_addr, dll_main_len,
619 E : dll_main_caller_name.data(), dll_main_caller_name.length());
620 :
621 : // Place bogus function immediately after the real DllMainCaller.
622 E : base::StringPiece func_bogus_name("BogusFunction");
623 : add_symbol_func_(dll_main_addr + dll_main_len, dll_main_len,
624 E : func_bogus_name.data(), func_bogus_name.length());
625 :
626 : // And place uncalled function immediately after the real DllMainCaller.
627 E : base::StringPiece func_uncalled_name("UncalledFunction");
628 : add_symbol_func_(dll_main_addr + dll_main_len * 2, dll_main_len,
629 E : func_uncalled_name.data(), func_uncalled_name.length());
630 :
631 : // Call through a "dynamic symbol" to the instrumented function.
632 E : ASSERT_NO_FATAL_FAILURE(DllMainCaller(CALL_THROUGH, NULL));
633 :
634 : // Now make as if BogusFunction moves to replace DllMainCaller's location.
635 E : move_symbol_func_(dll_main_addr + dll_main_len, dll_main_addr);
636 :
637 : // Call through a "dynamic symbol" to the instrumented function again.
638 : // This should result in a second dynamic symbol and entry in the trace file.
639 E : ASSERT_NO_FATAL_FAILURE(DllMainCaller(CALL_THROUGH, NULL));
640 :
641 E : ASSERT_NO_FATAL_FAILURE(UnloadDll());
642 :
643 E : EXPECT_CALL(handler_, OnProcessStarted(_, ::GetCurrentProcessId(), _));
644 : EXPECT_CALL(handler_, OnProcessAttach(_,
645 : ::GetCurrentProcessId(),
646 : ::GetCurrentThreadId(),
647 : _))
648 E : .Times(testing::AnyNumber());
649 :
650 : // Expect two invocation records batches with dynamic symbols.
651 : // TODO(siggi): Fixme: it's inefficient to alternate symbols and invocation
652 : // batches. Easiest fix is to pre-allocate invocation record in batches.
653 : EXPECT_CALL(handler_,
654 : OnInvocationBatch(
655 : _, ::GetCurrentProcessId(), ::GetCurrentThreadId(),
656 E : 1U, InvocationInfoHasCallerSymbol(1U, dll_main_len)));
657 : EXPECT_CALL(handler_,
658 : OnInvocationBatch(
659 : _, ::GetCurrentProcessId(), ::GetCurrentThreadId(),
660 E : 1U, InvocationInfoHasCallerSymbol(2U, dll_main_len)));
661 :
662 E : EXPECT_CALL(handler_, OnProcessEnded(_, ::GetCurrentProcessId()));
663 :
664 : // The DllMain and the Bogus functions should both make an appearance,
665 : // and nothing else.
666 : EXPECT_CALL(handler_,
667 E : OnDynamicSymbol(::GetCurrentProcessId(), 1, dll_main_caller_name));
668 : EXPECT_CALL(handler_,
669 E : OnDynamicSymbol(::GetCurrentProcessId(), _, func_bogus_name));
670 :
671 : // Replay the log.
672 E : ASSERT_NO_FATAL_FAILURE(ReplayLogs());
673 E : }
674 :
675 E : TEST_F(ProfilerTest, OnDynamicFunctionEntry) {
676 E : ASSERT_NO_FATAL_FAILURE(StartService());
677 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
678 :
679 : // Add a dynamic symbol for the DllMain and a hypothetical bogus function.
680 E : base::StringPiece dll_main_caller_name("DllMainCaller");
681 : const uint8* dll_main_addr =
682 E : reinterpret_cast<const uint8*>(DllMainCaller(RETURN_ADDR, NULL));
683 E : size_t dll_main_len = DllMainCaller(RETURN_LENGTH, NULL);
684 : add_symbol_func_(dll_main_addr, dll_main_len,
685 E : dll_main_caller_name.data(), dll_main_caller_name.length());
686 :
687 : // Call the V8 entry hook.
688 E : DllMainCaller(CALL_V8_ENTRY_HOOK, on_v8_function_entry_);
689 :
690 E : ASSERT_NO_FATAL_FAILURE(UnloadDll());
691 :
692 E : EXPECT_CALL(handler_, OnProcessStarted(_, ::GetCurrentProcessId(), _));
693 : EXPECT_CALL(handler_, OnProcessAttach(_,
694 : ::GetCurrentProcessId(),
695 : ::GetCurrentThreadId(),
696 : _))
697 E : .Times(testing::AnyNumber());
698 :
699 : // Expect two invocation records batches with dynamic symbols.
700 : EXPECT_CALL(handler_,
701 : OnInvocationBatch(
702 : _, ::GetCurrentProcessId(), ::GetCurrentThreadId(),
703 E : 1U, InvocationInfoHasFunctionSymbol(1U)));
704 :
705 E : EXPECT_CALL(handler_, OnProcessEnded(_, ::GetCurrentProcessId()));
706 :
707 : // The DllMain and the Bogus functions should both make an appearance,
708 : // and nothing else.
709 : EXPECT_CALL(handler_,
710 E : OnDynamicSymbol(::GetCurrentProcessId(), 1, dll_main_caller_name));
711 :
712 : // Replay the log.
713 E : ASSERT_NO_FATAL_FAILURE(ReplayLogs());
714 E : }
715 :
716 : namespace {
717 :
718 E : void WINAPI TlsAction(PVOID h, DWORD reason, PVOID reserved) {
719 : // We sometimes get stray threads winding up inside a unittest, and those
720 : // will generate a TLS callback. If we pass these through, flakiness will
721 : // result, so we pass only through calls on from base::Thread, which
722 : // we identify by the presence of a message loop.
723 E : if (base::MessageLoop::current() != NULL)
724 i : InvokeFunctionAThunk();
725 E : }
726 :
727 : } // namespace
728 :
729 E : TEST_F(ProfilerTest, ReleasesBufferOnThreadExit) {
730 : // Spin up the RPC service.
731 E : ASSERT_NO_FATAL_FAILURE(StartService());
732 :
733 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
734 :
735 E : tls_action = TlsAction;
736 :
737 : // Spinning 400 * 8 threads should exhaust the address
738 : // space if we're leaking a buffer for each thread.
739 E : for (size_t i = 0; i < 400; ++i) {
740 E : base::Thread thread1("one");
741 E : base::Thread thread2("two");
742 E : base::Thread thread3("three");
743 E : base::Thread thread4("four");
744 E : base::Thread thread5("five");
745 E : base::Thread thread6("six");
746 E : base::Thread thread7("seven");
747 E : base::Thread thread8("eight");
748 :
749 : base::Thread* threads[8] = { &thread1, &thread2, &thread3, &thread4,
750 E : &thread5, &thread6, &thread7, &thread8};
751 :
752 : // Start all the threads, and make them do some work.
753 E : for (size_t j = 0; j < arraysize(threads); ++j) {
754 E : base::Thread* thread = threads[j];
755 E : thread->Start();
756 : thread->message_loop()->PostTask(
757 E : FROM_HERE, base::Bind(InvokeFunctionAThunk));
758 E : }
759 :
760 : // This will implicitly wind down all the threads.
761 E : }
762 :
763 E : ASSERT_NO_FATAL_FAILURE(UnloadDll());
764 E : }
765 :
766 E : TEST_F(ProfilerTest, EntryHookPerformance) {
767 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
768 :
769 : // We grab the lowest value of 10 invocations to minimize scheduling
770 : // artifacts and such.
771 E : uint64 min_cycles = kuint64max;
772 E : for (size_t i = 0; i < 10; ++i) {
773 : // Invoke on the entry hook a hundred thousand times, and measure the
774 : // wall-clock time from start to finish.
775 E : uint64 start_cycles = __rdtsc();
776 E : for (size_t j = 0; j < 100000; ++j) {
777 E : InvokeFunctionAThunk();
778 E : }
779 E : uint64 end_cycles = __rdtsc();
780 :
781 E : if (min_cycles > (end_cycles - start_cycles))
782 E : min_cycles = end_cycles - start_cycles;
783 E : }
784 :
785 E : printf("100K entry hook invocations in [%llu] cycles.\n", min_cycles);
786 E : }
787 :
788 : } // namespace profiler
789 : } // namespace agent
|