Bug 1368837 - Convert printfs into MOZ_LOG(MediaResourceIndex) - r=cpearce draft
authorGerald Squelart <gsquelart@mozilla.com>
Tue, 30 May 2017 14:12:38 +1200
changeset 587485 36ddeabe3ab5b0982c43ad2522593f90d8d38148
parent 587484 9a37fffdef77cf56200ca1c595d47d200b252a14
child 631282 e8dd8475b223d5ffd08b5331f1c72472703b3ef4
push id61722
push usergsquelart@mozilla.com
push dateThu, 01 Jun 2017 04:10:47 +0000
reviewerscpearce
bugs1368837
milestone55.0a1
Bug 1368837 - Convert printfs into MOZ_LOG(MediaResourceIndex) - r=cpearce MozReview-Commit-ID: Bhi1vxDPwDV
dom/media/MediaResource.cpp
dom/media/MediaResource.h
--- a/dom/media/MediaResource.cpp
+++ b/dom/media/MediaResource.cpp
@@ -30,22 +30,30 @@
 #include "nsHostObjectProtocolHandler.h"
 #include <algorithm>
 #include "nsProxyRelease.h"
 #include "nsIContentPolicy.h"
 
 using mozilla::media::TimeUnit;
 
 #undef LOG
+#undef ILOG
 
 mozilla::LazyLogModule gMediaResourceLog("MediaResource");
 // Debug logging macro with object pointer and class name.
 #define LOG(msg, ...) MOZ_LOG(gMediaResourceLog, mozilla::LogLevel::Debug, \
   ("%p " msg, this, ##__VA_ARGS__))
 
+mozilla::LazyLogModule gMediaResourceIndexLog("MediaResourceIndex");
+// Debug logging macro with object pointer and class name.
+#define ILOG(msg, ...)                                                         \
+  MOZ_LOG(gMediaResourceIndexLog,                                              \
+          mozilla::LogLevel::Debug,                                            \
+          ("%p " msg, this, ##__VA_ARGS__))
+
 static const uint32_t HTTP_OK_CODE = 200;
 static const uint32_t HTTP_PARTIAL_RESPONSE_CODE = 206;
 
 namespace mozilla {
 
 void
 MediaResource::Destroy()
 {
@@ -1638,17 +1646,17 @@ MediaResourceIndex::Read(char* aBuffer, 
   nsresult rv = ReadAt(mOffset, aBuffer, aCount, aBytes);
   if (NS_FAILED(rv)) {
     return rv;
   }
   mOffset += *aBytes;
   return NS_OK;
 }
 
-nsCString
+static nsCString
 ResultName(nsresult aResult)
 {
   nsCString name;
   GetErrorName(aResult, name);
   return name;
 }
 
 nsresult
@@ -1656,25 +1664,19 @@ MediaResourceIndex::ReadAt(int64_t aOffs
                            char* aBuffer,
                            uint32_t aCount,
                            uint32_t* aBytes)
 {
   if (mCacheBlockSize == 0) {
     return UncachedReadAt(aOffset, aBuffer, aCount, aBytes);
   }
 
-  const int oOffset = int(aOffset);
-  const unsigned oCount = unsigned(aCount);
   *aBytes = 0;
 
   if (aCount == 0) {
-    printf("**** [%p]ReadAt(%u@%d) - aCount==0 -> NS_OK, 0\n",
-           this,
-           oCount,
-           oOffset);
     return NS_OK;
   }
 
   const int64_t endOffset = aOffset + aCount;
   const int64_t lastBlockOffset = CacheOffsetContaining(endOffset - 1);
 
   if (mCachedBytes != 0 && mCachedOffset + mCachedBytes >= aOffset &&
       mCachedOffset < endOffset) {
@@ -1683,173 +1685,164 @@ MediaResourceIndex::ReadAt(int64_t aOffs
     if (aOffset < mCachedOffset) {
       // We need to read before the cached data.
       const uint32_t toRead = uint32_t(mCachedOffset - aOffset);
       MOZ_ASSERT(toRead > 0);
       MOZ_ASSERT(toRead < aCount);
       uint32_t read = 0;
       nsresult rv = UncachedReadAt(aOffset, aBuffer, toRead, &read);
       if (NS_FAILED(rv)) {
-        printf("**** [%p]ReadAt(%u@%d) uncached read before cache -> %s\n",
-               this,
-               oCount,
-               oOffset,
-               ResultName(rv).get());
+        ILOG("ReadAt(%" PRIu32 "@%" PRId64
+             ") uncached read before cache -> %s, %" PRIu32,
+             aCount,
+             aOffset,
+             ResultName(rv).get(),
+             *aBytes);
         return rv;
       }
       *aBytes = read;
       if (read < toRead) {
         // Could not read everything we wanted, we're done.
-        printf("**** [%p]ReadAt(%u@%d) uncached read before cache, incomplete "
-               "-> OK, %u\n",
-               this,
-               oCount,
-               oOffset,
-               unsigned(*aBytes));
+        ILOG("ReadAt(%" PRIu32 "@%" PRId64
+             ") uncached read before cache, incomplete -> OK, %" PRIu32,
+             aCount,
+             aOffset,
+             *aBytes);
         return NS_OK;
       }
+      ILOG("ReadAt(%" PRIu32 "@%" PRId64
+           ") uncached read before cache: %" PRIu32 ", remaining: %" PRIu32
+           "@%" PRId64 "...",
+           aCount,
+           aOffset,
+           read,
+           aCount - read,
+           aOffset + read);
       aOffset += read;
       aBuffer += read;
       aCount -= read;
-      printf("**** [%p]ReadAt(%u@%d) uncached read before cache: %u, "
-             "remaining: %u@%d\n",
-             this,
-             oCount,
-             oOffset,
-             unsigned(read),
-             unsigned(aCount),
-             int(aOffset));
       // We should have reached the cache.
       MOZ_ASSERT(aOffset == mCachedOffset);
     }
     MOZ_ASSERT(aOffset >= mCachedOffset);
 
     // We've reached our cache.
     const uint32_t toCopy =
       std::min(aCount, uint32_t(mCachedOffset + mCachedBytes - aOffset));
     // Note that we could in fact be just after the last byte of the cache, in
     // which case we can't actually read from it! (But we will top-up next.)
     if (toCopy != 0) {
       memcpy(aBuffer, &mCachedBlock[IndexInCache(aOffset)], toCopy);
       *aBytes += toCopy;
       aCount -= toCopy;
       if (aCount == 0) {
         // All done!
-        printf("**** [%p]ReadAt(%u@%d) copied from cache(%u@%d) and done :-) "
-               "-> OK, %u\n",
-               this,
-               oCount,
-               oOffset,
-               unsigned(mCachedBytes),
-               int(mCachedOffset),
-               unsigned(*aBytes));
+        ILOG("ReadAt(%" PRIu32 "@%" PRId64 ") copied everything (%" PRIu32
+             ") from cache(%" PRIu32 "@%" PRId64 ") :-D -> OK, %" PRIu32,
+             aCount,
+             aOffset,
+             toCopy,
+             mCachedBytes,
+             mCachedOffset,
+             *aBytes);
         return NS_OK;
       }
       aOffset += toCopy;
       aBuffer += toCopy;
-      printf("**** [%p]ReadAt(%u@%d) copied %u from cache(%u@%d) :-), "
-             "remaining: %u@%d\n",
-             this,
-             oCount,
-             oOffset,
-             unsigned(toCopy),
-             unsigned(mCachedBytes),
-             int(mCachedOffset),
-             unsigned(aCount),
-             int(aOffset));
+      ILOG("ReadAt(%" PRIu32 "@%" PRId64 ") copied %" PRIu32
+           " from cache(%" PRIu32 "@%" PRId64 ") :-), remaining: %" PRIu32
+           "@%" PRId64 "...",
+           aCount + toCopy,
+           aOffset - toCopy,
+           toCopy,
+           mCachedBytes,
+           mCachedOffset,
+           aCount,
+           aOffset);
     }
 
     if (aOffset - 1 >= lastBlockOffset) {
       // We were already reading cached data from the last block, we need more
       // from it -> try to top-up, read what we can, and we'll be done.
       MOZ_ASSERT(aOffset == mCachedOffset + mCachedBytes);
       MOZ_ASSERT(endOffset <= lastBlockOffset + mCacheBlockSize);
-      return CacheOrReadAt(
-        oOffset, oCount, "top-up cache", aOffset, aBuffer, aCount, aBytes);
+      return CacheOrReadAt(aOffset, aBuffer, aCount, aBytes);
     }
 
     // We were not in the last block (but we may just have crossed the line now)
     MOZ_ASSERT(aOffset <= lastBlockOffset);
     // Continue below...
   } else if (aOffset >= lastBlockOffset) {
     // There was nothing we could get from the cache.
     // But we're already in the last block -> Cache or read what we can.
     // Make sure to invalidate the cache first.
     mCachedBytes = 0;
-    return CacheOrReadAt(
-      oOffset, oCount, "nothing in cache", aOffset, aBuffer, aCount, aBytes);
+    return CacheOrReadAt(aOffset, aBuffer, aCount, aBytes);
   }
 
   // If we're here, either there was nothing usable in the cache, or we've just
   // read what was in the cache but there's still more to read.
 
   if (aOffset < lastBlockOffset) {
     // We need to read before the last block.
     // Start with an uncached read up to the last block.
     const uint32_t toRead = uint32_t(lastBlockOffset - aOffset);
     MOZ_ASSERT(toRead > 0);
     MOZ_ASSERT(toRead < aCount);
     uint32_t read = 0;
     nsresult rv = UncachedReadAt(aOffset, aBuffer, toRead, &read);
     if (NS_FAILED(rv)) {
-      printf(
-        "**** [%p]ReadAt(%u@%d) uncached read before last block failed -> %s\n",
-        this,
-        oCount,
-        oOffset,
-        ResultName(rv).get());
+      ILOG("ReadAt(%" PRIu32 "@%" PRId64
+           ") uncached read before last block failed -> %s, %" PRIu32,
+           aCount,
+           aOffset,
+           ResultName(rv).get(),
+           *aBytes);
       return rv;
     }
     if (read == 0) {
-      printf(
-        "**** [%p]ReadAt(%u@%d) uncached read 0 before last block -> OK, %u\n",
-        this,
-        oCount,
-        oOffset,
-        unsigned(*aBytes));
+      ILOG("ReadAt(%" PRIu32 "@%" PRId64
+           ") uncached read 0 before last block -> OK, %" PRIu32,
+           aCount,
+           aOffset,
+           *aBytes);
       return NS_OK;
     }
     *aBytes += read;
     if (read < toRead) {
       // Could not read everything we wanted, we're done.
-      printf("**** [%p]ReadAt(%u@%d) uncached read before last block, "
-             "incomplete -> OK, %u\n",
-             this,
-             oCount,
-             oOffset,
-             unsigned(*aBytes));
+      ILOG("ReadAt(%" PRIu32 "@%" PRId64
+           ") uncached read before last block, incomplete -> OK, %" PRIu32,
+           aCount,
+           aOffset,
+           *aBytes);
       return NS_OK;
     }
+    ILOG("ReadAt(%" PRIu32 "@%" PRId64 ") read %" PRIu32
+         " before last block, remaining: %" PRIu32 "@%" PRId64 "...",
+         aCount,
+         aOffset,
+         read,
+         aCount - read,
+         aOffset + read);
     aOffset += read;
     aBuffer += read;
     aCount -= read;
-    printf(
-      "**** [%p]ReadAt(%u@%d) read %u before last block, remaining: %u@%d\n",
-      this,
-      oCount,
-      oOffset,
-      unsigned(read),
-      unsigned(aCount),
-      int(aOffset));
   }
 
   // We should just have reached the start of the last block.
   MOZ_ASSERT(aOffset == lastBlockOffset);
   MOZ_ASSERT(aCount <= mCacheBlockSize);
   // Make sure to invalidate the cache first.
   mCachedBytes = 0;
-  return CacheOrReadAt(
-    oOffset, oCount, "last block", aOffset, aBuffer, aCount, aBytes);
+  return CacheOrReadAt(aOffset, aBuffer, aCount, aBytes);
 }
 
 nsresult
-MediaResourceIndex::CacheOrReadAt(int oOffset,
-                                  unsigned oCount,
-                                  const char* oContext,
-                                  int64_t aOffset,
+MediaResourceIndex::CacheOrReadAt(int64_t aOffset,
                                   char* aBuffer,
                                   uint32_t aCount,
                                   uint32_t* aBytes)
 {
   // We should be here because there is more data to read.
   MOZ_ASSERT(aCount > 0);
   // We should be in the last block, so we shouldn't try to read past it.
   MOZ_ASSERT(IndexInCache(aOffset) + aCount <= mCacheBlockSize);
@@ -1870,104 +1863,101 @@ MediaResourceIndex::CacheOrReadAt(int oO
       const uint32_t toRead =
         uint32_t(std::min(cachedDataEnd - aOffset,
                           int64_t(mCacheBlockSize - cacheIndex)));
       MOZ_ASSERT(toRead >= aCount);
       nsresult rv =
         mResource->ReadFromCache(&mCachedBlock[cacheIndex], aOffset, toRead);
       if (NS_SUCCEEDED(rv)) {
         // Success means we have read the full `toRead` amount.
-        printf("**** [%p]ReadAt(%u@%d) - %s - ReadFromCache(%u@%d) succeeded\n",
-               this,
-               oCount,
-               oOffset,
-               oContext,
-               unsigned(toRead),
-               int(aOffset));
         if (mCachedOffset + mCachedBytes == aOffset) {
           // We were topping-up the cache, just update its size.
+          ILOG("ReadAt(%" PRIu32 "@%" PRId64 ") - ReadFromCache(%" PRIu32
+               "@%" PRId64 ") to top-up succeeded...",
+               aCount,
+               aOffset,
+               toRead,
+               aOffset);
           mCachedBytes += toRead;
         } else {
           // We were filling the cache from scratch, save new cache information.
+          ILOG("ReadAt(%" PRIu32 "@%" PRId64 ") - ReadFromCache(%" PRIu32
+               "@%" PRId64 ") to fill cache succeeded...",
+               aCount,
+               aOffset,
+               toRead,
+               aOffset);
           mCachedOffset = aOffset;
           mCachedBytes = toRead;
         }
         // Copy relevant part into output.
         memcpy(aBuffer, &mCachedBlock[cacheIndex], aCount);
         *aBytes += aCount;
-        printf("**** [%p]ReadAt(%u@%d) - %s - copied %u@%d, remaining: %u@%d "
-               "-> OK, %u\n",
-               this,
-               oCount,
-               oOffset,
-               oContext,
-               unsigned(aCount),
-               int(aOffset),
-               unsigned(aCount),
-               int(aOffset),
-               unsigned(*aBytes));
+        ILOG("ReadAt(%" PRIu32 "@%" PRId64 ") - copied %" PRIu32 "@%" PRId64
+             " -> OK, %" PRIu32,
+             aCount,
+             aOffset,
+             aCount,
+             aOffset,
+             *aBytes);
         // We may not have read all that was requested, but we got everything
         // we could get, so we're done.
         return NS_OK;
       }
-      printf("**** [%p]ReadAt(%u@%d) - %s - ReadFromCache(%u@%d) failed: %s, "
-             "will fallback to blocking read\n",
-             this,
-             oCount,
-             oOffset,
-             oContext,
-             unsigned(toRead),
-             int(aOffset),
-             ResultName(rv).get());
+      ILOG("ReadAt(%" PRIu32 "@%" PRId64 ") - ReadFromCache(%" PRIu32
+           "@%" PRId64 ") failed: %s, will fallback to blocking read...",
+           aCount,
+           aOffset,
+           toRead,
+           aOffset,
+           ResultName(rv).get());
       // Failure during reading. Note that this may be due to the cache
       // changing between `GetCachedDataEnd` and `ReadFromCache`, so it's not
       // totally unexpected, just hopefully rare; but we do need to handle it.
 
       // Invalidate part of cache that may have been partially overridden.
       if (mCachedOffset + mCachedBytes == aOffset) {
         // We were topping-up the cache, just keep the old untouched data.
         // (i.e., nothing to do here.)
       } else {
         // We were filling the cache from scratch, invalidate cache.
         mCachedBytes = 0;
       }
     } else {
-      printf("**** [%p]ReadAt(%u@%d) - %s - no cached data, will fallback to "
-             "blocking read\n",
-             this,
-             oCount,
-             oOffset,
-             oContext);
+      ILOG("ReadAt(%" PRIu32 "@%" PRId64
+           ") - no cached data, will fallback to blocking read...",
+           aCount,
+           aOffset);
     }
   } else {
-    printf("**** [%p]ReadAt(%u@%d) - %s - length is known and too short(!), "
-           "will fallback to blocking read as the caller requested\n",
-           this,
-           oCount,
-           oOffset,
-           oContext);
+    ILOG("ReadAt(%" PRIu32 "@%" PRId64 ") - length is %" PRId64
+         " (%s), will fallback to blocking read as the caller requested...",
+         aCount,
+         aOffset,
+         length,
+         length < 0 ? "unknown" : "too short!");
   }
   uint32_t read = 0;
   nsresult rv = UncachedReadAt(aOffset, aBuffer, aCount, &read);
   if (NS_SUCCEEDED(rv)) {
-    printf("**** [%p]ReadAt(%u@%d) - %s - fallback uncached read -> %s, %u\n",
-           this,
-           oCount,
-           oOffset,
-           oContext,
-           ResultName(rv).get(),
-           unsigned(read));
     *aBytes += read;
+    ILOG("ReadAt(%" PRIu32 "@%" PRId64 ") - fallback uncached read got %" PRIu32
+         " bytes -> %s, %" PRIu32,
+         aCount,
+         aOffset,
+         read,
+         ResultName(rv).get(),
+         *aBytes);
   } else {
-    printf("**** [%p]ReadAt(%u@%d) - %s - fallback uncached read -> %s\n",
-           this,
-           oCount,
-           oOffset,
-           oContext,
-           ResultName(rv).get());
+    ILOG("ReadAt(%" PRIu32 "@%" PRId64
+         ") - fallback uncached read failed -> %s, %" PRIu32,
+         aCount,
+         aOffset,
+         ResultName(rv).get(),
+         *aBytes);
   }
   return rv;
 }
 
 nsresult
 MediaResourceIndex::UncachedReadAt(int64_t aOffset,
                                    char* aBuffer,
                                    uint32_t aCount,
@@ -2022,8 +2012,9 @@ MediaResourceIndex::Seek(int32_t aWhence
 
   return NS_OK;
 }
 
 } // namespace mozilla
 
 // avoid redefined macro in unified build
 #undef LOG
+#undef ILOG
--- a/dom/media/MediaResource.h
+++ b/dom/media/MediaResource.h
@@ -853,20 +853,17 @@ public:
   int64_t GetLength() const { return mResource->GetLength(); }
 
 private:
   // If the resource has cached data past the requested range, try to grab it
   // into our local cache.
   // If there is no cached data, or attempting to read it fails, fallback on
   // a (potentially-blocking) read of just what was requested, so that we don't
   // get unexpected side-effects by trying to read more than intended.
-  nsresult CacheOrReadAt(int oOffset,
-                         unsigned oCount,
-                         const char* oContext,
-                         int64_t aOffset,
+  nsresult CacheOrReadAt(int64_t aOffset,
                          char* aBuffer,
                          uint32_t aCount,
                          uint32_t* aBytes);
 
   // Select the next power of 2 (in range 32B-128KB, or 0 -> no cache)
   static uint32_t SelectCacheSize(uint32_t aHint)
   {
     if (aHint == 0) {