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 ((it->instruction_pointer >= function_address) &&
 187         (it->instruction_pointer <
 188          (static_cast<const unsigned char*>(function_address) + function_size)))
 189       return it;
 190   }
 191   return sample.end();
 192 }
 193
 194 // Formats a sample into a string that can be output for test diagnostics.
 195 std::string FormatSampleForDiagnosticOutput(
 196     const Sample& sample,
 197     const std::vector<Module>& modules) {
 198   std::string output;
 199   for (const Frame& frame: sample) {
 200     output += StringPrintf(
 201         "0x%p %s\n", frame.instruction_pointer,
 202         modules[frame.module_index].filename.AsUTF8Unsafe().c_str());
 203   }
 204   return output;
 205 }
 206
 207 // Returns a duration that is longer than the test timeout. We would use
 208 // TimeDelta::Max() but https://crbug.com/465948.
 209 TimeDelta AVeryLongTimeDelta() { return TimeDelta::FromDays(1); }
 210
 211 }  // namespace
 212
 213 // Checks that the basic expected information is present in a sampled call stack
 214 // profile.
 215 #if defined(STACK_SAMPLING_PROFILER_SUPPORTED)
 216 #define MAYBE_Basic Basic
 217 #else
 218 #define MAYBE_Basic DISABLED_Basic
 219 #endif
 220 TEST(StackSamplingProfilerTest, MAYBE_Basic) {
 221   SamplingParams params;
 222   params.sampling_interval = TimeDelta::FromMilliseconds(0);
 223   params.samples_per_burst = 1;
 224
 225   std::vector<CallStackProfile> profiles;
 226   CaptureProfiles(params, AVeryLongTimeDelta(), &profiles);
 227
 228   // Check that the profile and samples sizes are correct, and the module
 229   // indices are in range.
 230   ASSERT_EQ(1u, profiles.size());
 231   const CallStackProfile& profile = profiles[0];
 232   ASSERT_EQ(1u, profile.samples.size());
 233   EXPECT_EQ(params.sampling_interval, profile.sampling_period);
 234   const Sample& sample = profile.samples[0];
 235   for (const auto& frame : sample) {
 236     ASSERT_GE(frame.module_index, 0u);
 237     ASSERT_LT(frame.module_index, profile.modules.size());
 238   }
 239
 240   // Check that the stack contains a frame for
 241   // TargetThread::SignalAndWaitUntilSignaled() and that the frame has this
 242   // executable's module.
 243   //
 244   // Since we don't have a good way to know the function size, use 100 bytes as
 245   // a reasonable window to locate the instruction pointer.
 246   Sample::const_iterator loc = FindFirstFrameWithinFunction(
 247       sample,
 248       reinterpret_cast<const void*>(&TargetThread::SignalAndWaitUntilSignaled),
 249       100);
 250   ASSERT_TRUE(loc != sample.end())
 251       << "Function at "
 252       << MaybeFixupFunctionAddressForILT(
 253           reinterpret_cast<const void*>(
 254               &TargetThread::SignalAndWaitUntilSignaled))
 255       << " was not found in stack:\n"
 256       << FormatSampleForDiagnosticOutput(sample, profile.modules);
 257   FilePath executable_path;
 258   EXPECT_TRUE(PathService::Get(FILE_EXE, &executable_path));
 259   EXPECT_EQ(executable_path, profile.modules[loc->module_index].filename);
 260 }
 261
 262 // Checks that the fire-and-forget interface works.
 263 #if defined(STACK_SAMPLING_PROFILER_SUPPORTED)
 264 #define MAYBE_StartAndRunAsync StartAndRunAsync
 265 #else
 266 #define MAYBE_StartAndRunAsync DISABLED_StartAndRunAsync
 267 #endif
 268 TEST(StackSamplingProfilerTest, MAYBE_StartAndRunAsync) {
 269   // StartAndRunAsync requires the caller to have a message loop.
 270   MessageLoop message_loop;
 271
 272   SamplingParams params;
 273   params.samples_per_burst = 1;
 274
 275   CallStackProfiles profiles;
 276   WithTargetThread([&params, &profiles](PlatformThreadId target_thread_id) {
 277     WaitableEvent sampling_thread_completed(false, false);
 278     const StackSamplingProfiler::CompletedCallback callback =
 279         Bind(&SaveProfilesAndSignalEvent, Unretained(&profiles),
 280              Unretained(&sampling_thread_completed));
 281     StackSamplingProfiler::StartAndRunAsync(target_thread_id, params, callback);
 282     RunLoop().RunUntilIdle();
 283     sampling_thread_completed.Wait();
 284   });
 285
 286   ASSERT_EQ(1u, profiles.size());
 287 }
 288
 289 // Checks that the expected number of profiles and samples are present in the
 290 // call stack profiles produced.
 291 #if defined(STACK_SAMPLING_PROFILER_SUPPORTED)
 292 #define MAYBE_MultipleProfilesAndSamples MultipleProfilesAndSamples
 293 #else
 294 #define MAYBE_MultipleProfilesAndSamples DISABLED_MultipleProfilesAndSamples
 295 #endif
 296 TEST(StackSamplingProfilerTest, MAYBE_MultipleProfilesAndSamples) {
 297   SamplingParams params;
 298   params.burst_interval = params.sampling_interval =
 299       TimeDelta::FromMilliseconds(0);
 300   params.bursts = 2;
 301   params.samples_per_burst = 3;
 302
 303   std::vector<CallStackProfile> profiles;
 304   CaptureProfiles(params, AVeryLongTimeDelta(), &profiles);
 305
 306   ASSERT_EQ(2u, profiles.size());
 307   EXPECT_EQ(3u, profiles[0].samples.size());
 308   EXPECT_EQ(3u, profiles[1].samples.size());
 309 }
 310
 311 // Checks that no call stack profiles are captured if the profiling is stopped
 312 // during the initial delay.
 313 #if defined(STACK_SAMPLING_PROFILER_SUPPORTED)
 314 #define MAYBE_StopDuringInitialDelay StopDuringInitialDelay
 315 #else
 316 #define MAYBE_StopDuringInitialDelay DISABLED_StopDuringInitialDelay
 317 #endif
 318 TEST(StackSamplingProfilerTest, MAYBE_StopDuringInitialDelay) {
 319   SamplingParams params;
 320   params.initial_delay = TimeDelta::FromSeconds(60);
 321
 322   std::vector<CallStackProfile> profiles;
 323   CaptureProfiles(params, TimeDelta::FromMilliseconds(0), &profiles);
 324
 325   EXPECT_TRUE(profiles.empty());
 326 }
 327
 328 // Checks that the single completed call stack profile is captured if the
 329 // profiling is stopped between bursts.
 330 #if defined(STACK_SAMPLING_PROFILER_SUPPORTED)
 331 #define MAYBE_StopDuringInterBurstInterval StopDuringInterBurstInterval
 332 #else
 333 #define MAYBE_StopDuringInterBurstInterval DISABLED_StopDuringInterBurstInterval
 334 #endif
 335 TEST(StackSamplingProfilerTest, MAYBE_StopDuringInterBurstInterval) {
 336   SamplingParams params;
 337   params.sampling_interval = TimeDelta::FromMilliseconds(0);
 338   params.burst_interval = TimeDelta::FromSeconds(60);
 339   params.bursts = 2;
 340   params.samples_per_burst = 1;
 341
 342   std::vector<CallStackProfile> profiles;
 343   CaptureProfiles(params, TimeDelta::FromMilliseconds(50), &profiles);
 344
 345   ASSERT_EQ(1u, profiles.size());
 346   EXPECT_EQ(1u, profiles[0].samples.size());
 347 }
 348
 349 // Checks that only completed call stack profiles are captured.
 350 #if defined(STACK_SAMPLING_PROFILER_SUPPORTED)
 351 #define MAYBE_StopDuringInterSampleInterval StopDuringInterSampleInterval
 352 #else
 353 #define MAYBE_StopDuringInterSampleInterval \
 354   DISABLED_StopDuringInterSampleInterval
 355 #endif
 356 TEST(StackSamplingProfilerTest, MAYBE_StopDuringInterSampleInterval) {
 357   SamplingParams params;
 358   params.sampling_interval = TimeDelta::FromSeconds(60);
 359   params.samples_per_burst = 2;
 360
 361   std::vector<CallStackProfile> profiles;
 362   CaptureProfiles(params, TimeDelta::FromMilliseconds(50), &profiles);
 363
 364   EXPECT_TRUE(profiles.empty());
 365 }
 366
 367 // Checks that we can destroy the profiler while profiling.
 368 #if defined(STACK_SAMPLING_PROFILER_SUPPORTED)
 369 #define MAYBE_DestroyProfilerWhileProfiling DestroyProfilerWhileProfiling
 370 #else
 371 #define MAYBE_DestroyProfilerWhileProfiling \
 372   DISABLED_DestroyProfilerWhileProfiling
 373 #endif
 374 TEST(StackSamplingProfilerTest, MAYBE_DestroyProfilerWhileProfiling) {
 375   SamplingParams params;
 376   params.sampling_interval = TimeDelta::FromMilliseconds(10);
 377
 378   CallStackProfiles profiles;
 379   WithTargetThread([&params, &profiles](PlatformThreadId target_thread_id) {
 380     scoped_ptr<StackSamplingProfiler> profiler;
 381     profiler.reset(new StackSamplingProfiler(
 382         target_thread_id, params, Bind(&SaveProfiles, Unretained(&profiles))));
 383     profiler->Start();
 384     profiler.reset();
 385
 386     // Wait longer than a sample interval to catch any use-after-free actions by
 387     // the profiler thread.
 388     PlatformThread::Sleep(TimeDelta::FromMilliseconds(50));
 389   });
 390 }
 391
 392 // Checks that the same profiler may be run multiple times.
 393 #if defined(STACK_SAMPLING_PROFILER_SUPPORTED)
 394 #define MAYBE_CanRunMultipleTimes CanRunMultipleTimes
 395 #else
 396 #define MAYBE_CanRunMultipleTimes DISABLED_CanRunMultipleTimes
 397 #endif
 398 TEST(StackSamplingProfilerTest, MAYBE_CanRunMultipleTimes) {
 399   SamplingParams params;
 400   params.sampling_interval = TimeDelta::FromMilliseconds(0);
 401   params.samples_per_burst = 1;
 402
 403   std::vector<CallStackProfile> profiles;
 404   CaptureProfiles(params, AVeryLongTimeDelta(), &profiles);
 405   ASSERT_EQ(1u, profiles.size());
 406
 407   profiles.clear();
 408   CaptureProfiles(params, AVeryLongTimeDelta(), &profiles);
 409   ASSERT_EQ(1u, profiles.size());
 410 }
 411
 412 // Checks that requests to start profiling while another profile is taking place
 413 // are ignored.
 414 #if defined(STACK_SAMPLING_PROFILER_SUPPORTED)
 415 #define MAYBE_ConcurrentProfiling ConcurrentProfiling
 416 #else
 417 #define MAYBE_ConcurrentProfiling DISABLED_ConcurrentProfiling
 418 #endif
 419 TEST(StackSamplingProfilerTest, MAYBE_ConcurrentProfiling) {
 420   WithTargetThread([](PlatformThreadId target_thread_id) {
 421     SamplingParams params[2];
 422     params[0].initial_delay = TimeDelta::FromMilliseconds(10);
 423     params[0].sampling_interval = TimeDelta::FromMilliseconds(0);
 424     params[0].samples_per_burst = 1;
 425
 426     params[1].sampling_interval = TimeDelta::FromMilliseconds(0);
 427     params[1].samples_per_burst = 1;
 428
 429     CallStackProfiles profiles[2];
 430     ScopedVector<WaitableEvent> sampling_completed;
 431     ScopedVector<StackSamplingProfiler> profiler;
 432     for (int i = 0; i < 2; ++i) {
 433       sampling_completed.push_back(new WaitableEvent(false, false));
 434       const StackSamplingProfiler::CompletedCallback callback =
 435           Bind(&SaveProfilesAndSignalEvent, Unretained(&profiles[i]),
 436                Unretained(sampling_completed[i]));
 437       profiler.push_back(
 438           new StackSamplingProfiler(target_thread_id, params[i], callback));
 439     }
 440
 441     profiler[0]->Start();
 442     profiler[1]->Start();
 443
 444     // Wait for the first profiler to finish.
 445     sampling_completed[0]->Wait();
 446     EXPECT_EQ(1u, profiles[0].size());
 447
 448     // Give the second profiler a chance to run and observe that it hasn't.
 449     EXPECT_FALSE(
 450         sampling_completed[1]->TimedWait(TimeDelta::FromMilliseconds(25)));
 451
 452     // Start the second profiler again and it should run.
 453     profiler[1]->Start();
 454     sampling_completed[1]->Wait();
 455     EXPECT_EQ(1u, profiles[1].size());
 456   });
 457 }
 458
 459 }  // namespace base