print correct run time (include hooks)

CHANGELOG.md

@@ -1,3 +1,9 @@
+## dbt 0.9.1 (unreleased)
+
+### Bugfixes
+
+- Include hook run time in reported model run time ([#607](https://github.com/fishtown-analytics/dbt/pull/607))
+
 ## dbt 0.9.0 (October 25, 2017)
 
 This release focuses on improvements to macros, materializations, and package management. Check out [the blog post](https://blog.fishtownanalytics.com/whats-new-in-dbt-0-9-0-dd36f3572ac6) to learn more about what's possible in this new version of dbt.

dbt/node_runners.py

@@ -180,12 +180,20 @@ def get_model_schemas(cls, flat_graph):
 
         return schemas
 
+    @classmethod
+    def before_hooks(self, project, adapter, flat_graph):
+        pass
+
     @classmethod
     def before_run(self, project, adapter, flat_graph):
         pass
 
     @classmethod
-    def after_run(self, project, adapter, results, flat_graph, elapsed):
+    def after_run(self, project, adapter, results, flat_graph):
+        pass
+
+    @classmethod
+    def after_hooks(self, project, adapter, results, flat_graph, elapsed):
         pass
 
 
@@ -352,8 +360,11 @@ def print_results_line(cls, results, execution_time):
             .format(stat_line=stat_line, execution=execution))
 
     @classmethod
-    def after_run(cls, project, adapter, results, flat_graph, elapsed):
+    def after_run(cls, project, adapter, results, flat_graph):
         cls.safe_run_hooks(project, adapter, flat_graph, RunHookType.End)
+
+    @classmethod
+    def after_hooks(cls, project, adapter, results, flat_graph, elapsed):
         cls.print_results_line(results, elapsed)
 
     def describe_node(self):

dbt/runner.py

@@ -203,11 +203,13 @@ def run_from_graph(self, Selector, Runner, query):
             logger.info("")
 
         try:
-            Runner.before_run(self.project, adapter, flat_graph)
+            Runner.before_hooks(self.project, adapter, flat_graph)
             started = time.time()
+            Runner.before_run(self.project, adapter, flat_graph)
             res = self.execute_nodes(linker, Runner, flat_graph, dep_list)
+            Runner.after_run(self.project, adapter, res, flat_graph)
             elapsed = time.time() - started
-            Runner.after_run(self.project, adapter, res, flat_graph, elapsed)
+            Runner.after_hooks(self.project, adapter, res, flat_graph, elapsed)
 
         finally:
             adapter.cleanup_connections()