Blob Blame History Raw
/*
 * Copyright (c) 2020 Red Hat, Inc.
 *
 * This program is free software; you can redistribute it and/or
 * modify it under the terms of the GNU General Public License
 * as published by the Free Software Foundation; either version 2
 * of the License, or (at your option) any later version.
 * 
 * This program is distributed in the hope that it will be useful,
 * but WITHOUT ANY WARRANTY; without even the implied warranty of
 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
 * GNU General Public License for more details.
 * 
 * You should have received a copy of the GNU General Public License
 * along with this program; if not, write to the Free Software
 * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
 * 02110-1301, USA. 
 *
 * $Id: //eng/vdo-releases/aluminum/src/c++/vdo/kernel/ktrace.c#2 $
 */

#include "ktrace.h"

#include "memoryAlloc.h"

#include "dataVIO.h"

#include "kvio.h"
#include "logger.h"

enum {
  // How much data from a trace can we log in one call without messing
  // up the log or losing data?
  TRACE_LOG_MAX         = 820,

  // What fraction (1 out of TRACE_SAMPLE_INTERVAL VIOs) to trace
  TRACE_SAMPLE_INTERVAL = 3,
};

bool traceRecording = false;

static struct {
  char         buffer[2000];
  unsigned int counter;
  struct mutex lock;
} traceLoggingState;

/**
 * Initialize a SampleCounter structure with the given sampling interval.
 *
 * @param counter    The counter to initialize
 * @param interval   The desired sampling interval
 **/
static void initializeSampleCounter(SampleCounter *counter,
                                    unsigned int   interval)
{
  spin_lock_init(&counter->lock);
  counter->tick = 0;
  counter->interval = interval;
}

/*************************************************************************/
bool sampleThisOne(SampleCounter *counter)
{
  bool wantTracing = false;
  spin_lock(&counter->lock);
  counter->tick++;
  if (counter->tick >= counter->interval) {
    counter->tick = 0;
    wantTracing = true;
  }
  spin_unlock(&counter->lock);
  return wantTracing;
}

/*************************************************************************/
static void freeTraceDataBuffer(void *poolData, void *data)
{
  Trace *trace = (Trace *) data;
  FREE(trace);
}

/*************************************************************************/
static int allocTraceDataBuffer(void *poolData, void **dataPtr)
{
  Trace *trace;
  int result = ALLOCATE(1, Trace, __func__, &trace);
  if (result != VDO_SUCCESS) {
    logError("trace data allocation failure %d", result);
    return result;
  }

  *dataPtr = trace;
  return VDO_SUCCESS;
}

/*************************************************************************/
int allocTraceFromPool(KernelLayer *layer, Trace **tracePointer)
{
  int result = allocBufferFromPool(layer->traceBufferPool,
                                   (void **) tracePointer);
  if (result == VDO_SUCCESS) {
    (*tracePointer)->used = 0;
  }
  return result;
}

/*************************************************************************/
void freeTraceToPool(KernelLayer *layer, Trace *trace)
{
  freeBufferToPool(layer->traceBufferPool, trace);
}

/*************************************************************************/
int traceKernelLayerInit(KernelLayer *layer)
{
  layer->vioTraceRecording = traceRecording;
  initializeSampleCounter(&layer->traceSampleCounter, TRACE_SAMPLE_INTERVAL);
  unsigned int traceRecordsNeeded = 0;
  if (layer->vioTraceRecording) {
    traceRecordsNeeded += layer->requestLimiter.limit;
  }
  if (traceRecordsNeeded > 0) {
    return makeBufferPool("KVDO Trace Data Pool", traceRecordsNeeded,
                          allocTraceDataBuffer, freeTraceDataBuffer, NULL,
                          layer, &layer->traceBufferPool);
  }
  return VDO_SUCCESS;
}

/*************************************************************************/
void initializeTraceLoggingOnce(void)
{
  mutex_init(&traceLoggingState.lock);
}

/*************************************************************************/
void logKvioTrace(KVIO *kvio)
{
  KernelLayer *layer = kvio->layer;

  mutex_lock(&traceLoggingState.lock);
  traceLoggingState.counter++;
  // Log about 0.1% to avoid spewing data faster than syslog can keep up
  // (on certain of Permabit's test machines).
  // Yes, the 37 is arbitrary and meaningless.

  if (layer->traceLogging && ((traceLoggingState.counter % 1024) == 37)) {
    kvioAddTraceRecord(kvio, THIS_LOCATION(NULL));
    size_t traceLen = 0;
    formatTrace(kvio->vio->trace, traceLoggingState.buffer,
                sizeof(traceLoggingState.buffer), &traceLen);

    if (isMetadata(kvio)) {
      logInfo("finishing kvio %s meta @%" PRIptr " %s",
              (isWriteVIO(kvio->vio) ? "read" : "write"),
              kvio, traceLoggingState.buffer);
    } else if (isCompressedWriter(kvio)) {
      logInfo("finishing kvio write comp @%" PRIptr " %s",
              kvio, traceLoggingState.buffer);
    } else {
      const char *dupeLabel = "";
      if (isWriteVIO(kvio->vio)) {
        DataVIO *dataVIO = vioAsDataVIO(kvio->vio);
        if (isTrimDataVIO(dataVIO)) {
          dupeLabel = "trim ";
        } else if (dataVIO->isZeroBlock) {
          dupeLabel = "zero ";
        } else if (dataVIO->isDuplicate) {
          dupeLabel = "dupe ";
        } else {
          dupeLabel = "new ";
        }
      }

      logInfo("finishing kvio %s data %s@%" PRIptr " %.*s",
              (isWriteVIO(kvio->vio) ? "read" : "write"),
              dupeLabel, kvio, TRACE_LOG_MAX, traceLoggingState.buffer);
      char *buf = traceLoggingState.buffer;
      while (traceLen > TRACE_LOG_MAX) {
        traceLen -= TRACE_LOG_MAX;
        buf += TRACE_LOG_MAX;
        logInfo("more kvio %" PRIptr " path: %.*s", kvio, TRACE_LOG_MAX, buf);
      }
    }
  }

  mutex_unlock(&traceLoggingState.lock);
}