mem: Adding verbose debug output in the memory system

This patch provides useful printouts throughut the memory system. This
includes pretty-printed cache tags and function call messages
(call-stack like).

src/mem/abstract_mem.cc

@@ -363,8 +363,11 @@ AbstractMemory::access(PacketPtr pkt)
             bytesInstRead[pkt->req->masterId()] += pkt->getSize();
     } else if (pkt->isWrite()) {
         if (writeOK(pkt)) {
-            if (pmemAddr)
+            if (pmemAddr) {
                 memcpy(hostAddr, pkt->getPtr<uint8_t>(), pkt->getSize());
+                DPRINTF(MemoryAccess, "%s wrote %x bytes to address %x\n",
+                        __func__, pkt->getSize(), pkt->getAddr());
+            }
             assert(!pkt->req->isInstFetch());
             TRACE_PACKET("Write");
             numWrites[pkt->req->masterId()]++;

src/mem/cache/SConscript

@@ -45,4 +45,5 @@ Source('mshr_queue.cc')
 DebugFlag('Cache')
 DebugFlag('CachePort')
 DebugFlag('CacheRepl')
+DebugFlag('CacheTags')
 DebugFlag('HWPrefetch')

src/mem/cache/blk.hh

@@ -288,6 +288,42 @@ class CacheBlk
         }
     }
 
+    /**
+     * Pretty-print a tag, and interpret state bits to readable form
+     * including mapping to a MOESI stat.
+     *
+     * @return string with basic state information
+     */
+    std::string print() const
+    {
+        /**
+         *  state       M   O   E   S   I
+         *  writable    1   0   1   0   0
+         *  dirty       1   1   0   0   0
+         *  valid       1   1   1   1   0
+         *
+         *  state   writable    dirty   valid
+         *  M       1           1       1
+         *  O       0           1       1
+         *  E       1           0       1
+         *  S       0           0       1
+         *  I       0           0       0
+         **/
+        unsigned state = isWritable() << 2 | isDirty() << 1 | isValid();
+        char s = '?';
+        switch (state) {
+          case 0b111: s = 'M'; break;
+          case 0b011: s = 'O'; break;
+          case 0b101: s = 'E'; break;
+          case 0b001: s = 'S'; break;
+          case 0b000: s = 'I'; break;
+          default:    s = 'T'; break; // @TODO add other types
+        }
+        return csprintf("state: %x (%c) valid: %d writable: %d readable: %d "
+                        "dirty: %d tag: %x data: %x", status, s, isValid(),
+                        isWritable(), isReadable(), isDirty(), tag, *data);
+    }
+
     /**
      * Handle interaction of load-locked operations and stores.
      * @return True if write should proceed, false otherwise.  Returns

src/mem/cache/cache_impl.hh

@@ -55,6 +55,7 @@
 #include "base/types.hh"
 #include "debug/Cache.hh"
 #include "debug/CachePort.hh"
+#include "debug/CacheTags.hh"
 #include "mem/cache/prefetch/base.hh"
 #include "mem/cache/blk.hh"
 #include "mem/cache/cache.hh"
@@ -278,6 +279,8 @@ bool
 Cache<TagStore>::access(PacketPtr pkt, BlkType *&blk,
                         Cycles &lat, PacketList &writebacks)
 {
+    DPRINTF(Cache, "%s for %s address %x size %d\n", __func__,
+            pkt->cmdString(), pkt->getAddr(), pkt->getSize());
     if (pkt->req->isUncacheable()) {
         uncacheableFlush(pkt);
         blk = NULL;
@@ -288,9 +291,9 @@ Cache<TagStore>::access(PacketPtr pkt, BlkType *&blk,
     int id = pkt->req->hasContextId() ? pkt->req->contextId() : -1;
     blk = tags->accessBlock(pkt->getAddr(), lat, id);
 
-    DPRINTF(Cache, "%s%s %x %s\n", pkt->cmdString(),
+    DPRINTF(Cache, "%s%s %x %s %s\n", pkt->cmdString(),
             pkt->req->isInstFetch() ? " (ifetch)" : "",
-            pkt->getAddr(), (blk) ? "hit" : "miss");
+            pkt->getAddr(), blk ? "hit" : "miss", blk ? blk->print() : "");
 
     if (blk != NULL) {
 
@@ -330,6 +333,7 @@ Cache<TagStore>::access(PacketPtr pkt, BlkType *&blk,
         }
         // nothing else to do; writeback doesn't expect response
         assert(!pkt->needsResponse());
+        DPRINTF(Cache, "%s new state is %s\n", __func__, blk->print());
         incHitCount(pkt);
         return true;
     }
@@ -360,6 +364,8 @@ template<class TagStore>
 void
 Cache<TagStore>::recvTimingSnoopResp(PacketPtr pkt)
 {
+    DPRINTF(Cache, "%s for %s address %x size %d\n", __func__,
+            pkt->cmdString(), pkt->getAddr(), pkt->getSize());
     Tick time = clockEdge(hitLatency);
 
     assert(pkt->isResponse());
@@ -391,6 +397,7 @@ template<class TagStore>
 bool
 Cache<TagStore>::recvTimingReq(PacketPtr pkt)
 {
+    DPRINTF(CacheTags, "%s tags: %s\n", __func__, tags->print());
 //@todo Add back in MemDebug Calls
 //    MemDebug::cacheAccess(pkt);
 
@@ -630,6 +637,8 @@ Cache<TagStore>::getBusPacket(PacketPtr cpu_pkt, BlkType *blk,
     PacketPtr pkt = new Packet(cpu_pkt->req, cmd, blkSize);
 
     pkt->allocate();
+    DPRINTF(Cache, "%s created %s address %x size %d\n",
+            __func__, pkt->cmdString(), pkt->getAddr(), pkt->getSize());
     return pkt;
 }
 
@@ -850,7 +859,8 @@ Cache<TagStore>::recvTimingResp(PacketPtr pkt)
                 "cmd: %s\n", pkt->getAddr(), pkt->cmdString());
     }
 
-    DPRINTF(Cache, "Handling response to %x\n", pkt->getAddr());
+    DPRINTF(Cache, "Handling response to %s for address %x\n",
+            pkt->cmdString(), pkt->getAddr());
 
     MSHRQueue *mq = mshr->queue;
     bool wasFull = mq->isFull();
@@ -959,6 +969,9 @@ Cache<TagStore>::recvTimingResp(PacketPtr pkt)
                 // propagate that.  Response should not have
                 // isInvalidate() set otherwise.
                 target->pkt->cmd = MemCmd::ReadRespWithInvalidate;
+                DPRINTF(Cache, "%s updated cmd to %s for address %x\n",
+                        __func__, target->pkt->cmdString(),
+                        target->pkt->getAddr());
             }
             // reset the bus additional time as it is now accounted for
             target->pkt->busFirstWordDelay = target->pkt->busLastWordDelay = 0;
@@ -1031,6 +1044,8 @@ Cache<TagStore>::recvTimingResp(PacketPtr pkt)
         blk->invalidate();
     }
 
+    DPRINTF(Cache, "Leaving %s with %s for address %x\n", __func__,
+            pkt->cmdString(), pkt->getAddr());
     delete pkt;
 }
 
@@ -1234,8 +1249,8 @@ Cache<TagStore>::handleFill(PacketPtr pkt, BlkType *blk,
             blk->status |= BlkDirty;
     }
 
-    DPRINTF(Cache, "Block addr %x moving from state %i to %i\n",
-            addr, old_state, blk->status);
+    DPRINTF(Cache, "Block addr %x moving from state %x to %s\n",
+            addr, old_state, blk->print());
 
     // if we got new data, copy it in
     if (pkt->isRead()) {
@@ -1261,6 +1276,8 @@ Cache<TagStore>::
 doTimingSupplyResponse(PacketPtr req_pkt, uint8_t *blk_data,
                        bool already_copied, bool pending_inval)
 {
+    DPRINTF(Cache, "%s for %s address %x size %d\n", __func__,
+            req_pkt->cmdString(), req_pkt->getAddr(), req_pkt->getSize());
     // timing-mode snoop responses require a new packet, unless we
     // already made a copy...
     PacketPtr pkt = already_copied ? req_pkt : new Packet(req_pkt);
@@ -1282,6 +1299,8 @@ doTimingSupplyResponse(PacketPtr req_pkt, uint8_t *blk_data,
         // invalidate it.
         pkt->cmd = MemCmd::ReadRespWithInvalidate;
     }
+    DPRINTF(Cache, "%s created response: %s address %x size %d\n",
+            __func__, pkt->cmdString(), pkt->getAddr(), pkt->getSize());
     memSidePort->schedTimingSnoopResp(pkt, clockEdge(hitLatency));
 }
 
@@ -1291,6 +1310,8 @@ Cache<TagStore>::handleSnoop(PacketPtr pkt, BlkType *blk,
                              bool is_timing, bool is_deferred,
                              bool pending_inval)
 {
+    DPRINTF(Cache, "%s for %s address %x size %d\n", __func__,
+            pkt->cmdString(), pkt->getAddr(), pkt->getSize());
     // deferred snoops can only happen in timing mode
     assert(!(is_deferred && !is_timing));
     // pending_inval only makes sense on deferred snoops
@@ -1336,9 +1357,15 @@ Cache<TagStore>::handleSnoop(PacketPtr pkt, BlkType *blk,
         }
     }
 
-    if (!blk || !blk->isValid()) {
-        return;
-    }
+     if (!blk || !blk->isValid()) {
+         DPRINTF(Cache, "%s snoop miss for %s address %x size %d\n",
+                 __func__, pkt->cmdString(), pkt->getAddr(), pkt->getSize());
+         return;
+     } else {
+        DPRINTF(Cache, "%s snoop hit for %s for address %x size %d, "
+                "old state is %s\n", __func__, pkt->cmdString(),
+                pkt->getAddr(), pkt->getSize(), blk->print());
+     }
 
     // we may end up modifying both the block state and the packet (if
     // we respond in atomic mode), so just figure out what to do now
@@ -1360,10 +1387,6 @@ Cache<TagStore>::handleSnoop(PacketPtr pkt, BlkType *blk,
         blk->status &= ~bits_to_clear;
     }
 
-    DPRINTF(Cache, "snooped a %s request for addr %x, %snew state is %i\n",
-            pkt->cmdString(), blockAlign(pkt->getAddr()),
-            respond ? "responding, " : "", invalidate ? 0 : blk->status);
-
     if (respond) {
         assert(!pkt->memInhibitAsserted());
         pkt->assertMemInhibit();
@@ -1390,6 +1413,8 @@ Cache<TagStore>::handleSnoop(PacketPtr pkt, BlkType *blk,
         tags->invalidate(blk);
         blk->invalidate();
     }
+
+    DPRINTF(Cache, "new state is %s\n", blk->print());
 }
 
 
@@ -1397,6 +1422,9 @@ template<class TagStore>
 void
 Cache<TagStore>::recvTimingSnoopReq(PacketPtr pkt)
 {
+    DPRINTF(Cache, "%s for %s address %x size %d\n", __func__,
+            pkt->cmdString(), pkt->getAddr(), pkt->getSize());
+
     // Snoops shouldn't happen when bypassing caches
     assert(!system->bypassCaches());
 
@@ -1417,8 +1445,9 @@ Cache<TagStore>::recvTimingSnoopReq(PacketPtr pkt)
     // Let the MSHR itself track the snoop and decide whether we want
     // to go ahead and do the regular cache snoop
     if (mshr && mshr->handleSnoop(pkt, order++)) {
-        DPRINTF(Cache, "Deferring snoop on in-service MSHR to blk %x\n",
-                blk_addr);
+        DPRINTF(Cache, "Deferring snoop on in-service MSHR to blk %x."
+                "mshrs: %s\n", blk_addr, mshr->print());
+
         if (mshr->getNumTargets() > numTarget)
             warn("allocating bonus target for snoop"); //handle later
         return;
@@ -1598,6 +1627,9 @@ Cache<TagStore>::getTimingPacket()
     PacketPtr tgt_pkt = mshr->getTarget()->pkt;
     PacketPtr pkt = NULL;
 
+    DPRINTF(CachePort, "%s %s for address %x size %d\n", __func__,
+            tgt_pkt->cmdString(), tgt_pkt->getAddr(), tgt_pkt->getSize());
+
     if (tgt_pkt->cmd == MemCmd::SCUpgradeFailReq ||
         tgt_pkt->cmd == MemCmd::StoreCondFailReq) {
         // SCUpgradeReq or StoreCondReq saw invalidation while queued

src/mem/cache/mshr.cc

@@ -1,4 +1,16 @@
 /*
+ * Copyright (c) 2012 ARM Limited
+ * All rights reserved.
+ *
+ * The license below extends only to copyright in the software and shall
+ * not be construed as granting a license to any other intellectual
+ * property including but not limited to intellectual property relating
+ * to a hardware implementation of the functionality of the software
+ * licensed hereunder.  You may use the software subject to the license
+ * terms below provided that you ensure that this notice is replicated
+ * unmodified and in its entirety in all distributions of the software,
+ * modified or unmodified, in source code or in binary form.
+ *
  * Copyright (c) 2002-2005 The Regents of The University of Michigan
  * Copyright (c) 2010 Advanced Micro Devices, Inc.
  * All rights reserved.
@@ -303,6 +315,8 @@ MSHR::allocateTarget(PacketPtr pkt, Tick whenReady, Counter _order)
 bool
 MSHR::handleSnoop(PacketPtr pkt, Counter _order)
 {
+    DPRINTF(Cache, "%s for %s address %x size %d\n", __func__,
+            pkt->cmdString(), pkt->getAddr(), pkt->getSize());
     if (!inService || (pkt->isExpressSnoop() && downstreamPending)) {
         // Request has not been issued yet, or it's been issued
         // locally but is buffered unissued at some downstream cache
@@ -467,6 +481,14 @@ MSHR::print(std::ostream &os, int verbosity, const std::string &prefix) const
     }
 }
 
+std::string
+MSHR::print() const
+{
+    ostringstream str;
+    print(str);
+    return str.str();
+}
+
 MSHR::~MSHR()
 {
     delete[] targets;

src/mem/cache/mshr.hh

@@ -1,4 +1,16 @@
 /*
+ * Copyright (c) 2012 ARM Limited
+ * All rights reserved.
+ *
+ * The license below extends only to copyright in the software and shall
+ * not be construed as granting a license to any other intellectual
+ * property including but not limited to intellectual property relating
+ * to a hardware implementation of the functionality of the software
+ * licensed hereunder.  You may use the software subject to the license
+ * terms below provided that you ensure that this notice is replicated
+ * unmodified and in its entirety in all distributions of the software,
+ * modified or unmodified, in source code or in binary form.
+ *
  * Copyright (c) 2002-2005 The Regents of The University of Michigan
  * All rights reserved.
  *
@@ -279,6 +291,13 @@ public:
     void print(std::ostream &os,
                int verbosity = 0,
                const std::string &prefix = "") const;
+    /**
+     * A no-args wrapper of print(std::ostream...)  meant to be
+     * invoked from DPRINTFs avoiding string overheads in fast mode
+     *
+     * @return string with mshr fields + [deferred]targets
+     */
+    std::string print() const;
 };
 
 #endif //__MSHR_HH__

src/mem/cache/tags/base.hh

@@ -159,6 +159,11 @@ class BaseTags
      *Needed to clear all lock tracking at once
      */
     virtual void clearLocks() {}
+
+    /**
+     * Print all tags used
+     */
+    virtual std::string print() const = 0;
 };
 
 class BaseTagsCallback : public Callback

src/mem/cache/tags/fa_lru.hh

@@ -300,6 +300,11 @@ public:
      */
     virtual void clearLocks();
 
+    /**
+     * @todo Implement as in lru. Currently not used
+     */
+    virtual std::string print() const { return ""; }
+
     /**
      * Visit each block in the tag store and apply a visitor to the
      * block.

src/mem/cache/tags/lru.cc

@@ -1,4 +1,16 @@
 /*
+ * Copyright (c) 2012 ARM Limited
+ * All rights reserved.
+ *
+ * The license below extends only to copyright in the software and shall
+ * not be construed as granting a license to any other intellectual
+ * property including but not limited to intellectual property relating
+ * to a hardware implementation of the functionality of the software
+ * licensed hereunder.  You may use the software subject to the license
+ * terms below provided that you ensure that this notice is replicated
+ * unmodified and in its entirety in all distributions of the software,
+ * modified or unmodified, in source code or in binary form.
+ *
  * Copyright (c) 2003-2005 The Regents of The University of Michigan
  * All rights reserved.
  *
@@ -36,6 +48,7 @@
 #include <string>
 
 #include "base/intmath.hh"
+#include "debug/Cache.hh"
 #include "debug/CacheRepl.hh"
 #include "mem/cache/tags/cacheset.hh"
 #include "mem/cache/tags/lru.hh"
@@ -226,6 +239,23 @@ LRU::clearLocks()
     }
 }
 
+std::string
+LRU::print() const {
+    std::string cache_state;
+    for (unsigned i = 0; i < numSets; ++i) {
+        // link in the data blocks
+        for (unsigned j = 0; j < assoc; ++j) {
+            BlkType *blk = sets[i].blks[j];
+            if (blk->isValid())
+                cache_state += csprintf("\tset: %d block: %d %s\n", i, j,
+                        blk->print());
+        }
+    }
+    if (cache_state.empty())
+        cache_state = "no valid tags\n";
+    return cache_state;
+}
+
 void
 LRU::cleanupRefs()
 {

src/mem/cache/tags/lru.hh

@@ -248,6 +248,11 @@ public:
      */
     virtual void cleanupRefs();
 
+    /**
+     * Print all tags used
+     */
+    virtual std::string print() const;
+
     /**
      * Visit each block in the tag store and apply a visitor to the
      * block.

src/mem/coherent_bus.cc

@@ -337,6 +337,9 @@ CoherentBus::recvTimingSnoopResp(PacketPtr pkt, PortID slave_port_id)
 void
 CoherentBus::forwardTiming(PacketPtr pkt, PortID exclude_slave_port_id)
 {
+    DPRINTF(CoherentBus, "%s for %s address %x size %d\n", __func__,
+            pkt->cmdString(), pkt->getAddr(), pkt->getSize());
+
     // snoops should only happen if the system isn't bypassing caches
     assert(!system->bypassCaches());
 

src/mem/packet.cc

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2011 ARM Limited
+ * Copyright (c) 2011-2012 ARM Limited
  * All rights reserved
  *
  * The license below extends only to copyright in the software and shall
@@ -340,6 +340,13 @@ Packet::print(ostream &o, const int verbosity, const string &prefix) const
              getAddr(), getAddr() + getSize() - 1, cmdString());
 }
 
+std::string
+Packet::print() const {
+    ostringstream str;
+    print(str);
+    return str.str();
+}
+
 Packet::PrintReqState::PrintReqState(ostream &_os, int _verbosity)
     : curPrefixPtr(new string("")), os(_os), verbosity(_verbosity)
 {

src/mem/packet.hh

@@ -923,6 +923,14 @@ class Packet : public Printable
 
     void print(std::ostream &o, int verbosity = 0,
                const std::string &prefix = "") const;
+
+    /**
+     * A no-args wrapper of print(std::ostream...)
+     * meant to be invoked from DPRINTFs
+     * avoiding string overheads in fast mode
+     * @return string with the request's type and start<->end addresses
+     */
+    std::string print() const;
 };
 
 #endif //__MEM_PACKET_HH

src/mem/packet_queue.cc

@@ -107,6 +107,8 @@ PacketQueue::schedSendEvent(Tick when)
 void
 PacketQueue::schedSendTiming(PacketPtr pkt, Tick when, bool send_as_snoop)
 {
+    DPRINTF(PacketQueue, "%s for %s address %x size %d\n", __func__,
+            pkt->cmdString(), pkt->getAddr(), pkt->getSize());
     // we can still send a packet before the end of this tick
     assert(when >= curTick());