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