/* * 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/workItemStats.c#4 $ */ #include "workItemStats.h" #include "atomic.h" #include "logger.h" /** * Scan the work queue stats table for the provided work function and * priority value. If it's not found, see if an empty slot is * available. * * @param table The work queue's function table * @param work The function we want to record stats for * @param priority The priority of the work item * * @return The index of the slot to use (matching or empty), or * NUM_WORK_QUEUE_ITEM_STATS if the table is full of * non-matching entries. **/ static inline unsigned int scanStatTable(const KvdoWorkFunctionTable *table, KvdoWorkFunction work, unsigned int priority) { unsigned int i; /* * See comments in getStatTableIndex regarding order of memory * accesses. Work function first, then a barrier, then priority. */ for (i = 0; i < NUM_WORK_QUEUE_ITEM_STATS; i++) { if (table->functions[i] == NULL) { return i; } else if (table->functions[i] == work) { smp_rmb(); if (table->priorities[i] == priority) { return i; } } } return NUM_WORK_QUEUE_ITEM_STATS; } /** * Scan the work queue stats table for the provided work function and * priority value. Assign an empty slot if necessary. * * @param stats The stats structure * @param work The function we want to record stats for * @param priority The priority of the work item * * @return The index of the matching slot, or NUM_WORK_QUEUE_ITEM_STATS * if the table is full of non-matching entries. **/ static unsigned int getStatTableIndex(KvdoWorkItemStats *stats, KvdoWorkFunction work, unsigned int priority) { KvdoWorkFunctionTable *functionTable = &stats->functionTable; unsigned int index = scanStatTable(functionTable, work, priority); if (unlikely(index == NUM_WORK_QUEUE_ITEM_STATS) || likely(functionTable->functions[index] != NULL)) { return index; } unsigned long flags = 0; // The delayed-work-item processing uses queue->lock in some cases, // and one case may call into this function, so we can't reuse // queue->lock here. spin_lock_irqsave(&functionTable->lock, flags); // Recheck now that we've got the lock... index = scanStatTable(functionTable, work, priority); if ((index == NUM_WORK_QUEUE_ITEM_STATS) || (functionTable->functions[index] != NULL)) { spin_unlock_irqrestore(&functionTable->lock, flags); return index; } /* * An uninitialized priority is indistinguishable from a zero * priority. So store the priority first, and enforce the ordering, * so that a non-null work function pointer indicates we've finished * filling in the value. (And, to make this work, we have to read * the work function first and priority second, when comparing.) */ functionTable->priorities[index] = priority; smp_wmb(); functionTable->functions[index] = work; spin_unlock_irqrestore(&functionTable->lock, flags); return index; } /** * Get counters on work items, identified by index into the internal * array. * * @param [in] stats The collected statistics * @param [in] index The index * @param [out] enqueuedPtr The total work items enqueued * @param [out] processedPtr The number of work items processed * @param [out] pendingPtr The number of work items still pending **/ static void getWorkItemCountsByItem(const KvdoWorkItemStats *stats, unsigned int index, uint64_t *enqueuedPtr, uint64_t *processedPtr, unsigned int *pendingPtr) { uint64_t enqueued = atomic64_read(&stats->enqueued[index]); uint64_t processed = stats->times[index].count; unsigned int pending; if (enqueued < processed) { // Probably just out of sync. pending = 1; } else { pending = enqueued - processed; // Pedantic paranoia: Check for overflow of the 32-bit "pending". if ((pending + processed) < enqueued) { pending = UINT_MAX; } } *enqueuedPtr = enqueued; *processedPtr = processed; *pendingPtr = pending; } /** * Get counters on work items not covered by any index value. * * @param [in] stats The collected statistics * @param [out] enqueuedPtr The total work items enqueued * @param [out] processedPtr The number of work items processed **/ static void getOtherWorkItemCounts(const KvdoWorkItemStats *stats, uint64_t *enqueuedPtr, uint64_t *processedPtr) { unsigned int pending; getWorkItemCountsByItem(stats, NUM_WORK_QUEUE_ITEM_STATS, enqueuedPtr, processedPtr, &pending); } /** * Get timing stats on work items, identified by index into the * internal array. * * @param [in] stats The collected statistics * @param [in] index The index into the array * @param [out] min The minimum execution time * @param [out] mean The mean execution time * @param [out] max The maximum execution time **/ static void getWorkItemTimesByItem(const KvdoWorkItemStats *stats, unsigned int index, uint64_t *min, uint64_t *mean, uint64_t *max) { *min = stats->times[index].min; *mean = getSampleAverage(&stats->times[index]); *max = stats->times[index].max; } /**********************************************************************/ void updateWorkItemStatsForEnqueue(KvdoWorkItemStats *stats, KvdoWorkItem *item, int priority) { item->statTableIndex = getStatTableIndex(stats, item->statsFunction, priority); atomic64_add(1, &stats->enqueued[item->statTableIndex]); } /**********************************************************************/ char *getFunctionName(void *pointer, char *buffer, size_t bufferLength) { if (pointer == NULL) { /* * Format "%ps" logs a null pointer as "(null)" with a bunch of * leading spaces. We sometimes use this when logging lots of * data; don't be so verbose. */ strncpy(buffer, "-", bufferLength); } else { /* * Use a non-const array instead of a string literal below to * defeat gcc's format checking, which doesn't understand that * "%ps" actually does support a precision spec in Linux kernel * code. */ static char truncatedFunctionNameFormatString[] = "%.*ps"; snprintf(buffer, bufferLength, truncatedFunctionNameFormatString, bufferLength - 1, pointer); char *space = strchr(buffer, ' '); if (space != NULL) { *space = '\0'; } } return buffer; } /**********************************************************************/ size_t formatWorkItemStats(const KvdoWorkItemStats *stats, char *buffer, size_t length) { const KvdoWorkFunctionTable *functionIDs = &stats->functionTable; size_t currentOffset = 0; uint64_t enqueued, processed; int i; for (i = 0; i < NUM_WORK_QUEUE_ITEM_STATS; i++) { if (functionIDs->functions[i] == NULL) { break; } if (atomic64_read(&stats->enqueued[i]) == 0) { continue; } /* * The reporting of all of "pending", "enqueued" and "processed" * here seems redundant, but "pending" is limited to 0 in the case * where "processed" exceeds "enqueued", either through current * activity and a lack of synchronization when fetching stats, or * a coding bug. This report is intended largely for debugging, so * we'll go ahead and print the not-necessarily-redundant values. */ unsigned int pending; getWorkItemCountsByItem(stats, i, &enqueued, &processed, &pending); // Format: fn prio enq proc timeo [ min max mean ] if (ENABLE_PER_FUNCTION_TIMING_STATS) { uint64_t min, mean, max; getWorkItemTimesByItem(stats, i, &min, &mean, &max); currentOffset += snprintf(buffer + currentOffset, length - currentOffset, "%-36ps %d %10llu %10" PRIu64 " %10llu %10llu %10" PRIu64 "\n", functionIDs->functions[i], functionIDs->priorities[i], enqueued, processed, min, max, mean); } else { currentOffset += snprintf(buffer + currentOffset, length - currentOffset, "%-36ps %d %10llu %10" PRIu64 "\n", functionIDs->functions[i], functionIDs->priorities[i], enqueued, processed); } if (currentOffset >= length) { break; } } if ((i == NUM_WORK_QUEUE_ITEM_STATS) && (currentOffset < length)) { uint64_t enqueued, processed; getOtherWorkItemCounts(stats, &enqueued, &processed); if (enqueued > 0) { currentOffset += snprintf(buffer + currentOffset, length - currentOffset, "%-36s %d %10llu %10" PRIu64 "\n", "OTHER", 0, enqueued, processed); } } return currentOffset; } /**********************************************************************/ void logWorkItemStats(const KvdoWorkItemStats *stats) { uint64_t totalEnqueued = 0; uint64_t totalProcessed = 0; const KvdoWorkFunctionTable *functionIDs = &stats->functionTable; int i; for (i = 0; i < NUM_WORK_QUEUE_ITEM_STATS; i++) { if (functionIDs->functions[i] == NULL) { break; } if (atomic64_read(&stats->enqueued[i]) == 0) { continue; } /* * The reporting of all of "pending", "enqueued" and "processed" * here seems redundant, but "pending" is limited to 0 in the case * where "processed" exceeds "enqueued", either through current * activity and a lack of synchronization when fetching stats, or * a coding bug. This report is intended largely for debugging, so * we'll go ahead and print the not-necessarily-redundant values. */ uint64_t enqueued, processed; unsigned int pending; getWorkItemCountsByItem(stats, i, &enqueued, &processed, &pending); totalEnqueued += enqueued; totalProcessed += processed; static char work[256]; // arbitrary size getFunctionName(functionIDs->functions[i], work, sizeof(work)); if (ENABLE_PER_FUNCTION_TIMING_STATS) { uint64_t min, mean, max; getWorkItemTimesByItem(stats, i, &min, &mean, &max); logInfo(" priority %d: %u pending" " %llu enqueued %llu processed" " %s" " times %llu/%llu/%lluns", functionIDs->priorities[i], pending, enqueued, processed, work, min, mean, max); } else { logInfo(" priority %d: %u pending" " %llu enqueued %llu processed" " %s", functionIDs->priorities[i], pending, enqueued, processed, work); } } if (i == NUM_WORK_QUEUE_ITEM_STATS) { uint64_t enqueued, processed; getOtherWorkItemCounts(stats, &enqueued, &processed); if (enqueued > 0) { totalEnqueued += enqueued; totalProcessed += processed; logInfo(" ... others: %llu enqueued %llu processed", enqueued, processed); } } logInfo(" total: %llu enqueued %llu processed", totalEnqueued, totalProcessed); }