add frontend logging utility function (#4226)

add loading log for dash and exploreview
breakdown whole page load action to multiple charts loading events and render events

superset/assets/javascripts/chart/Chart.jsx

@@ -7,6 +7,7 @@ import { Tooltip } from 'react-bootstrap';
 import { d3format } from '../modules/utils';
 import ChartBody from './ChartBody';
 import Loading from '../components/Loading';
+import { Logger, LOG_ACTIONS_RENDER_EVENT } from '../logger';
 import StackTraceMessage from '../components/StackTraceMessage';
 import visMap from '../../visualizations/main';
 import sandboxedEval from '../modules/sandbox';
@@ -171,6 +172,7 @@ class Chart extends React.PureComponent {
     const viz = visMap[this.props.vizType];
     const fd = this.props.formData;
     const qr = this.props.queryResponse;
+    const renderStart = Logger.getTimestamp();
     try {
       // Executing user-defined data mutator function
       if (fd.js_data) {
@@ -178,6 +180,13 @@ class Chart extends React.PureComponent {
       }
       // [re]rendering the visualization
       viz(this, qr, this.props.setControlValue);
+      Logger.append(LOG_ACTIONS_RENDER_EVENT, {
+        label: this.props.chartKey,
+        vis_type: this.props.vizType,
+        start_offset: renderStart,
+        duration: Logger.getTimestamp() - renderStart,
+      });
+      this.props.actions.chartRenderingSucceeded(this.props.chartKey);
     } catch (e) {
       this.props.actions.chartRenderingFailed(e, this.props.chartKey);
     }

superset/assets/javascripts/chart/chartAction.js

@@ -1,5 +1,6 @@
 import { getExploreUrl, getAnnotationJsonUrl } from '../explore/exploreUtils';
 import { requiresQuery, ANNOTATION_SOURCE_TYPES } from '../modules/AnnotationTypes';
+import { Logger, LOG_ACTIONS_LOAD_EVENT } from '../logger';
 
 const $ = window.$ = require('jquery');
 
@@ -36,6 +37,11 @@ export function chartRenderingFailed(error, key) {
   return { type: CHART_RENDERING_FAILED, error, key };
 }
 
+export const CHART_RENDERING_SUCCEEDED = 'CHART_RENDERING_SUCCEEDED';
+export function chartRenderingSucceeded(key) {
+  return { type: CHART_RENDERING_SUCCEEDED, key };
+}
+
 export const REMOVE_CHART = 'REMOVE_CHART';
 export function removeChart(key) {
   return { type: REMOVE_CHART, key };
@@ -107,16 +113,37 @@ export const RUN_QUERY = 'RUN_QUERY';
 export function runQuery(formData, force = false, timeout = 60, key) {
   return (dispatch) => {
     const url = getExploreUrl(formData, 'json', force);
+    let logStart;
     const queryRequest = $.ajax({
       url,
       dataType: 'json',
       timeout: timeout * 1000,
+      beforeSend: () => {
+        logStart = Logger.getTimestamp();
+      },
     });
 
     const queryPromise = Promise.resolve(dispatch(chartUpdateStarted(queryRequest, key)))
       .then(() => queryRequest)
-      .then(queryResponse => dispatch(chartUpdateSucceeded(queryResponse, key)))
+      .then((queryResponse) => {
+        Logger.append(LOG_ACTIONS_LOAD_EVENT, {
+          label: key,
+          is_cached: queryResponse.is_cached,
+          row_count: queryResponse.rowcount,
+          datasource: formData.datasource,
+          start_offset: logStart,
+          duration: Logger.getTimestamp() - logStart,
+        });
+        return dispatch(chartUpdateSucceeded(queryResponse, key));
+      })
       .catch((err) => {
+        Logger.append(LOG_ACTIONS_LOAD_EVENT, {
+          label: key,
+          has_err: true,
+          datasource: formData.datasource,
+          start_offset: logStart,
+          duration: Logger.getTimestamp() - logStart,
+        });
         if (err.statusText === 'timeout') {
           dispatch(chartUpdateTimeout(err.statusText, timeout, key));
         } else if (err.statusText !== 'abort') {

superset/assets/javascripts/chart/chartReducer.js

@@ -55,6 +55,11 @@ export default function chartReducer(charts = {}, action) {
         chartAlert: t('Updating chart was stopped'),
       };
     },
+    [actions.CHART_RENDERING_SUCCEEDED](state) {
+      return { ...state,
+        chartStatus: 'rendered',
+      };
+    },
     [actions.CHART_RENDERING_FAILED](state) {
       return { ...state,
         chartStatus: 'failed',

superset/assets/javascripts/dashboard/components/Dashboard.jsx

@@ -5,6 +5,8 @@ import AlertsWrapper from '../../components/AlertsWrapper';
 import GridLayout from './GridLayout';
 import Header from './Header';
 import { areObjectsEqual } from '../../reduxUtils';
+import { Logger, ActionLog, LOG_ACTIONS_PAGE_LOAD,
+  LOG_ACTIONS_LOAD_EVENT, LOG_ACTIONS_RENDER_EVENT } from '../../logger';
 import { t } from '../../locales';
 
 import '../../../stylesheets/dashboard.css';
@@ -21,6 +23,7 @@ const propTypes = {
   userId: PropTypes.string,
   isStarred: PropTypes.bool,
   editMode: PropTypes.bool,
+  impressionId: PropTypes.string,
 };
 
 const defaultProps = {
@@ -41,6 +44,14 @@ class Dashboard extends React.PureComponent {
     super(props);
     this.refreshTimer = null;
     this.firstLoad = true;
+    this.loadingLog = new ActionLog({
+      impressionId: props.impressionId,
+      actionType: LOG_ACTIONS_PAGE_LOAD,
+      source: 'dashboard',
+      sourceId: props.dashboard.id,
+      eventNames: [LOG_ACTIONS_LOAD_EVENT, LOG_ACTIONS_RENDER_EVENT],
+    });
+    Logger.start(this.loadingLog);
 
     // alert for unsaved changes
     this.state = { unsavedChanges: false };
@@ -68,10 +79,19 @@ class Dashboard extends React.PureComponent {
   }
 
   componentDidMount() {
-    this.firstLoad = false;
     window.addEventListener('resize', this.rerenderCharts);
   }
 
+  componentWillReceiveProps(nextProps) {
+    if (this.firstLoad &&
+      Object.values(nextProps.slices)
+        .every(slice => (['rendered', 'failed', 'stopped'].indexOf(slice.chartStatus) > -1))
+    ) {
+      Logger.end(this.loadingLog);
+      this.firstLoad = false;
+    }
+  }
+
   componentDidUpdate(prevProps) {
     if (!areObjectsEqual(prevProps.filters, this.props.filters) && this.props.refresh) {
       const currentFilterKeys = Object.keys(this.props.filters);

superset/assets/javascripts/dashboard/components/DashboardContainer.jsx

@@ -5,7 +5,7 @@ import * as dashboardActions from '../actions';
 import * as chartActions from '../../chart/chartAction';
 import Dashboard from './Dashboard';
 
-function mapStateToProps({ charts, dashboard }) {
+function mapStateToProps({ charts, dashboard, impressionId }) {
   return {
     initMessages: dashboard.common.flash_messages,
     timeout: dashboard.common.conf.SUPERSET_WEBSERVER_TIMEOUT,
@@ -17,6 +17,7 @@ function mapStateToProps({ charts, dashboard }) {
     userId: dashboard.userId,
     isStarred: !!dashboard.isStarred,
     editMode: dashboard.editMode,
+    impressionId,
   };
 }
 

superset/assets/javascripts/dashboard/reducers.js

@@ -1,5 +1,6 @@
 import { combineReducers } from 'redux';
 import d3 from 'd3';
+import shortid from 'shortid';
 
 import charts, { chart } from '../chart/chartReducer';
 import * as actions from './actions';
@@ -200,4 +201,5 @@ export const dashboard = function (state = {}, action) {
 export default combineReducers({
   charts,
   dashboard,
+  impressionId: () => (shortid.generate()),
 });

superset/assets/javascripts/explore/components/ExploreViewContainer.jsx

@@ -15,23 +15,36 @@ import { chartPropType } from '../../chart/chartReducer';
 import * as exploreActions from '../actions/exploreActions';
 import * as saveModalActions from '../actions/saveModalActions';
 import * as chartActions from '../../chart/chartAction';
+import { Logger, ActionLog, LOG_ACTIONS_PAGE_LOAD,
+  LOG_ACTIONS_LOAD_EVENT, LOG_ACTIONS_RENDER_EVENT } from '../../logger';
 
 const propTypes = {
   actions: PropTypes.object.isRequired,
   datasource_type: PropTypes.string.isRequired,
   isDatasourceMetaLoading: PropTypes.bool.isRequired,
-  chartStatus: PropTypes.string,
   chart: PropTypes.shape(chartPropType).isRequired,
+  slice: PropTypes.object,
   controls: PropTypes.object.isRequired,
   forcedHeight: PropTypes.string,
   form_data: PropTypes.object.isRequired,
   standalone: PropTypes.bool.isRequired,
   timeout: PropTypes.number,
+  impressionId: PropTypes.string,
 };
 
 class ExploreViewContainer extends React.Component {
   constructor(props) {
     super(props);
+    this.firstLoad = true;
+    this.loadingLog = new ActionLog({
+      impressionId: props.impressionId,
+      actionType: LOG_ACTIONS_PAGE_LOAD,
+      source: 'slice',
+      sourceId: props.slice ? props.slice.slice_id : 0,
+      eventNames: [LOG_ACTIONS_LOAD_EVENT, LOG_ACTIONS_RENDER_EVENT],
+    });
+    Logger.start(this.loadingLog);
+
     this.state = {
       height: this.getHeight(),
       width: this.getWidth(),
@@ -44,6 +57,11 @@ class ExploreViewContainer extends React.Component {
   }
 
   componentWillReceiveProps(np) {
+    if (this.firstLoad &&
+      ['rendered', 'failed', 'stopped'].indexOf(np.chart.chartStatus) > -1) {
+      Logger.end(this.loadingLog);
+      this.firstLoad = false;
+    }
     if (np.controls.viz_type.value !== this.props.controls.viz_type.value) {
       this.props.actions.resetControls();
       this.props.actions.triggerQuery(true, this.props.chart.chartKey);
@@ -197,7 +215,7 @@ class ExploreViewContainer extends React.Component {
 
 ExploreViewContainer.propTypes = propTypes;
 
-function mapStateToProps({ explore, charts }) {
+function mapStateToProps({ explore, charts, impressionId }) {
   const form_data = getFormDataFromControls(explore.controls);
   const chartKey = Object.keys(charts)[0];
   const chart = charts[chartKey];
@@ -220,6 +238,7 @@ function mapStateToProps({ explore, charts }) {
     forcedHeight: explore.forced_height,
     chart,
     timeout: explore.common.conf.SUPERSET_WEBSERVER_TIMEOUT,
+    impressionId,
   };
 }
 

superset/assets/javascripts/explore/index.jsx

@@ -5,6 +5,7 @@ import { createStore, applyMiddleware, compose } from 'redux';
 import { Provider } from 'react-redux';
 import thunk from 'redux-thunk';
 
+import shortid from 'shortid';
 import { now } from '../modules/dates';
 import { initEnhancer } from '../reduxUtils';
 import { getChartKey } from './exploreUtils';
@@ -64,6 +65,7 @@ const initState = {
     saveModalAlert: null,
   },
   explore: bootstrappedState,
+  impressionId: shortid.generate(),
 };
 const store = createStore(rootReducer, initState,
   compose(applyMiddleware(thunk), initEnhancer(false)),

superset/assets/javascripts/explore/reducers/index.js

@@ -1,4 +1,5 @@
 import { combineReducers } from 'redux';
+import shortid from 'shortid';
 
 import charts from '../../chart/chartReducer';
 import saveModal from './saveModalReducer';
@@ -8,4 +9,5 @@ export default combineReducers({
   charts,
   saveModal,
   explore,
+  impressionId: () => (shortid.generate()),
 });

superset/assets/javascripts/logger.js

@@ -0,0 +1,114 @@
+import $ from 'jquery';
+
+export const LOG_ACTIONS_PAGE_LOAD = 'page_load_perf';
+export const LOG_ACTIONS_LOAD_EVENT = 'load_events';
+export const LOG_ACTIONS_RENDER_EVENT = 'render_events';
+
+const handlers = {};
+
+export const Logger = {
+  start(log) {
+    log.setAttribute('startAt', new Date().getTime() - this.getTimestamp());
+    log.eventNames.forEach((eventName) => {
+      if (!handlers[eventName]) {
+        handlers[eventName] = [];
+      }
+      handlers[eventName].push(log.addEvent.bind(log));
+    });
+  },
+
+  append(eventName, eventBody) {
+    return handlers[eventName].length &&
+      handlers[eventName].forEach(handler => (handler(eventName, eventBody)));
+  },
+
+  end(log) {
+    log.setAttribute('duration', new Date().getTime() - log.startAt);
+    this.send(log);
+
+    log.eventNames.forEach((eventName) => {
+      if (handlers[eventName].length) {
+        const index = handlers[eventName]
+          .findIndex(handler => (handler === log.addEvent));
+        handlers[eventName].splice(index, 1);
+      }
+    });
+  },
+
+  send(log) {
+    const { impressionId, actionType, source, sourceId, events, startAt, duration } = log;
+    const requestPrams = [];
+    requestPrams.push(['impression_id', impressionId]);
+    switch (source) {
+      case 'dashboard':
+        requestPrams.push(['dashboard_id', sourceId]);
+        break;
+      case 'slice':
+        requestPrams.push(['slice_id', sourceId]);
+        break;
+      default:
+        break;
+    }
+    let url = '/superset/log/';
+    if (requestPrams.length) {
+      url += '?' + requestPrams.map(([k, v]) => (k + '=' + v)).join('&');
+    }
+    const eventData = {};
+    for (const eventName in events) {
+      eventData[eventName] = [];
+      events[eventName].forEach((event) => {
+        eventData[eventName].push(event);
+      });
+    }
+
+    $.ajax({
+      url,
+      method: 'POST',
+      dataType: 'json',
+      data: {
+        source: 'client',
+        type: actionType,
+        started_time: startAt,
+        duration,
+        events: JSON.stringify(eventData),
+      },
+    });
+  },
+
+  getTimestamp() {
+    return Math.round(window.performance.now());
+  },
+};
+
+export class ActionLog {
+  constructor({ impressionId, actionType, source, sourceId, eventNames, sendNow }) {
+    this.impressionId = impressionId;
+    this.source = source;
+    this.sourceId = sourceId;
+    this.actionType = actionType;
+    this.eventNames = eventNames;
+    this.sendNow = sendNow || false;
+    this.startAt = 0;
+    this.duration = 0;
+    this.events = {};
+
+    this.addEvent = this.addEvent.bind(this);
+  }
+
+  setAttribute(name, value) {
+    this[name] = value;
+  }
+
+  addEvent(eventName, eventBody) {
+    if (!this.events[eventName]) {
+      this.events[eventName] = [];
+    }
+    this.events[eventName].push(eventBody);
+
+    if (this.sendNow) {
+      this.setAttribute('duration', new Date().getTime() - this.startAt);
+      Logger.send(this);
+      this.events = {};
+    }
+  }
+}

superset/assets/spec/helpers/browser.js

@@ -38,4 +38,5 @@ global.sinon.useFakeXMLHttpRequest();
 
 global.window.XMLHttpRequest = global.XMLHttpRequest;
 global.window.location = { href: 'about:blank' };
+global.window.performance = { now: () => (new Date().getTime()) };
 global.$ = require('jquery')(global.window);

superset/models/core.py

@@ -860,7 +860,7 @@ class Log(Model):
             if g.user:
                 user_id = g.user.get_id()
             d = request.args.to_dict()
-            post_data = request.form or {}
+            post_data = request.form.to_dict() or {}
             d.update(post_data)
             d.update(kwargs)
             slice_id = d.get('slice_id')

superset/views/core.py

@@ -1974,6 +1974,13 @@ class Superset(BaseSupersetView):
             bootstrap_data=json.dumps(bootstrap_data),
         )
 
+    @api
+    @has_access_api
+    @log_this
+    @expose('/log/', methods=['POST'])
+    def log(self):
+        return Response(status=200)
+
     @has_access
     @expose('/sync_druid/', methods=['POST'])
     @log_this