DM: verbose and quiet logging

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"
@@ skipping 55 matching lines @@
         "this list, no image is written for that result.");
 
 DEFINE_int32(shards, 1, "We're splitting source data into this many shards.");
 DEFINE_int32(shard,  0, "Which shard do I run?");
 DEFINE_bool(simpleCodec, false, "Only decode images to native scale");
 
 using namespace DM;
 
 /*~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~*/
 
+static const SkMSec kStartMs = SkTime::GetMSecs();
+
+static FILE* gVLog;
+
+template <typename... Args>
+static void vlog(const char* fmt, Args&&... args) {
+    if (gVLog) {
+        fprintf(gVLog, "%s\t", HumanizeMs(SkTime::GetMSecs() - kStartMs).c_str());
+        fprintf(gVLog, fmt, args...);
+        fflush(gVLog);
+    }
+}
+
+template <typename... Args>
+static void info(const char* fmt, Args&&... args) {
+    vlog(fmt, args...);
+    FLAGS_quiet || printf(fmt, args...);

[hal.canary, 2016/03/08 15:09:34]

nit: We never use this syntax.

   if (!FLAGS_quiet) { printf(fmt, args...); }

is much more readable.  (I don't mind one-line conditionals, as long as {} are
used.)

[mtklein, 2016/03/08 15:15:55]

Done.

+}
+static void info(const char* fmt) {
+    FLAGS_quiet || printf("%s", fmt);  // Clang warns printf(fmt) is insecure.
+}
+
 SK_DECLARE_STATIC_MUTEX(gFailuresMutex);
 static SkTArray<SkString> gFailures;
 
 static void fail(const SkString& err) {
     SkAutoMutexAcquire lock(gFailuresMutex);
     SkDebugf("\n\nFAILURE: %s\n\n", err.c_str());
     gFailures.push_back(err);
 }
 
 
 // We use a spinlock to make locking this in a signal handler _somewhat_ safe.
 static SkSpinlock gMutex;
 static int32_t            gPending;
 static SkTArray<SkString> gRunning;
 
 static void done(const char* config, const char* src, const char* srcOptions, const char* name) {
     SkString id = SkStringPrintf("%s %s %s %s", config, src, srcOptions, name);
+    vlog("done  %s\n", id.c_str());
     int pending;
     {
         SkAutoTAcquire<SkSpinlock> lock(gMutex);
         for (int i = 0; i < gRunning.count(); i++) {
             if (gRunning[i] == id) {
                 gRunning.removeShuffle(i);
                 break;
             }
         }
         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(const char* config, const char* src, const char* srcOptions, const char* name) {
     SkString id = SkStringPrintf("%s %s %s %s", config, src, srcOptions, name);
+    vlog("start %s\n", id.c_str());
     SkAutoTAcquire<SkSpinlock> 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);
+    SkString elapsed = HumanizeMs(SkTime::GetMSecs() - kStartMs);
 
     SkAutoTAcquire<SkSpinlock> 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);
+    info("\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());
+        info("\t%s\n", task.c_str());
     }
 }
 
 // Yo dawg, I heard you like signals so I caught a signal in your
 // signal handler so you can handle signals while you handle signals.
 // Let's not get into that situation.  Only print if we're the first ones to get a crash signal.
 static std::atomic<bool> in_signal_handler{false};
 
 #if defined(SK_BUILD_FOR_WIN32)
     static LONG WINAPI handler(EXCEPTION_POINTERS* e) {
         static const struct {
             const char* name;
             DWORD code;
         } kExceptions[] = {
         #define _(E) {#E, E}
             _(EXCEPTION_ACCESS_VIOLATION),
             _(EXCEPTION_BREAKPOINT),
             _(EXCEPTION_INT_DIVIDE_BY_ZERO),
             _(EXCEPTION_STACK_OVERFLOW),
             // TODO: more?
         #undef _
         };
 
         if (!in_signal_handler.exchange(true)) {
             const DWORD code = e->ExceptionRecord->ExceptionCode;
-            SkDebugf("\nCaught exception %u", code);
+            info("\nCaught exception %u", code);
             for (const auto& exception : kExceptions) {
                 if (exception.code == code) {
-                    SkDebugf(" %s", exception.name);
+                    info(" %s", exception.name);
                 }
             }
-            SkDebugf("\n");
+            info("\n");
             print_status();
         }
         // Execute default exception handler... hopefully, exit.
         return EXCEPTION_EXECUTE_HANDLER;
     }
     static void setup_crash_handler() { SetUnhandledExceptionFilter(handler); }
 
 #elif !defined(SK_BUILD_FOR_ANDROID)
     #include <execinfo.h>
     #include <signal.h>
     #include <stdlib.h>
 
     static void setup_crash_handler() {
         const int kSignals[] = { SIGABRT, SIGBUS, SIGFPE, SIGILL, SIGSEGV };
         for (int sig : kSignals) {
             signal(sig, [](int sig) {
                 if (!in_signal_handler.exchange(true)) {
                     SkAutoTAcquire<SkSpinlock> lock(gMutex);
-                    SkDebugf("\nCaught signal %d [%s], was running:\n", sig, strsignal(sig));
+                    info("\nCaught signal %d [%s], was running:\n", sig, strsignal(sig));
                     for (auto& task : gRunning) {
-                        SkDebugf("\t%s\n", task.c_str());
+                        info("\t%s\n", task.c_str());
                     }
 
                     void* stack[64];
                     int count = backtrace(stack, SK_ARRAY_COUNT(stack));
                     char** symbols = backtrace_symbols(stack, count);
-                    SkDebugf("\nStack trace:\n");
+                    info("\nStack trace:\n");
                     for (int i = 0; i < count; i++) {
-                        SkDebugf("    %s\n", symbols[i]);
+                        info("    %s\n", symbols[i]);
                     }
                 }
                 _Exit(sig);
             });
         }
     }
 
 #else  // Android
     static void setup_crash_handler() {}
 #endif
@@ skipping 35 matching lines @@
 }
 
 /*~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~*/
 
 static SkTHashSet<SkString> gUninterestingHashes;
 
 static void gather_uninteresting_hashes() {
     if (!FLAGS_uninterestingHashesFile.isEmpty()) {
         SkAutoTUnref<SkData> data(SkData::NewFromFileName(FLAGS_uninterestingHashesFile[0]));
         if (!data) {
-            SkDebugf("WARNING: unable to read uninteresting hashes from %s\n",
-                     FLAGS_uninterestingHashesFile[0]);
+            info("WARNING: unable to read uninteresting hashes from %s\n",
+                 FLAGS_uninterestingHashesFile[0]);
             return;
         }
         SkTArray<SkString> hashes;
         SkStrSplit((const char*)data->data(), "\n", &hashes);
         for (const SkString& hash : hashes) {
             gUninterestingHashes.add(hash);
         }
-        SkDebugf("FYI: loaded %d distinct uninteresting hashes from %d lines\n",
-                 gUninterestingHashes.count(), hashes.count());
+        info("FYI: loaded %d distinct uninteresting hashes from %d lines\n",
+             gUninterestingHashes.count(), hashes.count());
     }
 }
 
 /*~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~*/
 
 struct TaggedSrc : public SkAutoTDelete<Src> {
     SkString tag;
     SkString options;
 };
 
@@ skipping 130 matching lines @@
         folder.appendf("_%.3f", 1.0f / (float) sampleSize);
     }
 
     AndroidCodecSrc* src = new AndroidCodecSrc(path, mode, dstColorType, dstAlphaType, sampleSize);
     push_src("image", folder, src);
 }
 
 static void push_codec_srcs(Path path) {
     SkAutoTUnref<SkData> encoded(SkData::NewFromFileName(path.c_str()));
     if (!encoded) {
-        SkDebugf("Couldn't read %s.", path.c_str());
+        info("Couldn't read %s.", path.c_str());
         return;
     }
     SkAutoTDelete<SkCodec> codec(SkCodec::NewFromData(encoded));
     if (nullptr == codec.get()) {
-        SkDebugf("Couldn't create codec for %s.", path.c_str());
+        info("Couldn't create codec for %s.", path.c_str());
         return;
     }
 
     // Native Scales
     // SkJpegCodec natively supports scaling to: 0.125, 0.25, 0.375, 0.5, 0.625, 0.75, 0.875
     const float nativeScales[] = { 0.125f, 0.25f, 0.375f, 0.5f, 0.625f, 0.750f, 0.875f, 1.0f };
 
     SkTArray<CodecSrc::Mode> nativeModes;
     nativeModes.push_back(CodecSrc::kCodec_Mode);
     nativeModes.push_back(CodecSrc::kCodecZeroInit_Mode);
@@ skipping 275 matching lines @@
         }
         SkISize size() const override { return SkISize::Make(16, 16); }
         Name name() const override { return "justOneRect"; }
     } justOneRect;
 
     SkBitmap bitmap;
     SkDynamicMemoryWStream stream;
     SkString log;
     Error err = sink->draw(justOneRect, &bitmap, &stream, &log);
     if (err.isFatal()) {
-        SkDebugf("Could not run %s: %s\n", config.getTag().c_str(), err.c_str());
+        info("Could not run %s: %s\n", config.getTag().c_str(), err.c_str());
         exit(1);
     }
 
     TaggedSink& ts = gSinks.push_back();
     ts.reset(sink.detach());
     ts.tag = config.getTag();
 }
 
 static bool gpu_supported() {
 #if SK_SUPPORT_GPU
     return FLAGS_gpu;
 #else
     return false;
 #endif
 }
 
 static Sink* create_sink(const SkCommandLineConfig* config) {
 #if SK_SUPPORT_GPU
     if (gpu_supported()) {
         if (const SkCommandLineConfigGpu* gpuConfig = config->asConfigGpu()) {
             GrContextFactory::GLContextType contextType = gpuConfig->getContextType();
             GrContextFactory::GLContextOptions contextOptions =
                     GrContextFactory::kNone_GLContextOptions;
             if (gpuConfig->getUseNVPR()) {
                 contextOptions = static_cast<GrContextFactory::GLContextOptions>(
                     contextOptions | GrContextFactory::kEnableNVPR_GLContextOptions);
             }
             GrContextFactory testFactory;
             if (!testFactory.get(contextType, contextOptions)) {
-                SkDebugf("WARNING: can not create GPU context for config '%s'. "
-                         "GM tests will be skipped.\n", gpuConfig->getTag().c_str());
+                info("WARNING: can not create GPU context for config '%s'. "
+                     "GM tests will be skipped.\n", gpuConfig->getTag().c_str());
                 return nullptr;
             }
             return new GPUSink(contextType, contextOptions, gpuConfig->getSamples(),
                                gpuConfig->getUseDIText(), FLAGS_gpu_threading);
         }
     }
 #endif
 
 #define SINK(t, sink, ...) if (config->getBackend().equals(t)) { return new sink(__VA_ARGS__); }
 
@@ skipping 49 matching lines @@
     return nullptr;
 }
 
 static void gather_sinks() {
     SkCommandLineConfigArray configs;
     ParseConfigs(FLAGS_config, &configs);
     for (int i = 0; i < configs.count(); i++) {
         const SkCommandLineConfig& config = *configs[i];
         Sink* sink = create_sink(&config);
         if (sink == nullptr) {
-            SkDebugf("Skipping config %s: Don't understand '%s'.\n", config.getTag().c_str(),
-                     config.getTag().c_str());
+            info("Skipping config %s: Don't understand '%s'.\n", config.getTag().c_str(),
+                 config.getTag().c_str());
             continue;
         }
 
         const SkTArray<SkString>& parts = config.getViaParts();
         for (int j = parts.count(); j-- > 0;) {
             const SkString& part = parts[j];
             Sink* next = create_via(part, sink);
             if (next == nullptr) {
-                SkDebugf("Skipping config %s: Don't understand '%s'.\n", config.getTag().c_str(),
-                         part.c_str());
+                info("Skipping config %s: Don't understand '%s'.\n", config.getTag().c_str(),
+                     part.c_str());
                 delete sink;
                 sink = nullptr;
                 break;
             }
             sink = next;
         }
         if (sink) {
             push_sink(config, sink);
         }
     }
@@ skipping 151 matching lines @@
         SkString name = task.src->name();
 
         SkString log;
         if (!FLAGS_dryRun) {
             SkBitmap bitmap;
             SkDynamicMemoryWStream stream;
             start(task.sink.tag.c_str(), task.src.tag.c_str(),
                   task.src.options.c_str(), name.c_str());
             Error err = task.sink->draw(*task.src, &bitmap, &stream, &log);
             if (!log.isEmpty()) {
-                SkDebugf("%s %s %s %s:\n%s\n", task.sink.tag.c_str()
-                                             , task.src.tag.c_str()
-                                             , task.src.options.c_str()
-                                             , name.c_str()
-                                             , log.c_str());
+                info("%s %s %s %s:\n%s\n", task.sink.tag.c_str()
+                                         , task.src.tag.c_str()
+                                         , task.src.options.c_str()
+                                         , name.c_str()
+                                         , log.c_str());
             }
             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()));
                 } else {
@@ skipping 215 matching lines @@
 }
 
 #undef PORTABLE_FONT_PREFIX
 
 extern SkTypeface* (*gCreateTypefaceDelegate)(const char [], SkTypeface::Style );
 
 int dm_main();
 int dm_main() {
     setup_crash_handler();
 
+    if (FLAGS_verbose && !FLAGS_writePath.isEmpty()) {
+        sk_mkdir(FLAGS_writePath[0]);
+        gVLog = freopen(SkOSPath::Join(FLAGS_writePath[0], "verbose.log").c_str(), "w", stderr);
+    }
+
     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;
 
     {
         SkString testResourcePath = GetResourcePath("color_wheel.png");
         SkFILEStream testResource(testResourcePath.c_str());
         if (!testResource.isValid()) {
-            SkDebugf("Some resources are missing.  Do you need to set --resourcePath?\n");
+            info("Some resources are missing.  Do you need to set --resourcePath?\n");
         }
     }
     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",
-             gSrcs.count(), gSinks.count(), gParallelTests.count() + gSerialTests.count(), gPending);
+    info("%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) {
         if (src->veto(sink->flags()) ||
             is_blacklisted(sink.tag.c_str(), src.tag.c_str(),
@@ skipping 24 matching lines @@
 
     // We'd better have run everything.
     SkASSERT(gPending == 0);
     // Make sure we've flushed all our results to disk.
     JsonWriter::DumpJson();
 
     // At this point we're back in single-threaded land.
     sk_tool_utils::release_portable_typefaces();
 
     if (gFailures.count() > 0) {
-        SkDebugf("Failures:\n");
+        info("Failures:\n");
         for (int i = 0; i < gFailures.count(); i++) {
-            SkDebugf("\t%s\n", gFailures[i].c_str());
+            info("\t%s\n", gFailures[i].c_str());
         }
-        SkDebugf("%d failures\n", gFailures.count());
+        info("%d failures\n", gFailures.count());
         return 1;
     }
 
 #ifdef SK_PDF_IMAGE_STATS
     SkPDFImageDumpStats();
 #endif  // SK_PDF_IMAGE_STATS
 
     print_status();
-    SkDebugf("Finished!\n");
+    info("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*);
 #if SK_SUPPORT_GPU
@@ skipping 77 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