Print gpu/cache stats from DM.

dm/DM.cpp

 #include "CrashHandler.h"
 #include "DMJsonWriter.h"
 #include "DMSrcSink.h"
 #include "OverwriteLine.h"
 #include "ProcStats.h"
 #include "SkBBHFactory.h"
 #include "SkChecksum.h"
 #include "SkCommonFlags.h"
 #include "SkForceLinking.h"
 #include "SkGraphics.h"
@@ skipping 30 matching lines @@
 static SkTArray<SkString> gFailures;
 
 static void fail(ImplicitString err) {
     SkAutoMutexAcquire lock(gFailuresMutex);
     SkDebugf("\n\nFAILURE: %s\n\n", err.c_str());
     gFailures.push_back(err);
 }
 
 static int32_t gPending = 0;  // Atomic.
 
-static void done(double ms, ImplicitString config, ImplicitString src, ImplicitString name) {
+static void done(double ms, ImplicitString config, ImplicitString src, ImplicitString name,
+                 ImplicitString verboseLog) {
     int32_t pending = sk_atomic_dec(&gPending)-1;
     SkDebugf("%s(%4dMB %5d) %s\t%s %s %s  ", FLAGS_verbose ? "\n" : kSkOverwriteLine

[mtklein, 2015/02/02 16:23:17]

I think you'll have a better time if we log everything from one SkDebugf call. 
On most platforms, SkDebugf is synchronized so that single calls print out
atomically.   But there'll definitely be no guarantee that your two SkDebugf
here will print sequentially.

                                            , sk_tools::getMaxResidentSetSizeMB()
                                            , pending
                                            , HumanizeMs(ms).c_str()
                                            , config.c_str()
                                            , src.c_str()
                                            , name.c_str());
+    if (FLAGS_verbose && !verboseLog.isEmpty()) {
+        SkDebugf("\n%s", verboseLog.c_str());
+    }
     // We write our dm.json file every once in a while in case we crash.
     // Notice this also handles the final dm.json when pending == 0.
     if (pending % 500 == 0) {
         JsonWriter::DumpJson();
     }
 }
 
 /*~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~*/
 
 struct Gold : public SkString {
@@ skipping 273 matching lines @@
                     SkASSERT(bitmap.drawsNothing());
                 } else if (!bitmap.drawsNothing()) {
                     WriteToDisk(*task, md5, ext, NULL, 0, &bitmap);
                 }
             }
         }
         timer.end();
         if (!whyBlacklisted.isEmpty()) {
             name.appendf(" (--blacklist, %s)", whyBlacklisted.c_str());
         }
-        done(timer.fWall, task->sink.tag, task->src.tag, name);
+        done(timer.fWall, task->sink.tag, task->src.tag, name, task->sink->verboseLog());
     }
 
     static void WriteToDisk(const Task& task,
                             SkString md5,
                             const char* ext,
                             SkStream* data, size_t len,
                             const SkBitmap* bitmap) {
         JsonWriter::BitmapResult result;
         result.name       = task.src->name();
         result.config     = task.sink.tag;
@@ skipping 100 matching lines @@
         }
         bool verbose() const SK_OVERRIDE { return FLAGS_veryVerbose; }
     } reporter;
     WallTimer timer;
     timer.start();
     if (!FLAGS_dryRun) {
         GrContextFactory factory;
         test->proc(&reporter, &factory);
     }
     timer.end();
-    done(timer.fWall, "unit", "test", test->name);
+    done(timer.fWall, "unit", "test", test->name, "");
 }
 
 /*~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~*/
 
 // If we're isolating all GPU-bound work to one thread (the default), this function runs all that.
 static void run_enclave_and_gpu_tests(SkTArray<Task>* tasks) {
     run_enclave(tasks);
     for (int i = 0; i < gGPUTests.count(); i++) {
         run_test(&gGPUTests[i]);
     }
@@ skipping 59 matching lines @@
     }
     return 0;
 }
 
 #if !defined(SK_BUILD_FOR_IOS) && !defined(SK_BUILD_FOR_NACL)
 int main(int argc, char** argv) {
     SkCommandLineFlags::Parse(argc, argv);
     return dm_main();
 }
 #endif