/* * 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/workQueueStats.c#6 $ */ #include "workQueueStats.h" #include "atomic.h" #include "logger.h" #include "workItemStats.h" #include "workQueueInternals.h" /**********************************************************************/ int initializeWorkQueueStats(KvdoWorkQueueStats *stats, struct kobject *queueKObject) { spin_lock_init(&stats->workItemStats.functionTable.lock); if (ENABLE_PER_FUNCTION_TIMING_STATS) { for (int i = 0; i < NUM_WORK_QUEUE_ITEM_STATS + 1; i++) { initSimpleStats(&stats->workItemStats.times[i]); } } stats->queueTimeHistogram = makeLogarithmicHistogram(queueKObject, "queue_time", "Queue Time", "work items", "wait time", "microseconds", 9); if (stats->queueTimeHistogram == NULL) { return -ENOMEM; } stats->rescheduleQueueLengthHistogram = makeLogarithmicHistogram(queueKObject, "reschedule_queue_length", "Reschedule Queue Length", "calls", "queued work items", NULL, 4); if (stats->rescheduleQueueLengthHistogram == NULL) { return -ENOMEM; } stats->rescheduleTimeHistogram = makeLogarithmicHistogram(queueKObject, "reschedule_time", "Reschedule Time", "calls", "sleep interval", "microseconds", 9); if (stats->rescheduleTimeHistogram == NULL) { return -ENOMEM; } stats->runTimeBeforeRescheduleHistogram = makeLogarithmicHistogram(queueKObject, "run_time_before_reschedule", "Run Time Before Reschedule", "calls", "run time", "microseconds", 9); if (stats->runTimeBeforeRescheduleHistogram == NULL) { return -ENOMEM; } stats->scheduleTimeHistogram = makeLogarithmicHistogram(queueKObject, "schedule_time", "Schedule Time", "calls", "sleep interval", "microseconds", 9); if (stats->scheduleTimeHistogram == NULL) { return -ENOMEM; } stats->wakeupLatencyHistogram = makeLogarithmicHistogram(queueKObject, "wakeup_latency", "Wakeup Latency", "wakeups", "latency", "microseconds", 9); if (stats->wakeupLatencyHistogram == NULL) { return -ENOMEM; } stats->wakeupQueueLengthHistogram = makeLogarithmicHistogram(queueKObject, "wakeup_queue_length", "Wakeup Queue Length", "wakeups", "queued work items", NULL, 4); if (stats->wakeupQueueLengthHistogram == NULL) { return -ENOMEM; } return 0; } /**********************************************************************/ void cleanupWorkQueueStats(KvdoWorkQueueStats *stats) { freeHistogram(&stats->queueTimeHistogram); freeHistogram(&stats->rescheduleQueueLengthHistogram); freeHistogram(&stats->rescheduleTimeHistogram); freeHistogram(&stats->runTimeBeforeRescheduleHistogram); freeHistogram(&stats->scheduleTimeHistogram); freeHistogram(&stats->wakeupLatencyHistogram); freeHistogram(&stats->wakeupQueueLengthHistogram); } /**********************************************************************/ static uint64_t getTotalProcessed(const SimpleWorkQueue *queue) { uint64_t totalProcessed = 0; for (int i = 0; i < NUM_WORK_QUEUE_ITEM_STATS + 1; i++) { totalProcessed += queue->stats.workItemStats.times[i].count; } return totalProcessed; } /**********************************************************************/ void logWorkQueueStats(const SimpleWorkQueue *queue) { uint64_t runtimeNS = 0; if (queue->thread != NULL) { runtimeNS += queue->thread->se.sum_exec_runtime; } unsigned long nsPerWorkItem = 0; uint64_t totalProcessed = getTotalProcessed(queue); if (totalProcessed > 0) { nsPerWorkItem = runtimeNS / totalProcessed; } unsigned long runtimeMS = runtimeNS / 1000; logInfo("workQ %" PRIptr " (%s) thread cpu usage %lu.%06lus, %" PRIu64 " tasks, %lu.%03luus/task", queue, queue->common.name, runtimeMS / 1000000, runtimeMS % 1000000, totalProcessed, nsPerWorkItem / 1000, nsPerWorkItem % 1000); } /**********************************************************************/ ssize_t formatRunTimeStats(const KvdoWorkQueueStats *stats, char *buffer) { // Get snapshots of all three at approximately the same time. uint64_t startTime = stats->startTime; uint64_t runTime = atomic64_read(&stats->runTime); uint64_t rescheduleTime = atomic64_read(&stats->rescheduleTime); loadFence(); // rdtsc barrier uint64_t now = currentTime(CLOCK_MONOTONIC); uint64_t lifetime = now - startTime; return sprintf(buffer, "%llu %llu %llu\n", lifetime, runTime, rescheduleTime); }