base/profiler/stack_sampling_profiler_unittest.cc

   1 // Copyright 2015 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "base/bind.h"
   6 #include "base/compiler_specific.h"
   7 #include "base/path_service.h"
   8 #include "base/profiler/stack_sampling_profiler.h"
   9 #include "base/strings/stringprintf.h"
  10 #include "base/synchronization/waitable_event.h"
  11 #include "base/threading/platform_thread.h"
  12 #include "base/time/time.h"
  13 #include "testing/gtest/include/gtest/gtest.h"
  14
  15 namespace base {
  16
  17 using SamplingParams = StackSamplingProfiler::SamplingParams;
  18 using Frame = StackSamplingProfiler::Frame;
  19 using Module = StackSamplingProfiler::Module;
  20 using Sample = StackSamplingProfiler::Sample;
  21 using CallStackProfile = StackSamplingProfiler::CallStackProfile;
  22 using CallStackProfiles = StackSamplingProfiler::CallStackProfiles;
  23
  24 namespace {
  25
  26 // A thread to target for profiling, whose stack is guaranteed to contain
  27 // SignalAndWaitUntilSignaled() when coordinated with the main thread.
  28 class TargetThread : public PlatformThread::Delegate {
  29  public:
  30   TargetThread();
  31
  32   // PlatformThread::Delegate:
  33   void ThreadMain() override;
  34
  35   // Waits for the thread to have started and be executing in
  36   // SignalAndWaitUntilSignaled().
  37   void WaitForThreadStart();
  38
  39   // Allows the thread to return from SignalAndWaitUntilSignaled() and finish
  40   // execution.
  41   void SignalThreadToFinish();
  42
  43   // This function is guaranteed to be executing between calls to
  44   // WaitForThreadStart() and SignalThreadToFinish(). This function is static so
  45   // that we can get a straightforward address for it in one of the tests below,
  46   // rather than dealing with the complexity of a member function pointer
  47   // representation.
  48   static void SignalAndWaitUntilSignaled(WaitableEvent* thread_started_event,
  49                                          WaitableEvent* finish_event);
  50
  51   PlatformThreadId id() const { return id_; }
  52
  53  private:
  54   WaitableEvent thread_started_event_;
  55   WaitableEvent finish_event_;
  56   PlatformThreadId id_;
  57
  58   DISALLOW_COPY_AND_ASSIGN(TargetThread);
  59 };
  60
  61 TargetThread::TargetThread()
  62     : thread_started_event_(false, false), finish_event_(false, false),
  63       id_(0) {}
  64
  65 void TargetThread::ThreadMain() {
  66   id_ = PlatformThread::CurrentId();
  67   SignalAndWaitUntilSignaled(&thread_started_event_, &finish_event_);
  68 }
  69
  70 void TargetThread::WaitForThreadStart() {
  71   thread_started_event_.Wait();
  72 }
  73
  74 void TargetThread::SignalThreadToFinish() {
  75   finish_event_.Signal();
  76 }
  77
  78 // static
  79 // Disable inlining for this function so that it gets its own stack frame.
  80 NOINLINE void TargetThread::SignalAndWaitUntilSignaled(
  81     WaitableEvent* thread_started_event,
  82     WaitableEvent* finish_event) {
  83   thread_started_event->Signal();
  84   volatile int x = 1;
  85   finish_event->Wait();
  86   x = 0;  // Prevent tail call to WaitableEvent::Wait().
  87   ALLOW_UNUSED_LOCAL(x);
  88 }
  89
  90 // Called on the profiler thread when complete, to collect profiles.
  91 void SaveProfiles(CallStackProfiles* profiles,
  92                   const CallStackProfiles& pending_profiles) {
  93   *profiles = pending_profiles;
  94 }
  95
  96 // Called on the profiler thread when complete. Collects profiles produced by
  97 // the profiler, and signals an event to allow the main thread to know that that
  98 // the profiler is done.
  99 void SaveProfilesAndSignalEvent(CallStackProfiles* profiles,
 100                                 WaitableEvent* event,
 101                                 const CallStackProfiles& pending_profiles) {
 102   *profiles = pending_profiles;
 103   event->Signal();
 104 }
 105
 106 // Executes the function with the target thread running and executing within
 107 // SignalAndWaitUntilSignaled(). Performs all necessary target thread startup
 108 // and shutdown work before and afterward.
 109 template <class Function>
 110 void WithTargetThread(Function function) {
 111   TargetThread target_thread;
 112   PlatformThreadHandle target_thread_handle;
 113   EXPECT_TRUE(PlatformThread::Create(0, &target_thread, &target_thread_handle));
 114
 115   target_thread.WaitForThreadStart();
 116
 117   function(target_thread.id());
 118
 119   target_thread.SignalThreadToFinish();
 120
 121   PlatformThread::Join(target_thread_handle);
 122 }
 123
 124 // Captures profiles as specified by |params| on the TargetThread, and returns
 125 // them in |profiles|. Waits up to |profiler_wait_time| for the profiler to
 126 // complete.
 127 void CaptureProfilesWithObjectCallback(const SamplingParams& params,
 128                                        CallStackProfiles* profiles,
 129                                        TimeDelta profiler_wait_time) {
 130   profiles->clear();
 131
 132   WithTargetThread([&params, profiles, profiler_wait_time](
 133       PlatformThreadId target_thread_id) {
 134     WaitableEvent sampling_thread_completed(true, false);
 135     const StackSamplingProfiler::CompletedCallback callback =
 136         Bind(&SaveProfilesAndSignalEvent, Unretained(profiles),
 137              Unretained(&sampling_thread_completed));
 138     StackSamplingProfiler profiler(target_thread_id, params, callback);
 139     profiler.Start();
 140     sampling_thread_completed.TimedWait(profiler_wait_time);
 141     profiler.Stop();
 142     sampling_thread_completed.Wait();
 143   });
 144 }
 145
 146 // Captures profiles as specified by |params| on the TargetThread, and returns
 147 // them in |profiles|. Uses the default callback rather than a per-object
 148 // callback.
 149 void CaptureProfilesWithDefaultCallback(const SamplingParams& params,
 150                                         CallStackProfiles* profiles) {
 151   profiles->clear();
 152
 153   WithTargetThread([&params, profiles](PlatformThreadId target_thread_id) {
 154     WaitableEvent sampling_thread_completed(false, false);
 155     StackSamplingProfiler::SetDefaultCompletedCallback(
 156         Bind(&SaveProfilesAndSignalEvent, Unretained(profiles),
 157              Unretained(&sampling_thread_completed)));
 158
 159     StackSamplingProfiler profiler(target_thread_id, params);
 160     profiler.Start();
 161     sampling_thread_completed.Wait();
 162
 163     StackSamplingProfiler::SetDefaultCompletedCallback(
 164         StackSamplingProfiler::CompletedCallback());
 165   });
 166 }
 167
 168 // Runs the profiler with |params| on the TargetThread, with no default or
 169 // per-object callback.
 170 void RunProfilerWithNoCallback(const SamplingParams& params,
 171                                TimeDelta profiler_wait_time) {
 172   WithTargetThread([&params, profiler_wait_time](
 173       PlatformThreadId target_thread_id) {
 174     StackSamplingProfiler profiler(target_thread_id, params);
 175     profiler.Start();
 176     // Since we don't specify a callback, we don't have a synchronization
 177     // mechanism with the sampling thread. Just sleep instead.
 178     PlatformThread::Sleep(profiler_wait_time);
 179     profiler.Stop();
 180   });
 181 }
 182
 183 // If this executable was linked with /INCREMENTAL (the default for non-official
 184 // debug and release builds on Windows), function addresses do not correspond to
 185 // function code itself, but instead to instructions in the Incremental Link
 186 // Table that jump to the functions. Checks for a jump instruction and if
 187 // present does a little decompilation to find the function's actual starting
 188 // address.
 189 const void* MaybeFixupFunctionAddressForILT(const void* function_address) {
 190 #if defined(_WIN64)
 191   const unsigned char* opcode =
 192       reinterpret_cast<const unsigned char*>(function_address);
 193   if (*opcode == 0xe9) {
 194     // This is a relative jump instruction. Assume we're in the ILT and compute
 195     // the function start address from the instruction offset.
 196     const int32* offset = reinterpret_cast<const int32*>(opcode + 1);
 197     const unsigned char* next_instruction =
 198         reinterpret_cast<const unsigned char*>(offset + 1);
 199     return next_instruction + *offset;
 200   }
 201 #endif
 202   return function_address;
 203 }
 204
 205 // Searches through the frames in |sample|, returning an iterator to the first
 206 // frame that has an instruction pointer between |function_address| and
 207 // |function_address| + |size|. Returns sample.end() if no such frames are
 208 // found.
 209 Sample::const_iterator FindFirstFrameWithinFunction(
 210     const Sample& sample,
 211     const void* function_address,
 212     int function_size) {
 213   function_address = MaybeFixupFunctionAddressForILT(function_address);
 214   for (auto it = sample.begin(); it != sample.end(); ++it) {
 215     if ((it->instruction_pointer >= function_address) &&
 216         (it->instruction_pointer <
 217          (static_cast<const unsigned char*>(function_address) + function_size)))
 218       return it;
 219   }
 220   return sample.end();
 221 }
 222
 223 // Formats a sample into a string that can be output for test diagnostics.
 224 std::string FormatSampleForDiagnosticOutput(
 225     const Sample& sample,
 226     const std::vector<Module>& modules) {
 227   std::string output;
 228   for (const Frame& frame: sample) {
 229     output += StringPrintf(
 230         "0x%p %s\n", frame.instruction_pointer,
 231         modules[frame.module_index].filename.AsUTF8Unsafe().c_str());
 232   }
 233   return output;
 234 }
 235
 236 // Returns a duration that is longer than the test timeout. We would use
 237 // TimeDelta::Max() but https://crbug.com/465948.
 238 TimeDelta AVeryLongTimeDelta() { return TimeDelta::FromDays(1); }
 239
 240 }  // namespace
 241
 242
 243 // The tests below are enabled for Win x64 only, pending implementation of the
 244 // tested functionality on other platforms/architectures.
 245
 246 // Checks that the basic expected information is present in a sampled call stack
 247 // profile.
 248 #if defined(_WIN64)
 249 #define MAYBE_Basic Basic
 250 #else
 251 #define MAYBE_Basic DISABLED_Basic
 252 #endif
 253 TEST(StackSamplingProfilerTest, MAYBE_Basic) {
 254   SamplingParams params;
 255   params.sampling_interval = TimeDelta::FromMilliseconds(0);
 256   params.samples_per_burst = 1;
 257   params.user_data = 100;
 258   params.preserve_sample_ordering = true;
 259
 260   std::vector<CallStackProfile> profiles;
 261   CaptureProfilesWithObjectCallback(params, &profiles, AVeryLongTimeDelta());
 262
 263   // Check that the profile and samples sizes are correct, and the module
 264   // indices are in range.
 265   ASSERT_EQ(1u, profiles.size());
 266   const CallStackProfile& profile = profiles[0];
 267   ASSERT_EQ(1u, profile.samples.size());
 268   EXPECT_EQ(params.sampling_interval, profile.sampling_period);
 269   const Sample& sample = profile.samples[0];
 270   for (const auto& frame : sample) {
 271     ASSERT_GE(frame.module_index, 0u);
 272     ASSERT_LT(frame.module_index, profile.modules.size());
 273   }
 274   EXPECT_EQ(100u, profile.user_data);
 275   EXPECT_EQ(true, profile.preserve_sample_ordering);
 276
 277   // Check that the stack contains a frame for
 278   // TargetThread::SignalAndWaitUntilSignaled() and that the frame has this
 279   // executable's module.
 280   //
 281   // Since we don't have a good way to know the function size, use 100 bytes as
 282   // a reasonable window to locate the instruction pointer.
 283   Sample::const_iterator loc = FindFirstFrameWithinFunction(
 284       sample,
 285       reinterpret_cast<const void*>(&TargetThread::SignalAndWaitUntilSignaled),
 286       100);
 287   ASSERT_TRUE(loc != sample.end())
 288       << "Function at "
 289       << MaybeFixupFunctionAddressForILT(
 290           reinterpret_cast<const void*>(
 291               &TargetThread::SignalAndWaitUntilSignaled))
 292       << " was not found in stack:\n"
 293       << FormatSampleForDiagnosticOutput(sample, profile.modules);
 294   FilePath executable_path;
 295   EXPECT_TRUE(PathService::Get(FILE_EXE, &executable_path));
 296   EXPECT_EQ(executable_path, profile.modules[loc->module_index].filename);
 297 }
 298
 299 // Checks that the expected number of profiles and samples are present in the
 300 // call stack profiles produced.
 301 #if defined(_WIN64)
 302 #define MAYBE_MultipleProfilesAndSamples MultipleProfilesAndSamples
 303 #else
 304 #define MAYBE_MultipleProfilesAndSamples DISABLED_MultipleProfilesAndSamples
 305 #endif
 306 TEST(StackSamplingProfilerTest, MAYBE_MultipleProfilesAndSamples) {
 307   SamplingParams params;
 308   params.burst_interval = params.sampling_interval =
 309       TimeDelta::FromMilliseconds(0);
 310   params.bursts = 2;
 311   params.samples_per_burst = 3;
 312
 313   std::vector<CallStackProfile> profiles;
 314   CaptureProfilesWithObjectCallback(params, &profiles, AVeryLongTimeDelta());
 315
 316   ASSERT_EQ(2u, profiles.size());
 317   EXPECT_EQ(3u, profiles[0].samples.size());
 318   EXPECT_EQ(3u, profiles[1].samples.size());
 319 }
 320
 321 // Checks that no call stack profiles are captured if the profiling is stopped
 322 // during the initial delay.
 323 #if defined(_WIN64)
 324 #define MAYBE_StopDuringInitialDelay StopDuringInitialDelay
 325 #else
 326 #define MAYBE_StopDuringInitialDelay DISABLED_StopDuringInitialDelay
 327 #endif
 328 TEST(StackSamplingProfilerTest, MAYBE_StopDuringInitialDelay) {
 329   SamplingParams params;
 330   params.initial_delay = TimeDelta::FromSeconds(60);
 331
 332   std::vector<CallStackProfile> profiles;
 333   CaptureProfilesWithObjectCallback(params, &profiles,
 334                                     TimeDelta::FromMilliseconds(0));
 335
 336   EXPECT_TRUE(profiles.empty());
 337 }
 338
 339 // Checks that the single completed call stack profile is captured if the
 340 // profiling is stopped between bursts.
 341 #if defined(_WIN64)
 342 #define MAYBE_StopDuringInterBurstInterval StopDuringInterBurstInterval
 343 #else
 344 #define MAYBE_StopDuringInterBurstInterval DISABLED_StopDuringInterBurstInterval
 345 #endif
 346 TEST(StackSamplingProfilerTest, MAYBE_StopDuringInterBurstInterval) {
 347   SamplingParams params;
 348   params.sampling_interval = TimeDelta::FromMilliseconds(0);
 349   params.burst_interval = TimeDelta::FromSeconds(60);
 350   params.bursts = 2;
 351   params.samples_per_burst = 1;
 352
 353   std::vector<CallStackProfile> profiles;
 354   CaptureProfilesWithObjectCallback(params, &profiles,
 355                                     TimeDelta::FromMilliseconds(50));
 356
 357   ASSERT_EQ(1u, profiles.size());
 358   EXPECT_EQ(1u, profiles[0].samples.size());
 359 }
 360
 361 // Checks that only completed call stack profiles are captured.
 362 #if defined(_WIN64)
 363 #define MAYBE_StopDuringInterSampleInterval StopDuringInterSampleInterval
 364 #else
 365 #define MAYBE_StopDuringInterSampleInterval \
 366   DISABLED_StopDuringInterSampleInterval
 367 #endif
 368 TEST(StackSamplingProfilerTest, MAYBE_StopDuringInterSampleInterval) {
 369   SamplingParams params;
 370   params.sampling_interval = TimeDelta::FromSeconds(60);
 371   params.samples_per_burst = 2;
 372
 373   std::vector<CallStackProfile> profiles;
 374   CaptureProfilesWithObjectCallback(params, &profiles,
 375                                     TimeDelta::FromMilliseconds(50));
 376
 377   EXPECT_TRUE(profiles.empty());
 378 }
 379
 380 // Checks that profiles are captured via the default completed callback.
 381 #if defined(_WIN64)
 382 #define MAYBE_DefaultCallback DefaultCallback
 383 #else
 384 #define MAYBE_DefaultCallback DISABLED_DefaultCallback
 385 #endif
 386 TEST(StackSamplingProfilerTest, MAYBE_DefaultCallback) {
 387   SamplingParams params;
 388   params.samples_per_burst = 1;
 389
 390   CallStackProfiles profiles;
 391   CaptureProfilesWithDefaultCallback(params, &profiles);
 392
 393   EXPECT_EQ(1u, profiles.size());
 394   EXPECT_EQ(1u, profiles[0].samples.size());
 395 }
 396
 397 // Checks that profiles are queued until a default callback is set, then
 398 // delivered.
 399 #if defined(_WIN64)
 400 #define MAYBE_ProfilesQueuedWithNoCallback ProfilesQueuedWithNoCallback
 401 #else
 402 #define MAYBE_ProfilesQueuedWithNoCallback DISABLED_ProfilesQueuedWithNoCallback
 403 #endif
 404 TEST(StackSamplingProfilerTest, MAYBE_ProfilesQueuedWithNoCallback) {
 405   SamplingParams params;
 406   params.samples_per_burst = 1;
 407
 408   RunProfilerWithNoCallback(params, TimeDelta::FromMilliseconds(50));
 409
 410   CallStackProfiles profiles;
 411   // This should immediately call SaveProfiles on this thread.
 412   StackSamplingProfiler::SetDefaultCompletedCallback(
 413       Bind(&SaveProfiles, Unretained(&profiles)));
 414   EXPECT_EQ(1u, profiles.size());
 415   EXPECT_EQ(1u, profiles[0].samples.size());
 416   StackSamplingProfiler::SetDefaultCompletedCallback(
 417       StackSamplingProfiler::CompletedCallback());
 418 }
 419
 420 // Checks that we can destroy the profiler while profiling.
 421 #if defined(_WIN64)
 422 #define MAYBE_DestroyProfilerWhileProfiling DestroyProfilerWhileProfiling
 423 #else
 424 #define MAYBE_DestroyProfilerWhileProfiling \
 425   DISABLED_DestroyProfilerWhileProfiling
 426 #endif
 427 TEST(StackSamplingProfilerTest, MAYBE_DestroyProfilerWhileProfiling) {
 428   SamplingParams params;
 429   params.sampling_interval = TimeDelta::FromMilliseconds(10);
 430
 431   CallStackProfiles profiles;
 432   WithTargetThread([&params, &profiles](PlatformThreadId target_thread_id) {
 433     scoped_ptr<StackSamplingProfiler> profiler;
 434     profiler.reset(new StackSamplingProfiler(
 435         target_thread_id, params, Bind(&SaveProfiles, Unretained(&profiles))));
 436     profiler->Start();
 437     profiler.reset();
 438
 439     // Wait longer than a sample interval to catch any use-after-free actions by
 440     // the profiler thread.
 441     PlatformThread::Sleep(TimeDelta::FromMilliseconds(50));
 442   });
 443 }
 444
 445 }  // namespace base