Repository: dbt-labs/dbt-core
Issue: Cache logging is slow!

It appears that something about cache logging is _very_ slow!

If I modify the [_relations_cache_for_schemas](https://github.com/fishtown-analytics/dbt/blob/dev/0.14.1/core/dbt/adapters/base/impl.py#L314-L330) method to look like: 
```python
        ...
        for db, schema in info_schema_name_map.search():
            rels = self.list_relations_without_caching(db, schema)
            import time
            stime = time.time()
            for relation in rels:
                self.cache.add(relation)
            etime = time.time()
            print("Added {} rels in {}s".format(len(rels), etime - stime))
```

Then I can see how long it takes for dbt to add relations to the relation cache. In a test postgres  schema, I can see that adding 1000 relations to the cache takes 13 seconds! For a schema with 4000 tables in it, this takes **almost four minutes** on my hardware!

My instinct is that this is either due to calling `pprint.pformat()` in the `cache.add()` method, or it has something to do with calling `self.dump_graph()` repeatedly.

It's not uncommon for dbt projects to contain hundreds or even thousands of models. I wonder: how frequently do dbt projects run against schemas that contain many thousands of objects in them?

cc @beckjake - what do you think about this? Are there other places in the codebase where we do something similar?

Changed files:
core/dbt/adapters/cache.py, core/dbt/logger.py, core/dbt/config/runtime.py, core/dbt/config/profile.py, core/dbt/config/project.py

diff --git a/core/dbt/adapters/cache.py b/core/dbt/adapters/cache.py
index 73e70ed99..521ff52d9 100644
--- a/core/dbt/adapters/cache.py
+++ b/core/dbt/adapters/cache.py
@@ -1,7 +1,6 @@
 from collections import namedtuple
 import threading
 from copy import deepcopy
-import pprint
 from dbt.logger import CACHE_LOGGER as logger
 import dbt.exceptions
 
@@ -163,6 +162,12 @@ class _CachedRelation:
         return [dot_separated(r) for r in self.referenced_by]
 
 
+def lazy_log(msg, func):
+    if logger.disabled:
+        return
+    logger.debug(msg.format(func()))
+
+
 class RelationsCache:
     """A cache of the relations known to dbt. Keeps track of relationships
     declared between tables and handles renames/drops as a real database would.
@@ -303,14 +308,13 @@ class RelationsCache:
         """
         cached = _CachedRelation(relation)
         logger.debug('Adding relation: {!s}'.format(cached))
-        logger.debug('before adding: {}'.format(
-            pprint.pformat(self.dump_graph()))
-        )
+
+        lazy_log('before adding: {!s}', self.dump_graph)
+
         with self.lock:
             self._setdefault(cached)
-        logger.debug('after adding: {}'.format(
-            pprint.pformat(self.dump_graph()))
-        )
+
+        lazy_log('after adding: {!s}', self.dump_graph)
 
     def _remove_refs(self, keys):
         """Removes all references to all entries in keys. This does not
@@ -431,11 +435,10 @@ class RelationsCache:
         old_key = _make_key(old)
         new_key = _make_key(new)
         logger.debug('Renaming relation {!s} to {!s}'.format(
-            old_key, new_key)
-        )
-        logger.debug('before rename: {}'.format(
-            pprint.pformat(self.dump_graph()))
-        )
+            old_key, new_key
+        ))
+
+        lazy_log('before rename: {!s}', self.dump_graph)
 
         with self.lock:
             if self._check_rename_constraints(old_key, new_key):
@@ -443,9 +446,7 @@ class RelationsCache:
             else:
                 self._setdefault(_CachedRelation(new))
 
-        logger.debug('after rename: {}'.format(
-            pprint.pformat(self.dump_graph()))
-        )
+        lazy_log('after rename: {!s}', self.dump_graph)
 
     def get_relations(self, database, schema):
         """Case-insensitively yield all relations matching the given schema.
diff --git a/core/dbt/config/profile.py b/core/dbt/config/profile.py
index 8828d8639..4e03a5d03 100644
--- a/core/dbt/config/profile.py
+++ b/core/dbt/config/profile.py
@@ -1,5 +1,4 @@
 import os
-import pprint
 
 from hologram import ValidationError
 
@@ -102,7 +101,7 @@ class Profile:
         return result
 
     def __str__(self):
-        return pprint.pformat(self.to_profile_info())
+        return str(self.to_profile_info())
 
     def __eq__(self, other):
         if not (isinstance(other, self.__class__) and
diff --git a/core/dbt/config/project.py b/core/dbt/config/project.py
index 9757ec7aa..e24cfbb23 100644
--- a/core/dbt/config/project.py
+++ b/core/dbt/config/project.py
@@ -1,7 +1,6 @@
 from copy import deepcopy
 import hashlib
 import os
-import pprint
 
 from dbt.clients.system import resolve_path_from_base
 from dbt.clients.system import path_exists
@@ -295,7 +294,7 @@ class Project:
 
     def __str__(self):
         cfg = self.to_project_config(with_packages=True)
-        return pprint.pformat(cfg)
+        return str(cfg)
 
     def __eq__(self, other):
         if not (isinstance(other, self.__class__) and
diff --git a/core/dbt/config/runtime.py b/core/dbt/config/runtime.py
index 2ca8c31db..34de274d0 100644
--- a/core/dbt/config/runtime.py
+++ b/core/dbt/config/runtime.py
@@ -1,6 +1,4 @@
-
 from copy import deepcopy
-import pprint
 
 from dbt.utils import parse_cli_vars
 from dbt.contracts.project import Configuration
@@ -148,7 +146,7 @@ class RuntimeConfig(Project, Profile):
         return result
 
     def __str__(self):
-        return pprint.pformat(self.serialize())
+        return str(self.serialize())
 
     def validate(self):
         """Validate the configuration against its contract.
diff --git a/core/dbt/logger.py b/core/dbt/logger.py
index becb0f236..e91bfad2f 100644
--- a/core/dbt/logger.py
+++ b/core/dbt/logger.py
@@ -358,7 +358,9 @@ log_manager = LogManager()
 def log_cache_events(flag):
     """Set the cache logger to propagate its messages based on the given flag.
     """
-    CACHE_LOGGER.disabled = True
+    # the flag is True if we should log, and False if we shouldn't, so disabled
+    # is the inverse.
+    CACHE_LOGGER.disabled = not flag
 
 
 GLOBAL_LOGGER = logger