Rethink DM output

dm/DM.cpp

 /*
  * Copyright 2013 Google Inc.
  *
  * Use of this source code is governed by a BSD-style license that can be
  * found in the LICENSE file.
  */
 
 #include "CrashHandler.h"
 #include "DMJsonWriter.h"
 #include "DMSrcSink.h"
 #include "DMSrcSinkAndroid.h"
-#include "OverwriteLine.h"
 #include "ProcStats.h"
 #include "SkBBHFactory.h"
 #include "SkChecksum.h"
 #include "SkCodec.h"
 #include "SkCommonFlags.h"
 #include "SkCommonFlagsConfig.h"
 #include "SkFontMgr.h"
 #include "SkForceLinking.h"
 #include "SkGraphics.h"
 #include "SkMD5.h"
@@ skipping 52 matching lines @@
 
 SK_DECLARE_STATIC_MUTEX(gFailuresMutex);
 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.  Total number of running and queued tasks.
 
 // We use a spinlock to make locking this in a signal handler _somewhat_ safe.
-SK_DECLARE_STATIC_SPINLOCK(gRunningAndTallyMutex);
+SK_DECLARE_STATIC_SPINLOCK(gMutex);
+static int32_t                   gPending;
 static SkTArray<SkString>        gRunning;
 static SkTHashMap<SkString, int> gNoteTally;
 
 static void done(double ms,
                  ImplicitString config, ImplicitString src, ImplicitString srcOptions,
                  ImplicitString name, ImplicitString note, ImplicitString log) {
     SkString id = SkStringPrintf("%s %s %s %s", config.c_str(), src.c_str(),
                                                 srcOptions.c_str(), name.c_str());
+    int pending;
     {
-        SkAutoTAcquire<SkPODSpinlock> lock(gRunningAndTallyMutex);
+        SkAutoTAcquire<SkPODSpinlock> lock(gMutex);
         for (int i = 0; i < gRunning.count(); i++) {
             if (gRunning[i] == id) {
                 gRunning.removeShuffle(i);
                 break;
             }
         }
         if (!note.isEmpty()) {
             if (int* tally = gNoteTally.find(note)) {
                 *tally += 1;
             } else {
                 gNoteTally.set(note, 1);
             }
         }
-    }
-    if (!log.isEmpty()) {
-        log.prepend("\n");
-    }
-    auto pending = sk_atomic_dec(&gPending)-1;
-    if (!FLAGS_quiet && note.isEmpty()) {
-        SkDebugf("%s(%4d/%-4dMB %6d) %s\t%s%s", FLAGS_verbose ? "\n" : kSkOverwriteLine
-                                           , sk_tools::getCurrResidentSetSizeMB()
-                                           , sk_tools::getMaxResidentSetSizeMB()
-                                           , pending
-                                           , HumanizeMs(ms).c_str()
-                                           , id.c_str()
-                                           , log.c_str());
+        pending = --gPending;
     }
     // 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();
     }
 }
 
 static void start(ImplicitString config, ImplicitString src,
                   ImplicitString srcOptions, ImplicitString name) {
     SkString id = SkStringPrintf("%s %s %s %s", config.c_str(), src.c_str(),
                                                 srcOptions.c_str(), name.c_str());
-    SkAutoTAcquire<SkPODSpinlock> lock(gRunningAndTallyMutex);
+    SkAutoTAcquire<SkPODSpinlock> lock(gMutex);
     gRunning.push_back(id);
 }
 
+static void print_status() {
+    static SkMSec start_ms = SkTime::GetMSecs();
+
+    int curr = sk_tools::getCurrResidentSetSizeMB(),
+        peak = sk_tools::getMaxResidentSetSizeMB();
+    SkString elapsed = HumanizeMs(SkTime::GetMSecs() - start_ms);
+
+    SkAutoTAcquire<SkPODSpinlock> lock(gMutex);
+    SkDebugf("\n%s elapsed, %d active, %d queued, %dMB RAM, %dMB peak\n",
+             elapsed.c_str(), gRunning.count(), gPending - gRunning.count(), curr, peak);
+    for (auto& task : gRunning) {
+        SkDebugf("\t%s\n", task.c_str());
+    }
+}
+
 #if defined(SK_BUILD_FOR_WIN32)
     static void setup_crash_handler() {
         // TODO: custom crash handler like below to print out what was running
         SetupCrashHandler();
     }
 
 #else
     #include <signal.h>
     static void setup_crash_handler() {
         const int kSignals[] = { SIGABRT, SIGBUS, SIGFPE, SIGILL, SIGSEGV };
         for (int sig : kSignals) {
             signal(sig, [](int sig) {
-                SkAutoTAcquire<SkPODSpinlock> lock(gRunningAndTallyMutex);
-                SkDebugf("\nCaught signal %d [%s] while running %d tasks:\n",
-                         sig, strsignal(sig), gRunning.count());
-                for (auto& task : gRunning) {
-                    SkDebugf("\t%s\n", task.c_str());
-                }
+                SkDebugf("\nCaught signal %d [%s].\n", sig, strsignal(sig));
+                print_status();
             });
         }
     }
 #endif
 
 /*~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~*/
 
 struct Gold : public SkString {
     Gold() : SkString("") {}
     Gold(ImplicitString sink, ImplicitString src, ImplicitString srcOptions,
@@ skipping 725 matching lines @@
                                                  task.src.options.c_str(), name.c_str());
         if (!whyBlacklisted.isEmpty()) {
             note.appendf(" (--blacklist %s)", whyBlacklisted.c_str());
         }
 
         SkString log;
         auto timerStart = now_ms();
         if (!FLAGS_dryRun && note.isEmpty()) {
             SkBitmap bitmap;
             SkDynamicMemoryWStream stream;
-            if (FLAGS_pre_log) {
-                SkDebugf("\nRunning %s->%s", name.c_str(), task.sink.tag.c_str());
-            }
             start(task.sink.tag.c_str(), task.src.tag, task.src.options, name.c_str());
             Error err = task.sink->draw(*task.src, &bitmap, &stream, &log);
             if (!err.isEmpty()) {
                 if (err.isFatal()) {
                     fail(SkStringPrintf("%s %s %s %s: %s",
                                         task.sink.tag.c_str(),
                                         task.src.tag.c_str(),
                                         task.src.options.c_str(),
                                         name.c_str(),
                                         err.c_str()));
@@ skipping 178 matching lines @@
     SkString note;
     SkString whyBlacklisted = is_blacklisted("_", "tests", "_", test.name);
     if (!whyBlacklisted.isEmpty()) {
         note.appendf(" (--blacklist %s)", whyBlacklisted.c_str());
     }
 
     auto timerStart = now_ms();
     if (!FLAGS_dryRun && whyBlacklisted.isEmpty()) {
         start("unit", "test", "", test.name);
         GrContextFactory factory;
-        if (FLAGS_pre_log) {
-            SkDebugf("\nRunning test %s", test.name);
-        }
         test.proc(&reporter, &factory);
     }
     done(now_ms()-timerStart, "unit", "test", "", test.name, note, "");
 }
 
 /*~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~*/
 
-// Some runs (mostly, Valgrind) are so slow that the bot framework thinks we've hung.
-// This prints something every once in a while so that it knows we're still working.
-static void start_keepalive() {
-    struct Loop {
-        static void forever(void*) {
-            for (;;) {
-                static const int kSec = 300;
-            #if defined(SK_BUILD_FOR_WIN)
-                Sleep(kSec * 1000);
-            #else
-                sleep(kSec);
-            #endif
-                SkString running;
-                {
-                    SkAutoTAcquire<SkPODSpinlock> lock(gRunningAndTallyMutex);
-                    for (int i = 0; i < gRunning.count(); i++) {
-                        running.appendf("\n\t%s", gRunning[i].c_str());
-                    }
-                }
-                SkDebugf("\nCurrently running:%s\n", running.c_str());
-            }
+DEFINE_int32(status_sec, 15, "Print status this often (and if we crash).");
+
+SkThread* start_status_thread() {
+    auto thread = new SkThread([] (void*) {
+        for (;;) {
+            print_status();
+        #if defined(SK_BUILD_FOR_WIN)
+            Sleep(FLAGS_status_sec * 1000);
+        #else
+            sleep(FLAGS_status_sec);
+        #endif
         }
-    };
-    static SkThread* intentionallyLeaked = new SkThread(Loop::forever);
-    intentionallyLeaked->start();
+    });
+    thread->start();
+    return thread;
 }
 
 #define PORTABLE_FONT_PREFIX "Toy Liberation "
 
 static SkTypeface* create_from_name(const char familyName[], SkTypeface::Style style) {
     if (familyName && strlen(familyName) > sizeof(PORTABLE_FONT_PREFIX)
             && !strncmp(familyName, PORTABLE_FONT_PREFIX, sizeof(PORTABLE_FONT_PREFIX) - 1)) {
         return sk_tool_utils::create_portable_typeface(familyName, style);
     }
     return nullptr;
 }
 
 #undef PORTABLE_FONT_PREFIX
 
 extern SkTypeface* (*gCreateTypefaceDelegate)(const char [], SkTypeface::Style );
 
 int dm_main();
 int dm_main() {
     setup_crash_handler();
+
     JsonWriter::DumpJson();  // It's handy for the bots to assume this is ~never missing.
     SkAutoGraphics ag;
     SkTaskGroup::Enabler enabled(FLAGS_threads);
     gCreateTypefaceDelegate = &create_from_name;
 
-    start_keepalive();
-
     gather_gold();
     gather_uninteresting_hashes();
 
     if (!gather_srcs()) {
         return 1;
     }
     gather_sinks();
     gather_tests();
 
     gPending = gSrcs.count() * gSinks.count() + gParallelTests.count() + gSerialTests.count();
-    SkDebugf("%d srcs * %d sinks + %d tests == %d tasks\n",
+    SkDebugf("%d srcs * %d sinks + %d tests == %d tasks",
              gSrcs.count(), gSinks.count(), gParallelTests.count() + gSerialTests.count(), gPending);
+    SkAutoTDelete<SkThread> statusThread(start_status_thread());
 
     // Kick off as much parallel work as we can, making note of any serial work we'll need to do.
     SkTaskGroup parallel;
     SkTArray<Task> serial;
 
     for (auto& sink : gSinks)
     for (auto&  src : gSrcs) {
         Task task(src, sink);
         if (src->serial() || sink->serial()) {
             serial.push_back(task);
@@ skipping 25 matching lines @@
 
     SkDebugf("\n");
     if (gFailures.count() > 0) {
         SkDebugf("Failures:\n");
         for (int i = 0; i < gFailures.count(); i++) {
             SkDebugf("\t%s\n", gFailures[i].c_str());
         }
         SkDebugf("%d failures\n", gFailures.count());
         return 1;
     }
-    if (gPending > 0) {
-        SkDebugf("Hrm, we didn't seem to run everything we intended to!  Please file a bug.\n");
-        return 1;
-    }
-    #ifdef SK_PDF_IMAGE_STATS
+
+#ifdef SK_PDF_IMAGE_STATS
     SkPDFImageDumpStats();
-    #endif  // SK_PDF_IMAGE_STATS
+#endif  // SK_PDF_IMAGE_STATS
+
+    print_status();
     SkDebugf("Finished!\n");
     return 0;
 }
 
 // TODO: currently many GPU tests are declared outside SK_SUPPORT_GPU guards.
 // Thus we export the empty RunWithGPUTestContexts when SK_SUPPORT_GPU=0.
 namespace skiatest {
 namespace {
 typedef void(*TestWithGrContext)(skiatest::Reporter*, GrContext*);
 typedef void(*TestWithGrContextAndGLContext)(skiatest::Reporter*, GrContext*, SkGLContext*);
@@ skipping 78 matching lines @@
                                                            Reporter* reporter,
                                                            GrContextFactory* factory);
 } // namespace skiatest
 
 #if !defined(SK_BUILD_FOR_IOS)
 int main(int argc, char** argv) {
     SkCommandLineFlags::Parse(argc, argv);
     return dm_main();
 }
 #endif