diff --git a/superset/assets/javascripts/chart/Chart.jsx b/superset/assets/javascripts/chart/Chart.jsx index e1502a3a2114..d370c7947daf 100644 --- a/superset/assets/javascripts/chart/Chart.jsx +++ b/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); } diff --git a/superset/assets/javascripts/chart/chartAction.js b/superset/assets/javascripts/chart/chartAction.js index 393400d6bcd6..3682949bbb38 100644 --- a/superset/assets/javascripts/chart/chartAction.js +++ b/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') { diff --git a/superset/assets/javascripts/chart/chartReducer.js b/superset/assets/javascripts/chart/chartReducer.js index 3cc9e5e6dfc3..e1dfe0524d4e 100644 --- a/superset/assets/javascripts/chart/chartReducer.js +++ b/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', diff --git a/superset/assets/javascripts/dashboard/components/Dashboard.jsx b/superset/assets/javascripts/dashboard/components/Dashboard.jsx index cc85cad06758..c99c293604ad 100644 --- a/superset/assets/javascripts/dashboard/components/Dashboard.jsx +++ b/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); diff --git a/superset/assets/javascripts/dashboard/components/DashboardContainer.jsx b/superset/assets/javascripts/dashboard/components/DashboardContainer.jsx index 092caf6745b1..a18a5d2990a2 100644 --- a/superset/assets/javascripts/dashboard/components/DashboardContainer.jsx +++ b/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, }; } diff --git a/superset/assets/javascripts/dashboard/reducers.js b/superset/assets/javascripts/dashboard/reducers.js index 0ee7964ab121..1e37aca9fb6c 100644 --- a/superset/assets/javascripts/dashboard/reducers.js +++ b/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()), }); diff --git a/superset/assets/javascripts/explore/components/ExploreViewContainer.jsx b/superset/assets/javascripts/explore/components/ExploreViewContainer.jsx index 835cc1a3beef..bf9afd4be34b 100644 --- a/superset/assets/javascripts/explore/components/ExploreViewContainer.jsx +++ b/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, }; } diff --git a/superset/assets/javascripts/explore/index.jsx b/superset/assets/javascripts/explore/index.jsx index d66ad52e79fa..35eb68db975b 100644 --- a/superset/assets/javascripts/explore/index.jsx +++ b/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)), diff --git a/superset/assets/javascripts/explore/reducers/index.js b/superset/assets/javascripts/explore/reducers/index.js index 22f7e8f30329..13d0ed1b0bb6 100644 --- a/superset/assets/javascripts/explore/reducers/index.js +++ b/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()), }); diff --git a/superset/assets/javascripts/logger.js b/superset/assets/javascripts/logger.js new file mode 100644 index 000000000000..c7823fcf2e25 --- /dev/null +++ b/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 = {}; + } + } +} diff --git a/superset/assets/spec/helpers/browser.js b/superset/assets/spec/helpers/browser.js index 638a63dcc8d6..d465d864733e 100644 --- a/superset/assets/spec/helpers/browser.js +++ b/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); diff --git a/superset/models/core.py b/superset/models/core.py index 1b71d42c4b23..142482bdbd73 100644 --- a/superset/models/core.py +++ b/superset/models/core.py @@ -860,7 +860,7 @@ def wrapper(*args, **kwargs): 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') diff --git a/superset/views/core.py b/superset/views/core.py index db905f3a82b9..0f0adea149ed 100755 --- a/superset/views/core.py +++ b/superset/views/core.py @@ -1974,6 +1974,13 @@ def dashboard(**kwargs): # noqa 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