Adding `end_result_backend_time` to Query model (#2766)

This will help us keep track on how long it takes to push the data
into the results backend.

superset/migrations/versions/a65458420354_add_result_backend_time_logging.py

@@ -0,0 +1,26 @@
+"""add_result_backend_time_logging
+
+Revision ID: a65458420354
+Revises: 2fcdcb35e487
+Create Date: 2017-04-25 10:00:58.053120
+
+"""
+from alembic import op
+import sqlalchemy as sa
+
+# revision identifiers, used by Alembic.
+revision = 'a65458420354'
+down_revision = '2fcdcb35e487'
+
+
+def upgrade():
+    op.add_column(
+        'query',
+        sa.Column(
+            'end_result_backend_time',
+            sa.Numeric(precision=20, scale=6),
+            nullable=True))
+
+
+def downgrade():
+    op.drop_column('query', 'end_result_backend_time')

superset/models/sql_lab.py

@@ -65,9 +65,11 @@ class Query(Model):
 
     # Using Numeric in place of DateTime for sub-second precision
     # stored as seconds since epoch, allowing for milliseconds
-    start_time = Column(Numeric(precision=3))
-    start_running_time = Column(Numeric(precision=3))
-    end_time = Column(Numeric(precision=3))
+    start_time = Column(Numeric(precision=20, scale=6))
+    start_running_time = Column(Numeric(precision=20, scale=6))
+    end_time = Column(Numeric(precision=20, scale=6))
+    end_result_backend_time = Column(Numeric(precision=20, scale=6))
+
     changed_on = Column(
         DateTime,
         default=datetime.utcnow,

superset/sql_lab.py

@@ -188,6 +188,7 @@ def get_sql_results(self, query_id, return_results=True, store_results=False):
         logging.info("Storing results in results backend, key: {}".format(key))
         results_backend.set(key, utils.zlib_compress(payload))
         query.results_key = key
+        query.end_result_backend_time = utils.now_as_float()
 
     session.merge(query)
     session.commit()