From 894211971ebf8b53ed3a78d771764021f7de2de6 Mon Sep 17 00:00:00 2001 From: Lars Knoll Date: Mon, 27 Nov 2017 10:53:33 +0100 Subject: Add logging categories for GC statistics And use them to dump some useful information. This replaces the old QV4_MM_STATS environment variable and introduces the qt.qml.gc.statistics (for some stats at app exit) and qt.qml.gc.allocatorStats (for stats on each GC run) logging categories. Change-Id: I0a16b25b8663aa7dbfe2adae299d3d990e8e5554 Reviewed-by: Simon Hausmann --- src/qml/memory/qv4mm.cpp | 144 ++++++++++++++++++++--------------------------- src/qml/memory/qv4mm_p.h | 25 +++----- 2 files changed, 70 insertions(+), 99 deletions(-) (limited to 'src/qml/memory') diff --git a/src/qml/memory/qv4mm.cpp b/src/qml/memory/qv4mm.cpp index 538be0d16a..4f4124d505 100644 --- a/src/qml/memory/qv4mm.cpp +++ b/src/qml/memory/qv4mm.cpp @@ -44,6 +44,7 @@ #include "qv4qobjectwrapper_p.h" #include #include +#include #include #include "PageReservation.h" #include "PageAllocation.h" @@ -87,6 +88,11 @@ #define MIN_UNMANAGED_HEAPSIZE_GC_LIMIT std::size_t(128 * 1024) +Q_LOGGING_CATEGORY(lcGcStats, "qt.qml.gc.statistics") +Q_DECLARE_LOGGING_CATEGORY(lcGcStats) +Q_LOGGING_CATEGORY(lcGcAllocatorStats, "qt.qml.gc.allocatorStats") +Q_DECLARE_LOGGING_CATEGORY(lcGcAllocatorStats) + using namespace WTF; QT_BEGIN_NAMESPACE @@ -485,9 +491,9 @@ template struct StackAllocator; HeapItem *BlockAllocator::allocate(size_t size, bool forceAllocation) { Q_ASSERT((size % Chunk::SlotSize) == 0); size_t slotsRequired = size >> Chunk::SlotSizeShift; -#if MM_DEBUG - ++allocations[bin]; -#endif + + if (allocationStats) + ++allocationStats[binForSlots(slotsRequired)]; HeapItem **last; @@ -616,36 +622,6 @@ void BlockAllocator::freeAll() } } -#if MM_DEBUG -void BlockAllocator::stats() { - DEBUG << "MM stats:"; - QString s; - for (int i = 0; i < 10; ++i) { - uint c = 0; - HeapItem *item = freeBins[i]; - while (item) { - ++c; - item = item->freeData.next; - } - s += QString::number(c) + QLatin1String(", "); - } - HeapItem *item = freeBins[NumBins - 1]; - uint c = 0; - while (item) { - ++c; - item = item->freeData.next; - } - s += QLatin1String("..., ") + QString::number(c); - DEBUG << "bins:" << s; - QString a; - for (int i = 0; i < 10; ++i) - a += QString::number(allocations[i]) + QLatin1String(", "); - a += QLatin1String("..., ") + QString::number(allocations[NumBins - 1]); - DEBUG << "allocs:" << a; - memset(allocations, 0, sizeof(allocations)); -} -#endif - HeapItem *HugeItemAllocator::allocate(size_t size) { Chunk *c = chunkAllocator->allocate(size); @@ -700,11 +676,15 @@ MemoryManager::MemoryManager(ExecutionEngine *engine) , m_weakValues(new PersistentValueStorage(engine)) , unmanagedHeapSizeGCLimit(MIN_UNMANAGED_HEAPSIZE_GC_LIMIT) , aggressiveGC(!qEnvironmentVariableIsEmpty("QV4_MM_AGGRESSIVE_GC")) - , gcStats(!qEnvironmentVariableIsEmpty(QV4_MM_STATS)) + , gcStats(lcGcStats().isDebugEnabled()) + , gcCollectorStats(lcGcAllocatorStats().isDebugEnabled()) { #ifdef V4_USE_VALGRIND VALGRIND_CREATE_MEMPOOL(this, 0, true); #endif + memset(statistics.allocations, 0, sizeof(statistics.allocations)); + if (gcStats) + blockAllocator.allocationStats = statistics.allocations; } #ifndef QT_NO_DEBUG @@ -759,9 +739,6 @@ Heap::Base *MemoryManager::allocData(std::size_t size) runGC(); didRunGC = true; } -#ifdef DETAILED_MM_STATS - willAllocate(size); -#endif // DETAILED_MM_STATS Q_ASSERT(size >= Chunk::SlotSize); Q_ASSERT(size % Chunk::SlotSize == 0); @@ -925,9 +902,10 @@ bool MemoryManager::shouldRunGC() const size_t dumpBins(BlockAllocator *b, bool printOutput = true) { + const QLoggingCategory &stats = lcGcAllocatorStats(); size_t totalFragmentedSlots = 0; if (printOutput) - qDebug() << "Fragmentation map:"; + qDebug(stats) << "Fragmentation map:"; for (uint i = 0; i < BlockAllocator::NumBins; ++i) { uint nEntries = 0; HeapItem *h = b->freeBins[i]; @@ -937,7 +915,7 @@ size_t dumpBins(BlockAllocator *b, bool printOutput = true) h = h->freeData.next; } if (printOutput) - qDebug() << " number of entries in slot" << i << ":" << nEntries; + qDebug(stats) << " number of entries in slot" << i << ":" << nEntries; } SDUMP() << " large slot map"; HeapItem *h = b->freeBins[BlockAllocator::NumBins - 1]; @@ -947,7 +925,7 @@ size_t dumpBins(BlockAllocator *b, bool printOutput = true) } if (printOutput) - qDebug() << " total mem in bins" << totalFragmentedSlots*Chunk::SlotSize; + qDebug(stats) << " total mem in bins" << totalFragmentedSlots*Chunk::SlotSize; return totalFragmentedSlots*Chunk::SlotSize; } @@ -960,25 +938,30 @@ void MemoryManager::runGC() QScopedValueRollback gcBlocker(gcBlocked, true); - if (!gcStats) { -// uint oldUsed = allocator.usedMem(); + if (gcStats) { + statistics.maxReservedMem = qMax(statistics.maxReservedMem, getAllocatedMem()); + statistics.maxAllocatedMem = qMax(statistics.maxAllocatedMem, getUsedMem() + getLargeItemsMem()); + } + + if (!gcCollectorStats) { mark(); sweep(); -// DEBUG << "RUN GC: allocated:" << allocator.allocatedMem() << "used before" << oldUsed << "used now" << allocator.usedMem(); } else { bool triggeredByUnmanagedHeap = (unmanagedHeapSize > unmanagedHeapSizeGCLimit); size_t oldUnmanagedSize = unmanagedHeapSize; + const size_t totalMem = getAllocatedMem(); const size_t usedBefore = getUsedMem(); const size_t largeItemsBefore = getLargeItemsMem(); - qDebug() << "========== GC =========="; + const QLoggingCategory &stats = lcGcAllocatorStats(); + qDebug(stats) << "========== GC =========="; #ifndef QT_NO_DEBUG - qDebug() << " Triggered by alloc request of" << lastAllocRequestedSlots << "slots."; + qDebug(stats) << " Triggered by alloc request of" << lastAllocRequestedSlots << "slots."; #endif size_t oldChunks = blockAllocator.chunks.size(); - qDebug() << "Allocated" << totalMem << "bytes in" << oldChunks << "chunks"; - qDebug() << "Fragmented memory before GC" << (totalMem - usedBefore); + qDebug(stats) << "Allocated" << totalMem << "bytes in" << oldChunks << "chunks"; + qDebug(stats) << "Fragmented memory before GC" << (totalMem - usedBefore); dumpBins(&blockAllocator); QElapsedTimer t; @@ -991,29 +974,32 @@ void MemoryManager::runGC() qint64 sweepTime = t.elapsed(); if (triggeredByUnmanagedHeap) { - qDebug() << "triggered by unmanaged heap:"; - qDebug() << " old unmanaged heap size:" << oldUnmanagedSize; - qDebug() << " new unmanaged heap:" << unmanagedHeapSize; - qDebug() << " unmanaged heap limit:" << unmanagedHeapSizeGCLimit; + qDebug(stats) << "triggered by unmanaged heap:"; + qDebug(stats) << " old unmanaged heap size:" << oldUnmanagedSize; + qDebug(stats) << " new unmanaged heap:" << unmanagedHeapSize; + qDebug(stats) << " unmanaged heap limit:" << unmanagedHeapSizeGCLimit; } size_t memInBins = dumpBins(&blockAllocator); - qDebug() << "Marked object in" << markTime << "ms."; - qDebug() << "Sweeped object in" << sweepTime << "ms."; - qDebug() << "Used memory before GC:" << usedBefore; - qDebug() << "Used memory after GC:" << usedAfter; - qDebug() << "Freed up bytes:" << (usedBefore - usedAfter); - qDebug() << "Freed up chunks:" << (oldChunks - blockAllocator.chunks.size()); + qDebug(stats) << "Marked object in" << markTime << "ms."; + qDebug(stats) << "Sweeped object in" << sweepTime << "ms."; + qDebug(stats) << "Used memory before GC:" << usedBefore; + qDebug(stats) << "Used memory after GC:" << usedAfter; + qDebug(stats) << "Freed up bytes:" << (usedBefore - usedAfter); + qDebug(stats) << "Freed up chunks:" << (oldChunks - blockAllocator.chunks.size()); size_t lost = blockAllocator.allocatedMem() - memInBins - usedAfter; if (lost) - qDebug() << "!!!!!!!!!!!!!!!!!!!!! LOST MEM:" << lost << "!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!"; + qDebug(stats) << "!!!!!!!!!!!!!!!!!!!!! LOST MEM:" << lost << "!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!"; if (largeItemsBefore || largeItemsAfter) { - qDebug() << "Large item memory before GC:" << largeItemsBefore; - qDebug() << "Large item memory after GC:" << largeItemsAfter; - qDebug() << "Large item memory freed up:" << (largeItemsBefore - largeItemsAfter); + qDebug(stats) << "Large item memory before GC:" << largeItemsBefore; + qDebug(stats) << "Large item memory after GC:" << largeItemsAfter; + qDebug(stats) << "Large item memory freed up:" << (largeItemsBefore - largeItemsAfter); } - qDebug() << "======== End GC ========"; + qDebug(stats) << "======== End GC ========"; } + if (gcStats) + statistics.maxUsedMem = qMax(statistics.maxUsedMem, getUsedMem() + getLargeItemsMem()); + if (aggressiveGC) { // ensure we don't 'loose' any memory Q_ASSERT(blockAllocator.allocatedMem() == getUsedMem() + dumpBins(&blockAllocator, false)); @@ -1039,6 +1025,8 @@ MemoryManager::~MemoryManager() { delete m_persistentValues; + dumpStats(); + sweep(/*lastSweep*/true); blockAllocator.freeAll(); hugeItemAllocator.freeAll(); @@ -1054,30 +1042,20 @@ MemoryManager::~MemoryManager() void MemoryManager::dumpStats() const { -#ifdef DETAILED_MM_STATS - std::cerr << "=================" << std::endl; - std::cerr << "Allocation stats:" << std::endl; - std::cerr << "Requests for each chunk size:" << std::endl; - for (int i = 0; i < allocSizeCounters.size(); ++i) { - if (unsigned count = allocSizeCounters[i]) { - std::cerr << "\t" << (i << 4) << " bytes chunks: " << count << std::endl; - } - } -#endif // DETAILED_MM_STATS -} + if (!gcStats) + return; -#ifdef DETAILED_MM_STATS -void MemoryManager::willAllocate(std::size_t size) -{ - unsigned alignedSize = (size + 15) >> 4; - QVector &counters = allocSizeCounters; - if ((unsigned) counters.size() < alignedSize + 1) - counters.resize(alignedSize + 1); - counters[alignedSize]++; + const QLoggingCategory &stats = lcGcStats(); + qDebug(stats) << "Qml GC memory allocation statistics:"; + qDebug(stats) << "Total memory allocated:" << statistics.maxReservedMem; + qDebug(stats) << "Max memory used before a GC run:" << statistics.maxAllocatedMem; + qDebug(stats) << "Max memory used after a GC run:" << statistics.maxUsedMem; + qDebug(stats) << "Requests for different item sizes:"; + for (int i = 1; i < BlockAllocator::NumBins - 1; ++i) + qDebug(stats) << " <" << (i << Chunk::SlotSizeShift) << " bytes: " << statistics.allocations[i]; + qDebug(stats) << " >=" << ((BlockAllocator::NumBins - 1) << Chunk::SlotSizeShift) << " bytes: " << statistics.allocations[BlockAllocator::NumBins - 1]; } -#endif // DETAILED_MM_STATS - void MemoryManager::collectFromJSStack() const { Value *v = engine->jsStackBase; diff --git a/src/qml/memory/qv4mm_p.h b/src/qml/memory/qv4mm_p.h index e3cccb6aa0..aa8d13de8c 100644 --- a/src/qml/memory/qv4mm_p.h +++ b/src/qml/memory/qv4mm_p.h @@ -58,8 +58,6 @@ #include #include -//#define DETAILED_MM_STATS - #define QV4_MM_MAXBLOCK_SHIFT "QV4_MM_MAXBLOCK_SHIFT" #define QV4_MM_MAX_CHUNK_SIZE "QV4_MM_MAX_CHUNK_SIZE" #define QV4_MM_STATS "QV4_MM_STATS" @@ -121,9 +119,6 @@ struct BlockAllocator { : chunkAllocator(chunkAllocator), engine(engine) { memset(freeBins, 0, sizeof(freeBins)); -#if MM_DEBUG - memset(allocations, 0, sizeof(allocations)); -#endif } enum { NumBins = 8 }; @@ -132,10 +127,6 @@ struct BlockAllocator { return nSlots >= NumBins ? NumBins - 1 : nSlots; } -#if MM_DEBUG - void stats(); -#endif - HeapItem *allocate(size_t size, bool forceAllocation = false); size_t totalSlots() const { @@ -163,9 +154,7 @@ struct BlockAllocator { ChunkAllocator *chunkAllocator; ExecutionEngine *engine; std::vector chunks; -#if MM_DEBUG - uint allocations[NumBins]; -#endif + uint *allocationStats = nullptr; }; struct HugeItemAllocator { @@ -449,10 +438,6 @@ protected: Heap::Base *allocData(std::size_t size); Heap::Object *allocObjectWithMemberData(const QV4::VTable *vtable, uint nMembers); -#ifdef DETAILED_MM_STATS - void willAllocate(std::size_t size); -#endif // DETAILED_MM_STATS - private: void collectFromJSStack() const; void mark(); @@ -475,6 +460,14 @@ public: bool gcBlocked = false; bool aggressiveGC = false; bool gcStats = false; + bool gcCollectorStats = false; + + struct { + size_t maxReservedMem = 0; + size_t maxAllocatedMem = 0; + size_t maxUsedMem = 0; + uint allocations[BlockAllocator::NumBins]; + } statistics; }; } -- cgit v1.2.3