[dashboard v2] logging updates

[williaster]

This PR updates Dashboard logging for dashboard v2. It

1. captures additional client events we want to analyze
2. updates how we capture performance (now more complicated because of Tabs and nested Tabs). specifically it introduces mount_dashboard, mount_explorer, and load_dashboard_pane events
3. it normalizes batch client logs, inserting one row per event, instead of logging a large blob containing an array of multiple events.

Some events are logged immediately, while others are "batched" similar to the current dashboard logging.

Event name changes (made for improved event name clarity)

• page_load_perf => load_dashboard_pane (see below for details)
• load_events => load_chart_data (dashboard + explorer views)
  • event now includes vis_type, has_extra_filters, and force_refresh fields
• render_events => render_chart (dashboard + explorer views)
  • note: this event already included vis_type

New dashboard click events that are captured

• force refresh chart
• force_refresh_dashboard
• change_dashboard_filter
• explore_dashboard_chart*
• export_csv_dashboard_chart*

*denotes dispatched immediately, the others cause page re-renders and therefore result in a batch event

Updated performance logs

Previously we captured a single page_load_perf event the first time all dashboard charts were loaded (or explore view loaded). To reduce the number of ajax calls, this was a "batch event" and included all chart data fetching + render events under the events. This event

• does not capture subsequent page loads (e.g., when a filter is added, or an entire dashboard is refreshed)
• no longer makes sense in the context of dashboard v2 tabs + nested tabs
• does not explode the multiple events into their own log rows (arguably better for downstream analysis)

This PR replaces the single page_load_perf event with (potentially multiple) load_dashboard_pane events, each of which is a batched event. A dashboard "pane" is any of the following:

• simply the dashboard page (if no tabs exist)
• A top-level tab
• A dashboard-level tab (a tab within the page)

A load_dashboard_pane event is dispatched every time all of the charts within a pane (not including any nested within another set of tabs!) go from an unloaded => loaded state. This includes when a filter changes or force refreshes. Every load_dashboard_pane event includes the following metadata about the pane:

• start_offset ms offset from page load time when the pane began to load (if you click on a tab 2 minutes into a session, this would be (2 min * 60 s/min * 1000 min/s)
• duration ms duration of all chart data requests
• id the layout component id of the pane
• type the layout type of the pane (grid or tab)
• parentType parent pane type, null if the pane is a top-level tab or no top-level tabs exist
• parentId id of the parent layout component (useful if you want to associate two tab panes with a common set of tabs)
• index the index of the pane (0 for grid, 0-5 for tabs)
• depth the depth of the pane (0 for grid or top-level tabs, 1 for nested tabs [you cannot nest tabs beyond this])
• chartCount number of charts within the tab (not including any nested tabs)

New performance logging

• A new mount_dashboard event was added and will be included in the first load_dashboard_pane batch event. The start_offset value in this event is effectively the amount of time it takes for a user to see something on their screen (so, bundle download + parsing time) and marks the point at which the Dashboard React component mounts and therefore chart queries begin.
• A similar, new mount_explorer event was added with an equivalent start_offset value

General logger.js changes

I made the following changes/improvements to the logger util file

• do not allow multiple ActionLoggers to handle the same event type (I'm not convinced this wasn't buggy previously, and seems unnecessary)
• add source, source_id, ts, start_offset, event_name, and impression_id to all events within in a batch action (to support unrolling batched events into multiple rows and re-associating with the batch action)
• batched log source value changed from client to dashboard or slice depending on its source
• because batch events are now exploded and inserted as multiple single-event log rows, the following top-level batch event key/values were removed: duration and actionType

@graceguo-supercat let me know if you see any issues with this + the changes I made to logger.js
@john-bodley @michellethomas @mistercrunch

Remaining TODO

• test / validate
  • batching
  • multiple types of tab layouts
  • explore view
  • add logger_spec
• filter render events that come from chart resizes?
• hook up refresh chart + refresh dashboard events
• add unravelling of batched logs on the backend
• remove unnecessary start_offset values in Logger calls (now included in every event)
• add dashboard_first_load event
• add slice_ids to dashboard_pane_load event

[williaster]

note that this was changed because ADD_FILTER was really used for both adding and removing filters. REMOVE_FILTER was never used by anything in the dashboard app.

[williaster]

update: this is what explore logging looks like now

[williaster]

@john-bodley @graceguo-supercat I refactored to use bulk log insertions for batch evetns in Python, PTAL 👀

[john-bodley]

Nit. I think the duration should really only capture the f(*args, **kwargs) call.

[john-bodley]

No need for None as that's the default return value for dict.get(key) if key doesn't exist.

[john-bodley]

You can delete line #919 and replace line #923 with events = None.

[john-bodley]

If you change line #923 to be events = [d] you don't need to repeat the cls(...) call. I would also maybe rename events to records as it's more representative of what these are. Note the only difference is previously params could be an empty string whereas now it would be None (which translates to a NULL in the database), though this is preferred in my opinion

try:
    records = json.loads(d.get(explode_by))
except Exception:
    records = [d]

for records in records:
    log = cls(...)
    logs.appen(log)

[williaster]

dig this and renaming to records

previously params could be an empty string whereas now it would be None

the previous logic set params to empty string and try/catch parsed it to json, whereas this approach has no try/catch and would simply json.dumps(d). so I don't think it'd be None and there's the potential risk of it throwing in that conversion?

[williaster]

I think with this approach (ie a single for loop for logs), we'd need a try catch within the for loop in case json.dumps failed

[williaster]

@graceguo-supercat yes, below each event becomes a row, this is the json column of that row (python also adds dttm, user, slice/dashboard id if it exists)

dashboard view

[
  {
    "source": "dashboard",
    "source_id": 10,
    "event_name": "mount_dashboard",
    "impression_id": "ry8ULDny7",
    "ts": 1527703118214,
    "start_offset": 9859
  },
  {
    "source": "dashboard",
    "source_id": 10,
    "event_name": "load_chart_data",
    "impression_id": "ry8ULDny7",
    "ts": 1527703156723,
    "start_offset": 47889,
    "slice_id": "slice_15",
    "is_cached": false,
    "force_refresh": false,
    "row_count": 50,
    "datasource": "7__table",
    "duration": 480,
    "has_extra_filters": false,
    "viz_type": "table"
  },
  {
    "source": "dashboard",
    "source_id": 10,
    "event_name": "load_chart_data",
    "impression_id": "ry8ULDny7",
    "ts": 1527703156901,
    "start_offset": 47896,
    "slice_id": "slice_16",
    "is_cached": false,
    "force_refresh": false,
    "row_count": 50,
    "datasource": "7__table",
    "duration": 652,
    "has_extra_filters": false,
    "viz_type": "table"
  },
  {
    "source": "dashboard",
    "source_id": 10,
    "event_name": "load_chart_data",
    "impression_id": "ry8ULDny7",
    "ts": 1527703157012,
    "start_offset": 47883,
    "slice_id": "slice_20",
    "is_cached": false,
    "force_refresh": false,
    "row_count": 1092,
    "datasource": "7__table",
    "duration": 775,
    "has_extra_filters": false,
    "viz_type": "line"
  },
  {
    "source": "dashboard",
    "source_id": 10,
    "event_name": "render_chart",
    "impression_id": "ry8ULDny7",
    "ts": 1527703156878,
    "start_offset": 48380,
    "label": "slice_15",
    "vis_type": "table",
    "duration": 145
  },
  {
    "source": "dashboard",
    "source_id": 10,
    "event_name": "render_chart",
    "impression_id": "ry8ULDny7",
    "ts": 1527703156988,
    "start_offset": 48574,
    "label": "slice_16",
    "vis_type": "table",
    "duration": 61
  },
  {
    "source": "dashboard",
    "source_id": 10,
    "event_name": "render_chart",
    "impression_id": "ry8ULDny7",
    "ts": 1527703157022,
    "start_offset": 48667,
    "label": "slice_20",
    "vis_type": "line",
    "duration": 1
  },
  {
    "source": "dashboard",
    "source_id": 10,
    "event_name": "load_dashboard_pane",
    "impression_id": "ry8ULDny7",
    "ts": 1527703157022,
    "start_offset": 48668,
    "id": "DASHBOARD_TAB_TYPE-HkZkwVkwTz",
    "type": "DASHBOARD_TAB_TYPE",
    "parentType": null,
    "parentId": null,
    "index": 0,
    "depth": 0,
    "chartCount": 3,
    "duration": 784
  }
]

explorer view

[
  {
    "source": "slice",
    "source_id": 6,
    "event_name": "mount_explorer",
    "impression_id": "HJwBLw3k7",
    "ts": 1527703104483,
    "start_offset": 7892
  },
  {
    "source": "slice",
    "source_id": 6,
    "event_name": "load_chart_data",
    "impression_id": "HJwBLw3k7",
    "ts": 1527703106080,
    "start_offset": 7885,
    "slice_id": "slice_6",
    "is_cached": false,
    "force_refresh": false,
    "row_count": 5,
    "datasource": "6__table",
    "duration": 1605,
    "viz_type": "table"
  },
  {
    "source": "slice",
    "source_id": 6,
    "event_name": "render_chart",
    "impression_id": "HJwBLw3k7",
    "ts": 1527703106159,
    "start_offset": 9516,
    "label": "slice_6",
    "vis_type": "table",
    "duration": 52
  }
]

[graceguo-supercat]

js code changes LGTM.

[williaster]

talked to @john-bodley offline, merging this 👍