Repository: dbt-labs/dbt-core
Pull request: Add data processed info into dbt run logs for all statement types
resolves #2526 

### Description

Changing the log output of BigQuery query CREATE_TABLE_AS_SELECT statement to include byte processed.


### Checklist
 - [X] I have signed the [CLA](https://docs.getdbt.com/docs/contributor-license-agreements)
 - [x] I have run this code in development and it appears to resolve the stated issue
 - [X] This PR includes tests, or tests are not required/relevant for this PR
 - [x] I have updated the `CHANGELOG.md` and added information about my change to the "dbt next" section.

Sorry but at the moment, I cannot install all the requirements to run the tests suite.
I am not sure what to write and where. @jtcohen6 can you offer an advice?


Problem statement:
Add data processed info into dbt run logs for all statement types
### Describe the feature
When using BigQuery `dbt run` logs should show the data scan value for create table statement and not just for script.

### Describe alternatives you've considered
No alternative

### Additional context
This specific improvement is about BigQuery. However, this might apply for other database too I do not have experience to give specific examples.

### Who will this benefit?
Everyone using dbt to get easier access to usage.

Hints from issue discussion:
Very cool idea!

The code for printing out bytes billed is fairly straightforward:
https://github.com/fishtown-analytics/dbt/blob/c9b34681b756ccd4b5c4f0a3bd8f12f48f23081d/plugins/bigquery/dbt/adapters/bigquery/connections.py#L250-L252

I think it would just be a matter of reporting the `total_bytes_processed` for other `query_job` statement types.

@alepuccetti Is this something you'd be interested in working on? I think this could be a great opportunity for a first contribution :)
@jtcohen6  Yes, I would be interested. You can assigned to me if this is the procedure.
It's all yours! Happy to help if you want more direction or get stuck
Hi Guys,

While the bytes processed is an interesting KPI for those bigquery customers that are on an on-demand pricing, the average slot usage of a query is interesting for those customers on a slot commitment.

It is very similar to calculate from the query job object you get when launching a query: you have to calculate the duration of the query in milliseconds using ```query_job.ended - query_job.started``` and then divide ```query_job.slot_millis``` by that value.

Could we add this info in the same PR, or do we create a new issue for this?
@bodschut Thanks for the suggestion! We're packing a lot of info into limited horizontal space right now. Your point has crystallized for me that we should give the user more control.

Here's what makes sense to me: a set of [additional configuration parameters](https://docs.getdbt.com/docs/running-a-dbt-project/using-the-command-line-interface/configure-your-profile/#additional-profile-configurations) in `profiles.yml` to control what dbt includes in its info output.

```yml
config:
  bytes_processed: true | false
  slot_duration: true | false
```

@drewbanin @alepuccetti What do you think here? I know this throws one more wrench into #2530, though I feel a lot better knowing that we'd be:
* supporting both BQ pricing mechanisms
* displaying a less overwhelming amount of information by default
@jtcohen6 Having the user configure it is a good idea. I second that. I am up for implementing the configuration parameters, might take a while, I am doing this in my spare time.

About the average slots usage. I had a discussion with google engineers on how to measure slots utilisation to estimate if it is worth it moving to flat-rate pricing and how to evaluate the performance implications. The answer was that there is no formula but only try your workload and look how it performs.
Because of this I am not not convinced about the metric as it is proposed if it actually serve a purpose of measuring the slots utilisation.
I can think of an example: if you have multiple queries in your model that can run in parallel is very difficult to understand what is happening because query running at the same time share the slots but the metrics as it is prosed will not account for this concurrency.

I am in favour having a slots metric but I think it should be discussed more of what it should be and how to interpret it in a separate issue. For instance, I think that even just `slot_millis ` is a good metric.

Hi @alepuccetti 

You are right to say that the slot usage is not the only parameter to consider a move to a slot commitment. But, it's an interesting indicator when you are on a slot commitment and need to optimize your slot reservations for certain projects. At that point, knowing which queries consume how many slots on average can be interesting to optimize or to decide on changing a certain slot reservation or even upgrading your commitment with another package of 500 slots.

You could indeed include the slot millis like that, without calculating the query duration, but the average slot usage as calculated above is the best indicator for the 'slot load' of the query. I don't know if the model duration that dbt logs by default is the actual query duration or whether it includes the setup time. If it is the actual query duration, you could indeed calculate the average slots used yourself.
Huh, I think that this is a string templating issue, and I think Jinja could be a good tool to solve that kind of problem :) 

I think we should keep the focus narrow for this particular PR, but in the future, I would like to:
1. Provide a config option that accepts a templated string for the model status
2. Provide a context that has variables in scope (like `job`, `materialization`, `status`, `runtime`, etc)

What do y'all think?
@drewbanin This is a great idea. I am not sure I will be able to implement something like that with my limited knowledge of dbt internals.


> Huh, I think that this is a string templating issue, and I think Jinja could be a good tool to solve that kind of problem :)
> 
> I think we should keep the focus narrow for this particular PR, but in the future, I would like to:
> 
> 1. Provide a config option that accepts a templated string for the model status
> 2. Provide a context that has variables in scope (like `job`, `materialization`, `status`, `runtime`, etc)
> 
> What do y'all think?

@drewbanin This is a great idea.
@bodschut I like the idea of having a slot usage metrics. I just think it needs more discussion. Because it is not straightforward like number of rows or byte processed.

Commit message: core/dbt/utils: remove extra empty line

Patch to review:
diff --git a/CHANGELOG.md b/CHANGELOG.md
index f31a038398e..48393197dcb 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -11,10 +11,12 @@
 - Added support for renaming BigQuery relations ([#2520](https://github.com/fishtown-analytics/dbt/issues/2520), [#2521](https://github.com/fishtown-analytics/dbt/pull/2521))
 - Added support for BigQuery authorized views ([#1718](https://github.com/fishtown-analytics/dbt/issues/1718), [#2517](https://github.com/fishtown-analytics/dbt/pull/2517))
 - Added support for altering BigQuery column types ([#2546](https://github.com/fishtown-analytics/dbt/issues/2546), [#2547](https://github.com/fishtown-analytics/dbt/pull/2547))
+- Format rows number in BigQuery plugin logs, [#2526](https://github.com/fishtown-analytics/dbt/issues/2526)
 
 ### Fixes
 - Fixed an error in create_adapter_plugins.py script when -dependency arg not passed ([#2507](https://github.com/fishtown-analytics/dbt/issues/2507), [#2508](https://github.com/fishtown-analytics/dbt/pull/2508))
 - Remove misleading "Opening a new connection" log message in set_connection_name. ([#2511](https://github.com/fishtown-analytics/dbt/issues/2511))
+- Now all the BigQuery statement types return the number of bytes processed ([#2526](https://github.com/fishtown-analytics/dbt/issues/2526)).
 
 Contributors:
  - [@raalsky](https://github.com/Raalsky) ([#2417](https://github.com/fishtown-analytics/dbt/pull/2417), [#2485](https://github.com/fishtown-analytics/dbt/pull/2485))
@@ -22,6 +24,7 @@ Contributors:
  - [@scarrucciu](https://github.com/scarrucciu) ([#2508](https://github.com/fishtown-analytics/dbt/pull/2508))
  - [@southpolemonkey](https://github.com/southpolemonkey) ([#2511](https://github.com/fishtown-analytics/dbt/issues/2511))
  - [@azhard](https://github.com/azhard) ([#2517](https://github.com/fishtown-analytics/dbt/pull/2517), ([#2521](https://github.com/fishtown-analytics/dbt/pull/2521)), [#2547](https://github.com/fishtown-analytics/dbt/pull/2547))
+ - [@alepuccetti](https://github.com/alepuccetti) ([#2526](https://github.com/fishtown-analytics/dbt/issues/2526))
 
 
 ## dbt 0.17.1 (Release TBD)
diff --git a/core/dbt/utils.py b/core/dbt/utils.py
index 989b93308d5..c171ecb76a5 100644
--- a/core/dbt/utils.py
+++ b/core/dbt/utils.py
@@ -510,12 +510,23 @@ def __get__(self, obj, objtype):
 
 
 def format_bytes(num_bytes):
-    for unit in ['Bytes', 'KB', 'MB', 'GB', 'TB']:
+    for unit in ['Bytes', 'KB', 'MB', 'GB', 'TB', 'PB']:
         if abs(num_bytes) < 1024.0:
             return f"{num_bytes:3.1f} {unit}"
         num_bytes /= 1024.0
 
-    return "> 1024 TB"
+    num_bytes *= 1024.0
+    return f"{num_bytes:3.1f} {unit}"
+
+
+def format_rows_number(rows_number):
+    for unit in ['', 'k', 'm', 'b', 't']:
+        if abs(rows_number) < 1000.0:
+            return f"{rows_number:3.1f}{unit}".strip()
+        rows_number /= 1000.0
+
+    rows_number *= 1000.0
+    return f"{rows_number:3.1f}{unit}".strip()
 
 
 # a little concurrent.futures.Executor for single-threaded mode
diff --git a/plugins/bigquery/dbt/adapters/bigquery/connections.py b/plugins/bigquery/dbt/adapters/bigquery/connections.py
index 74e5d7d3690..b62dba5320d 100644
--- a/plugins/bigquery/dbt/adapters/bigquery/connections.py
+++ b/plugins/bigquery/dbt/adapters/bigquery/connections.py
@@ -8,7 +8,7 @@
 from google.api_core import retry, client_info
 from google.oauth2 import service_account
 
-from dbt.utils import format_bytes
+from dbt.utils import format_bytes, format_rows_number
 from dbt.clients import agate_helper, gcloud
 from dbt.exceptions import (
     FailedToConnectException, RuntimeException, DatabaseException
@@ -245,16 +245,21 @@ def execute(self, sql, auto_begin=False, fetch=None):
             conn = self.get_thread_connection()
             client = conn.handle
             table = client.get_table(query_job.destination)
-            status = 'CREATE TABLE ({})'.format(table.num_rows)
+            processed = format_bytes(query_job.total_bytes_processed)
+            status = 'CREATE TABLE ({} rows, {} processed)'.format(
+                format_rows_number(table.num_rows),
+                format_bytes(query_job.total_bytes_processed),
+            )
 
         elif query_job.statement_type == 'SCRIPT':
             processed = format_bytes(query_job.total_bytes_processed)
             status = f'SCRIPT ({processed} processed)'
 
         elif query_job.statement_type in ['INSERT', 'DELETE', 'MERGE']:
-            status = '{} ({})'.format(
+            status = '{} ({} rows, {} processed)'.format(
                 query_job.statement_type,
-                query_job.num_dml_affected_rows
+                format_rows_number(query_job.num_dml_affected_rows),
+                format_bytes(query_job.total_bytes_processed),
             )
 
         else:
diff --git a/test/unit/test_utils.py b/test/unit/test_utils.py
index e624d5da4e0..e4b2f005fc5 100644
--- a/test/unit/test_utils.py
+++ b/test/unit/test_utils.py
@@ -93,7 +93,6 @@ def test__simple_cases(self):
         actual = dbt.utils.deep_map(self.intify_all, expected)
         self.assertEqual(actual, expected)
 
-
     @staticmethod
     def special_keypath(value, keypath):
 
@@ -150,7 +149,25 @@ def test__simple_cases(self):
         self.assertEqual(dbt.utils.format_bytes(1024**2*1.5), '1.5 MB')
         self.assertEqual(dbt.utils.format_bytes(1024**3*52.6), '52.6 GB')
         self.assertEqual(dbt.utils.format_bytes(1024**4*128), '128.0 TB')
-        self.assertEqual(dbt.utils.format_bytes(1024**5+1), '> 1024 TB')
+        self.assertEqual(dbt.utils.format_bytes(1024**5), '1.0 PB')
+        self.assertEqual(dbt.utils.format_bytes(1024**5*31.4), '31.4 PB')
+        self.assertEqual(dbt.utils.format_bytes(1024**6), '1024.0 PB')
+        self.assertEqual(dbt.utils.format_bytes(1024**6*42), '43008.0 PB')
+
+
+class TestRowsNumberFormatting(unittest.TestCase):
+
+    def test__simple_cases(self):
+        self.assertEqual(dbt.utils.format_rows_number(-1), '-1.0')
+        self.assertEqual(dbt.utils.format_rows_number(0), '0.0')
+        self.assertEqual(dbt.utils.format_rows_number(20), '20.0')
+        self.assertEqual(dbt.utils.format_rows_number(1030), '1.0k')
+        self.assertEqual(dbt.utils.format_rows_number(1000**2*1.5), '1.5m')
+        self.assertEqual(dbt.utils.format_rows_number(1000**3*52.6), '52.6b')
+        self.assertEqual(dbt.utils.format_rows_number(1000**3*128), '128.0b')
+        self.assertEqual(dbt.utils.format_rows_number(1000**4), '1.0t')
+        self.assertEqual(dbt.utils.format_rows_number(1000**4*31.4), '31.4t')
+        self.assertEqual(dbt.utils.format_rows_number(1000**5*31.4), '31400.0t')  # noqa: E501
 
 
 class TestMultiDict(unittest.TestCase):


Code review comments:
diff_hunk: @@ -11,17 +11,20 @@
 - Added support for renaming BigQuery relations ([#2520](https://github.com/fishtown-analytics/dbt/issues/2520), [#2521](https://github.com/fishtown-analytics/dbt/pull/2521))
 - Added support for BigQuery authorized views ([#1718](https://github.com/fishtown-analytics/dbt/issues/1718), [#2517](https://github.com/fishtown-analytics/dbt/pull/2517))
 - Added support for altering BigQuery column types ([#2546](https://github.com/fishtown-analytics/dbt/issues/2546), [#2547](https://github.com/fishtown-analytics/dbt/pull/2547))
+- Format rows number in BigQuery plugin logs, [#2526](https://github.com/fishtown-analytics/dbt/issues/2526)
path: CHANGELOG.md
text: @user1:
```suggestion
- Include row counts and bytes processed in log output for all BigQuery statement types ([#2526](https://github.com/fishtown-analytics/dbt/issues/2526))
```