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