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/message_loop.h"
24 : #include "base/files/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 : typedef void (__cdecl *AddDynamicSymbolFunc)(
42 : const void* address, size_t length, const char* name, size_t name_len);
43 : typedef void (__cdecl *MoveDynamicSymbolFunc)(
44 : const void* old_address, const void* new_address);
45 : typedef void (__cdecl *OnDynamicFunctionEntryFunc)(
46 : uintptr_t function, uintptr_t return_addr_location);
47 :
48 : // We register a TLS callback to test TLS thread notifications.
49 : extern PIMAGE_TLS_CALLBACK profiler_test_tls_callback_entry;
50 : void WINAPI ProfilerTestTlsCallback(PVOID h, DWORD reason, PVOID reserved);
51 :
52 : // Force the linker to include the TLS entry.
53 : #pragma comment(linker, "/INCLUDE:__tls_used")
54 : #pragma comment(linker, "/INCLUDE:_profiler_test_tls_callback_entry")
55 :
56 : #pragma data_seg(push, old_seg)
57 : // Use a typical possible name in the .CRT$XL? list of segments.
58 : #pragma data_seg(".CRT$XLB")
59 : PIMAGE_TLS_CALLBACK profiler_test_tls_callback_entry =
60 : &ProfilerTestTlsCallback;
61 : #pragma data_seg(pop, old_seg)
62 :
63 : PIMAGE_TLS_CALLBACK tls_action = NULL;
64 :
65 E : void WINAPI ProfilerTestTlsCallback(PVOID h, DWORD reason, PVOID reserved) {
66 E : if (tls_action)
67 E : tls_action(h, reason, reserved);
68 E : }
69 :
70 : } // extern "C"
71 :
72 : namespace agent {
73 : namespace profiler {
74 :
75 : namespace {
76 :
77 : using agent::common::GetProcessModules;
78 : using agent::common::ModuleVector;
79 : using file_util::FileEnumerator;
80 : using testing::_;
81 : using testing::AllOf;
82 : using testing::Return;
83 : using testing::StrictMockParseEventHandler;
84 : using trace::service::RpcServiceInstanceManager;
85 : using trace::service::TraceFileWriterFactory;
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 : file_util::FileEnumerator enumerator(temp_dir_.path(),
214 : false,
215 E : 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 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
519 :
520 : // Record the module load twice.
521 E : EXPECT_NO_FATAL_FAILURE(InvokeDllMainThunk(self_module));
522 E : EXPECT_NO_FATAL_FAILURE(InvokeDllMainThunk(self_module));
523 :
524 : // And invoke Function A twice.
525 E : ASSERT_NO_FATAL_FAILURE(InvokeFunctionAThunk());
526 E : ASSERT_NO_FATAL_FAILURE(InvokeFunctionAThunk());
527 :
528 : // Get the module list prior to unloading the profile DLL.
529 E : ModuleVector modules;
530 E : GetProcessModules(&modules);
531 :
532 E : ASSERT_NO_FATAL_FAILURE(UnloadDll());
533 :
534 E : EXPECT_CALL(handler_, OnProcessStarted(_, ::GetCurrentProcessId(), _));
535 :
536 : // We should only have one event per module,
537 : // despite the double DllMain invocation.
538 E : for (size_t i = 0; i < modules.size(); ++i) {
539 : EXPECT_CALL(handler_, OnProcessAttach(_,
540 : ::GetCurrentProcessId(),
541 : ::GetCurrentThreadId(),
542 E : ModuleAtAddress(modules[i])));
543 E : }
544 :
545 : // TODO(siggi): Match harder here.
546 : // We should only have two distinct invocation records,
547 : // despite calling each function twice.
548 : EXPECT_CALL(handler_, OnInvocationBatch(_,
549 : ::GetCurrentProcessId(),
550 : ::GetCurrentThreadId(),
551 : 2,
552 E : _));
553 E : EXPECT_CALL(handler_, OnProcessEnded(_, ::GetCurrentProcessId()));
554 :
555 : // Replay the log.
556 E : ASSERT_NO_FATAL_FAILURE(ReplayLogs());
557 E : }
558 :
559 E : TEST_F(ProfilerTest, RecordsThreadName) {
560 E : if (::IsDebuggerPresent()) {
561 i : LOG(WARNING) << "This test fails under debugging.";
562 i : return;
563 : }
564 :
565 : // Spin up the RPC service.
566 E : ASSERT_NO_FATAL_FAILURE(StartService());
567 :
568 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
569 :
570 : // And invoke a function to get things initialized.
571 E : ASSERT_NO_FATAL_FAILURE(InvokeFunctionAThunk());
572 :
573 : // Beware that this test will fail under debugging, as the
574 : // debugger by default swallows the exception.
575 : static const char kThreadName[] = "Profiler Test Thread";
576 E : SetNameInternal(kThreadName);
577 :
578 E : ASSERT_NO_FATAL_FAILURE(UnloadDll());
579 :
580 E : EXPECT_CALL(handler_, OnProcessStarted(_, ::GetCurrentProcessId(), _));
581 : EXPECT_CALL(handler_, OnProcessAttach(_,
582 : ::GetCurrentProcessId(),
583 : ::GetCurrentThreadId(),
584 : _))
585 E : .Times(testing::AnyNumber());
586 : EXPECT_CALL(handler_, OnInvocationBatch(_,
587 : ::GetCurrentProcessId(),
588 : ::GetCurrentThreadId(),
589 E : _ ,_));
590 : EXPECT_CALL(handler_, OnThreadName(_,
591 : ::GetCurrentProcessId(),
592 : ::GetCurrentThreadId(),
593 E : base::StringPiece(kThreadName)));
594 E : EXPECT_CALL(handler_, OnProcessEnded(_, ::GetCurrentProcessId()));
595 :
596 : // Replay the log.
597 E : ASSERT_NO_FATAL_FAILURE(ReplayLogs());
598 E : }
599 :
600 E : TEST_F(ProfilerTest, RecordsUsedSymbols) {
601 : // Spin up the RPC service.
602 E : ASSERT_NO_FATAL_FAILURE(StartService());
603 :
604 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
605 :
606 : // Add a dynamic symbol for the DllMain and a hypothetical bogus function.
607 E : base::StringPiece dll_main_caller_name("DllMainCaller");
608 : const uint8* dll_main_addr =
609 E : reinterpret_cast<const uint8*>(DllMainCaller(RETURN_ADDR, NULL));
610 E : size_t dll_main_len = DllMainCaller(RETURN_LENGTH, NULL);
611 : add_symbol_func_(dll_main_addr, dll_main_len,
612 E : dll_main_caller_name.data(), dll_main_caller_name.length());
613 :
614 : // Place bogus function immediately after the real DllMainCaller.
615 E : base::StringPiece func_bogus_name("BogusFunction");
616 : add_symbol_func_(dll_main_addr + dll_main_len, dll_main_len,
617 E : func_bogus_name.data(), func_bogus_name.length());
618 :
619 : // And place uncalled function immediately after the real DllMainCaller.
620 E : base::StringPiece func_uncalled_name("UncalledFunction");
621 : add_symbol_func_(dll_main_addr + dll_main_len * 2, dll_main_len,
622 E : func_uncalled_name.data(), func_uncalled_name.length());
623 :
624 : // Call through a "dynamic symbol" to the instrumented function.
625 E : ASSERT_NO_FATAL_FAILURE(DllMainCaller(CALL_THROUGH, NULL));
626 :
627 : // Now make as if BogusFunction moves to replace DllMainCaller's location.
628 E : move_symbol_func_(dll_main_addr + dll_main_len, dll_main_addr);
629 :
630 : // Call through a "dynamic symbol" to the instrumented function again.
631 : // This should result in a second dynamic symbol and entry in the trace file.
632 E : ASSERT_NO_FATAL_FAILURE(DllMainCaller(CALL_THROUGH, NULL));
633 :
634 E : ASSERT_NO_FATAL_FAILURE(UnloadDll());
635 :
636 E : EXPECT_CALL(handler_, OnProcessStarted(_, ::GetCurrentProcessId(), _));
637 : EXPECT_CALL(handler_, OnProcessAttach(_,
638 : ::GetCurrentProcessId(),
639 : ::GetCurrentThreadId(),
640 : _))
641 E : .Times(testing::AnyNumber());
642 :
643 : // Expect two invocation records batches with dynamic symbols.
644 : // TODO(siggi): Fixme: it's inefficient to alternate symbols and invocation
645 : // batches. Easiest fix is to pre-allocate invocation record in batches.
646 : EXPECT_CALL(handler_,
647 : OnInvocationBatch(
648 : _, ::GetCurrentProcessId(), ::GetCurrentThreadId(),
649 E : 1U, InvocationInfoHasCallerSymbol(1U, dll_main_len)));
650 : EXPECT_CALL(handler_,
651 : OnInvocationBatch(
652 : _, ::GetCurrentProcessId(), ::GetCurrentThreadId(),
653 E : 1U, InvocationInfoHasCallerSymbol(2U, dll_main_len)));
654 :
655 E : EXPECT_CALL(handler_, OnProcessEnded(_, ::GetCurrentProcessId()));
656 :
657 : // The DllMain and the Bogus functions should both make an appearance,
658 : // and nothing else.
659 : EXPECT_CALL(handler_,
660 E : OnDynamicSymbol(::GetCurrentProcessId(), 1, dll_main_caller_name));
661 : EXPECT_CALL(handler_,
662 E : OnDynamicSymbol(::GetCurrentProcessId(), _, func_bogus_name));
663 :
664 : // Replay the log.
665 E : ASSERT_NO_FATAL_FAILURE(ReplayLogs());
666 E : }
667 :
668 E : TEST_F(ProfilerTest, OnDynamicFunctionEntry) {
669 E : ASSERT_NO_FATAL_FAILURE(StartService());
670 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
671 :
672 : // Add a dynamic symbol for the DllMain and a hypothetical bogus function.
673 E : base::StringPiece dll_main_caller_name("DllMainCaller");
674 : const uint8* dll_main_addr =
675 E : reinterpret_cast<const uint8*>(DllMainCaller(RETURN_ADDR, NULL));
676 E : size_t dll_main_len = DllMainCaller(RETURN_LENGTH, NULL);
677 : add_symbol_func_(dll_main_addr, dll_main_len,
678 E : dll_main_caller_name.data(), dll_main_caller_name.length());
679 :
680 : // Call the V8 entry hook.
681 E : DllMainCaller(CALL_V8_ENTRY_HOOK, on_v8_function_entry_);
682 :
683 E : ASSERT_NO_FATAL_FAILURE(UnloadDll());
684 :
685 E : EXPECT_CALL(handler_, OnProcessStarted(_, ::GetCurrentProcessId(), _));
686 : EXPECT_CALL(handler_, OnProcessAttach(_,
687 : ::GetCurrentProcessId(),
688 : ::GetCurrentThreadId(),
689 : _))
690 E : .Times(testing::AnyNumber());
691 :
692 : // Expect two invocation records batches with dynamic symbols.
693 : EXPECT_CALL(handler_,
694 : OnInvocationBatch(
695 : _, ::GetCurrentProcessId(), ::GetCurrentThreadId(),
696 E : 1U, InvocationInfoHasFunctionSymbol(1U)));
697 :
698 E : EXPECT_CALL(handler_, OnProcessEnded(_, ::GetCurrentProcessId()));
699 :
700 : // The DllMain and the Bogus functions should both make an appearance,
701 : // and nothing else.
702 : EXPECT_CALL(handler_,
703 E : OnDynamicSymbol(::GetCurrentProcessId(), 1, dll_main_caller_name));
704 :
705 : // Replay the log.
706 E : ASSERT_NO_FATAL_FAILURE(ReplayLogs());
707 E : }
708 :
709 : namespace {
710 :
711 E : void WINAPI TlsAction(PVOID h, DWORD reason, PVOID reserved) {
712 E : InvokeFunctionAThunk();
713 E : }
714 :
715 : } // namespace
716 :
717 E : TEST_F(ProfilerTest, ReleasesBufferOnThreadExit) {
718 : // Spin up the RPC service.
719 E : ASSERT_NO_FATAL_FAILURE(StartService());
720 :
721 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
722 :
723 E : tls_action = TlsAction;
724 :
725 : // Spinning 400 * 8 threads should exhaust the address
726 : // space if we're leaking a buffer for each thread.
727 E : for (size_t i = 0; i < 400; ++i) {
728 E : base::Thread thread1("one");
729 E : base::Thread thread2("two");
730 E : base::Thread thread3("three");
731 E : base::Thread thread4("four");
732 E : base::Thread thread5("five");
733 E : base::Thread thread6("six");
734 E : base::Thread thread7("seven");
735 E : base::Thread thread8("eight");
736 :
737 E : base::Thread* threads[8] = { &thread1, &thread2, &thread3, &thread4,
738 E : &thread5, &thread6, &thread7, &thread8};
739 :
740 : // Start all the threads, and make them do some work.
741 E : for (size_t j = 0; j < arraysize(threads); ++j) {
742 E : base::Thread* thread = threads[j];
743 E : thread->Start();
744 : thread->message_loop()->PostTask(
745 E : FROM_HERE, base::Bind(InvokeFunctionAThunk));
746 E : }
747 :
748 : // This will implicitly wind down all the threads.
749 E : }
750 :
751 E : ASSERT_NO_FATAL_FAILURE(UnloadDll());
752 E : }
753 :
754 E : TEST_F(ProfilerTest, EntryHookPerformance) {
755 E : ASSERT_NO_FATAL_FAILURE(LoadDll());
756 :
757 : // We grab the lowest value of 10 invocations to minimize scheduling
758 : // artifacts and such.
759 E : uint64 min_cycles = kuint64max;
760 E : for (size_t i = 0; i < 10; ++i) {
761 : // Invoke on the entry hook a hundred thousand times, and measure the
762 : // wall-clock time from start to finish.
763 E : uint64 start_cycles = __rdtsc();
764 E : for (size_t j = 0; j < 100000; ++j) {
765 E : InvokeFunctionAThunk();
766 E : }
767 E : uint64 end_cycles = __rdtsc();
768 :
769 E : if (min_cycles > (end_cycles - start_cycles))
770 E : min_cycles = end_cycles - start_cycles;
771 E : }
772 :
773 E : printf("100K entry hook invocations in [%llu] cycles.\n", min_cycles);
774 E : }
775 :
776 : } // namespace profiler
777 : } // namespace agent
|