src/kudu/util/spinlock_profiling.cc

// Licensed to the Apache Software Foundation (ASF) under one
// or more contributor license agreements.  See the NOTICE file
// distributed with this work for additional information
// regarding copyright ownership.  The ASF licenses this file
// to you under the Apache License, Version 2.0 (the
// "License"); you may not use this file except in compliance
// with the License.  You may obtain a copy of the License at
//
//   http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing,
// software distributed under the License is distributed on an
// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
// KIND, either express or implied.  See the License for the
// specific language governing permissions and limitations
// under the License.

#include "kudu/util/spinlock_profiling.h"

#include <functional>
#include <sstream>

#include <gflags/gflags.h>
#include <glog/logging.h>

#include "kudu/gutil/atomicops.h"
#include "kudu/gutil/casts.h"
#include "kudu/gutil/macros.h"
#include "kudu/gutil/once.h"
#include "kudu/gutil/port.h"
#include "kudu/gutil/spinlock.h"
#include "kudu/gutil/strings/human_readable.h"
#include "kudu/gutil/sysinfo.h"
#include "kudu/util/atomic.h"
#include "kudu/util/debug-util.h"
#include "kudu/util/flag_tags.h"
#include "kudu/util/metrics.h"
#include "kudu/util/striped64.h"
#include "kudu/util/trace.h"

DEFINE_int32(lock_contention_trace_threshold_cycles,
             2000000, // 2M cycles should be about 1ms
             "If acquiring a spinlock takes more than this number of "
             "cycles, and a Trace is currently active, then the current "
             "stack trace is logged to the trace buffer.");
TAG_FLAG(lock_contention_trace_threshold_cycles, hidden);

METRIC_DEFINE_gauge_uint64(server, spinlock_contention_time,
    "Spinlock Contention Time", kudu::MetricUnit::kMicroseconds,
    "Amount of time consumed by contention on internal spinlocks since the server "
    "started. If this increases rapidly, it may indicate a performance issue in Kudu "
    "internals triggered by a particular workload and warrant investigation.",
    kudu::MetricLevel::kWarn,
    kudu::EXPOSE_AS_COUNTER);


using base::SpinLock;
using base::SpinLockHolder;

namespace kudu {

static const double kMicrosPerSecond = 1000000.0;

static LongAdder* g_contended_cycles = nullptr;

namespace {

// Implements a very simple linear-probing hashtable of stack traces with
// a fixed number of entries.
//
// Threads experiencing contention record their stacks into this hashtable,
// or increment an already-existing entry. Each entry has its own lock,
// but we can "skip" an entry under contention, and spread out a single stack
// into multiple buckets if necessary.
//
// A thread collecting a profile collects stack traces out of the hash table
// and resets the counts to 0 as they are collected.
class ContentionStacks {
 public:
  ContentionStacks()
    : dropped_samples_(0) {
  }

  // Add a stack trace to the table.
  void AddStack(const StackTrace& s, int64_t cycles);

  // Flush stacks from the buffer to 'out'. See the docs for FlushSynchronizationProfile()
  // in spinlock_profiling.h for details on format.
  //
  // On return, guarantees that any stack traces that were present at the beginning of
  // the call have been flushed. However, new stacks can be added concurrently with this call.
  void Flush(std::ostringstream* out, int64_t* dropped);

 private:

  // Collect the next sample from the underlying buffer, and set it back to 0 count
  // (thus marking it as "empty").
  //
  // 'iterator' serves as a way to keep track of the current position in the buffer.
  // Callers should initially set it to 0, and then pass the same pointer to each
  // call to CollectSample. This serves to loop through the collected samples.
  bool CollectSample(uint64_t* iterator, StackTrace* s, int64_t* trip_count, int64_t* cycles);

  // Hashtable entry.
  struct Entry {
    Entry() : trip_count(0),
              cycle_count(0) {
    }

    // Protects all other entries.
    SpinLock lock;

    // The number of times we've experienced contention with a stack trace equal
    // to 'trace'.
    //
    // If this is 0, then the entry is "unclaimed" and the other fields are not
    // considered valid.
    int64_t trip_count;

    // The total number of cycles spent waiting at this stack trace.
    int64_t cycle_count;

    // A cached hashcode of the trace.
    uint64_t hash;

    // The actual stack trace.
    StackTrace trace;
  };

  enum {
    kNumEntries = 1024,
    kNumLinearProbeAttempts = 4
  };
  Entry entries_[kNumEntries];

  // The number of samples which were dropped due to contention on this structure or
  // due to the hashtable being too full.
  AtomicInt<int64_t> dropped_samples_;
};

Atomic32 g_profiling_enabled = 0;
ContentionStacks* g_contention_stacks = nullptr;

void ContentionStacks::AddStack(const StackTrace& s, int64_t cycles) {
  uint64_t hash = s.HashCode();

  // Linear probe up to 4 attempts before giving up
  for (int i = 0; i < kNumLinearProbeAttempts; i++) {
    Entry* e = &entries_[(hash + i) % kNumEntries];
    if (!e->lock.TryLock()) {
      // If we fail to lock it, we can safely just use a different slot.
      // It's OK if a single stack shows up multiple times, because pprof
      // aggregates them in the end anyway.
      continue;
    }

    if (e->trip_count == 0) {
      // It's an un-claimed slot. Claim it.
      e->hash = hash;
      e->trace.CopyFrom(s);
    } else if (e->hash != hash || !e->trace.Equals(s)) {
      // It's claimed by a different stack trace.
      e->lock.Unlock();
      continue;
    }

    // Contribute to the stats for this stack.
    e->cycle_count += cycles;
    e->trip_count++;
    e->lock.Unlock();
    return;
  }

  // If we failed to find a matching hashtable slot, or we hit lock contention
  // trying to record our sample, add it to the dropped sample count.
  dropped_samples_.Increment();
}

void ContentionStacks::Flush(std::ostringstream* out, int64_t* dropped) {
  uint64_t iterator = 0;
  StackTrace t;
  int64_t cycles;
  int64_t count;
  while (g_contention_stacks->CollectSample(&iterator, &t, &count, &cycles)) {
    *out << cycles << " " << count
         << " @ " << t.ToHexString(StackTrace::NO_FIX_CALLER_ADDRESSES |
                                   StackTrace::HEX_0X_PREFIX)
         << std::endl;
  }

  *dropped += dropped_samples_.Exchange(0);
}

bool ContentionStacks::CollectSample(uint64_t* iterator, StackTrace* s, int64_t* trip_count,
                                     int64_t* cycles) {
  while (*iterator < kNumEntries) {
    Entry* e = &entries_[(*iterator)++];
    SpinLockHolder l(&e->lock);
    if (e->trip_count == 0) continue;

    *trip_count = e->trip_count;
    *cycles = e->cycle_count;
    s->CopyFrom(e->trace);

    e->trip_count = 0;
    e->cycle_count = 0;
    return true;
  }

  // Looped through the whole array and found nothing.
  return false;
}


void SubmitSpinLockProfileData(const void *contendedlock, int64_t wait_cycles) {
  TRACE_COUNTER_INCREMENT("spinlock_wait_cycles", wait_cycles);
  bool profiling_enabled = base::subtle::Acquire_Load(&g_profiling_enabled);
  bool long_wait_time = wait_cycles > FLAGS_lock_contention_trace_threshold_cycles;
  // Short circuit this function quickly in the common case.
  if (PREDICT_TRUE(!profiling_enabled && !long_wait_time)) {
    return;
  }

  static __thread bool in_func = false;
  if (in_func) return; // non-re-entrant
  in_func = true;

  StackTrace stack;
  stack.Collect();

  if (profiling_enabled) {
    DCHECK_NOTNULL(g_contention_stacks)->AddStack(stack, wait_cycles);
  }

  if (PREDICT_FALSE(long_wait_time)) {
    Trace* t = Trace::CurrentTrace();
    if (t) {
      double seconds = static_cast<double>(wait_cycles) / base::CyclesPerSecond();
      char backtrace_buffer[1024];
      stack.StringifyToHex(backtrace_buffer, arraysize(backtrace_buffer));
      TRACE_TO(t, "Waited $0 on lock $1. stack: $2",
               HumanReadableElapsedTime::ToShortString(seconds), contendedlock,
               backtrace_buffer);
    }
  }

  LongAdder* la = reinterpret_cast<LongAdder*>(
      base::subtle::Acquire_Load(reinterpret_cast<AtomicWord*>(&g_contended_cycles)));
  if (la) {
    la->IncrementBy(wait_cycles);
  }

  in_func = false;
}

void DoInit() {
  base::subtle::Release_Store(reinterpret_cast<AtomicWord*>(&g_contention_stacks),
                              reinterpret_cast<uintptr_t>(new ContentionStacks()));
  base::subtle::Release_Store(reinterpret_cast<AtomicWord*>(&g_contended_cycles),
                              reinterpret_cast<uintptr_t>(new LongAdder()));
}

} // anonymous namespace

void InitSpinLockContentionProfiling() {
  static GoogleOnceType once = GOOGLE_ONCE_INIT;
  GoogleOnceInit(&once, DoInit);
}


void RegisterSpinLockContentionMetrics(const scoped_refptr<MetricEntity>& entity) {
  InitSpinLockContentionProfiling();
  entity->NeverRetire(
      METRIC_spinlock_contention_time.InstantiateFunctionGauge(
          entity, []() { return GetSpinLockContentionMicros(); }));
}

uint64_t GetSpinLockContentionMicros() {
  int64_t wait_cycles = DCHECK_NOTNULL(g_contended_cycles)->Value();
  double micros = static_cast<double>(wait_cycles) / base::CyclesPerSecond()
    * kMicrosPerSecond;
  return implicit_cast<int64_t>(micros);
}

void StartSynchronizationProfiling() {
  InitSpinLockContentionProfiling();
  base::subtle::Barrier_AtomicIncrement(&g_profiling_enabled, 1);
}

void FlushSynchronizationProfile(std::ostringstream* out,
                                 int64_t* drop_count) {
  CHECK_NOTNULL(g_contention_stacks)->Flush(out, drop_count);
}

void StopSynchronizationProfiling() {
  InitSpinLockContentionProfiling();
  CHECK_GE(base::subtle::Barrier_AtomicIncrement(&g_profiling_enabled, -1), 0);
}

} // namespace kudu

// The hook expected by gutil is in the gutil namespace. Simply forward into the
// kudu namespace so we don't need to qualify everything.
namespace gutil {
void SubmitSpinLockProfileData(const void *contendedlock, int64_t wait_cycles) {
  kudu::SubmitSpinLockProfileData(contendedlock, wait_cycles);
}
} // namespace gutil