Explore: Logging render performance

- moved from grid to flexbox - calculate Explore results only when query transactions change to prevent expensive re-renders - split up rendering of graph and log data - render log results in 2 stages
2024-11-26 02:40:26 -06:00 · 2018-11-29 17:09:32 +01:00 · 2018-11-29 17:09:32 +01:00 · ae26f7126f
commit ae26f7126f
parent 8024a6aa9f
5 changed files with 231 additions and 93 deletions
--- a/public/app/core/utils/explore.test.ts
+++ b/public/app/core/utils/explore.test.ts
@ -16,7 +16,7 @@ const DEFAULT_EXPLORE_STATE: ExploreState = {
  datasourceMissing: false,
  datasourceName: '',
  exploreDatasources: [],
-  graphRange: DEFAULT_RANGE,
+  graphInterval: 1000,
  history: [],
  initialQueries: [],
  queryTransactions: [],
--- a/public/app/features/explore/Explore.tsx
+++ b/public/app/features/explore/Explore.tsx
@ -50,6 +50,35 @@ interface ExploreProps {
  urlState: ExploreUrlState;
 }

+function calulcateResultsFromQueryTransactions(
+  queryTransactions: QueryTransaction[],
+  datasource: any,
+  graphInterval: number
+) {
+  const graphResult = _.flatten(
+    queryTransactions.filter(qt => qt.resultType === 'Graph' && qt.done && qt.result).map(qt => qt.result)
+  );
+  const tableResult = mergeTablesIntoModel(
+    new TableModel(),
+    ...queryTransactions.filter(qt => qt.resultType === 'Table' && qt.done && qt.result).map(qt => qt.result)
+  );
+  const logsResult =
+    datasource && datasource.mergeStreams
+      ? datasource.mergeStreams(
+          _.flatten(
+            queryTransactions.filter(qt => qt.resultType === 'Logs' && qt.done && qt.result).map(qt => qt.result)
+          ),
+          graphInterval
+        )
+      : undefined;
+
+  return {
+    graphResult,
+    tableResult,
+    logsResult,
+  };
+}
+
 /**
 * Explore provides an area for quick query iteration for a given datasource.
 * Once a datasource is selected it populates the query section at the top.
@ -122,9 +151,11 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
        datasourceMissing: false,
        datasourceName: datasource,
        exploreDatasources: [],
-        graphRange: initialRange,
+        graphInterval: 15 * 1000,
+        graphResult: [],
        initialQueries,
        history: [],
+        logsResult: null,
        queryTransactions: [],
        range: initialRange,
        scanning: false,
@ -135,6 +166,7 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
        supportsGraph: null,
        supportsLogs: null,
        supportsTable: null,
+        tableResult: new TableModel(),
      };
    }
    this.modifiedQueries = initialQueries.slice();
@ -176,6 +208,8 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
  }

  async setDatasource(datasource: any, origin?: DataSource) {
+    const { initialQueries, range } = this.state;
+
    const supportsGraph = datasource.meta.metrics;
    const supportsLogs = datasource.meta.logs;
    const supportsTable = datasource.meta.metrics;
@ -220,7 +254,7 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
    }

    // Reset edit state with new queries
-    const nextQueries = this.state.initialQueries.map((q, i) => ({
+    const nextQueries = initialQueries.map((q, i) => ({
      ...modifiedQueries[i],
      ...generateQueryKeys(i),
    }));
@ -229,11 +263,15 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
    // Custom components
    const StartPage = datasource.pluginExports.ExploreStartPage;

+    // Calculate graph bucketing interval
+    const graphInterval = getIntervals(range, datasource, this.el ? this.el.offsetWidth : 0).intervalMs;
+
    this.setState(
      {
        StartPage,
        datasource,
        datasourceError,
+        graphInterval,
        history,
        supportsGraph,
        supportsLogs,
@ -414,12 +452,19 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
    this.setState(
      state => {
        const showingTable = !state.showingTable;
-        let nextQueryTransactions = state.queryTransactions;
-        if (!showingTable) {
-          // Discard transactions related to Table query
-          nextQueryTransactions = state.queryTransactions.filter(qt => qt.resultType !== 'Table');
+        if (showingTable) {
+          return { showingTable, queryTransactions: state.queryTransactions };
        }
-        return { queryTransactions: nextQueryTransactions, showingTable };
+
+        // Toggle off needs discarding of table queries
+        const nextQueryTransactions = state.queryTransactions.filter(qt => qt.resultType !== 'Table');
+        const results = calulcateResultsFromQueryTransactions(
+          nextQueryTransactions,
+          state.datasource,
+          state.graphInterval
+        );
+
+        return { ...results, queryTransactions: nextQueryTransactions, showingTable };
      },
      () => {
        if (this.state.showingTable) {
@ -500,8 +545,14 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {

        // Discard transactions related to row query
        const nextQueryTransactions = queryTransactions.filter(qt => qt.rowIndex !== index);
+        const results = calulcateResultsFromQueryTransactions(
+          nextQueryTransactions,
+          state.datasource,
+          state.graphInterval
+        );

        return {
+          ...results,
          initialQueries: nextQueries,
          queryTransactions: nextQueryTransactions,
        };
@ -609,7 +660,14 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
      // Append new transaction
      const nextQueryTransactions = [...remainingTransactions, transaction];

+      const results = calulcateResultsFromQueryTransactions(
+        nextQueryTransactions,
+        state.datasource,
+        state.graphInterval
+      );
+
      return {
+        ...results,
        queryTransactions: nextQueryTransactions,
        showingStartPage: false,
      };
@ -660,6 +718,12 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
        return qt;
      });

+      const results = calulcateResultsFromQueryTransactions(
+        nextQueryTransactions,
+        state.datasource,
+        state.graphInterval
+      );
+
      const nextHistory = updateHistory(history, datasourceId, queries);

      // Keep scanning for results if this was the last scanning transaction
@ -671,19 +735,13 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
      }

      return {
+        ...results,
        history: nextHistory,
        queryTransactions: nextQueryTransactions,
      };
    });
  }

-  discardTransactions(rowIndex: number) {
-    this.setState(state => {
-      const remainingTransactions = state.queryTransactions.filter(qt => qt.rowIndex !== rowIndex);
-      return { queryTransactions: remainingTransactions };
-    });
-  }
-
  failQueryTransaction(transactionId: string, response: any, datasourceId: string) {
    const { datasource } = this.state;
    if (datasource.meta.id !== datasourceId || response.cancelled) {
@ -746,7 +804,6 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
        const latency = Date.now() - now;
        const results = resultGetter ? resultGetter(res.data) : res.data;
        this.completeQueryTransaction(transaction.id, results, latency, queries, datasourceId);
-        this.setState({ graphRange: transaction.options.range });
      } catch (response) {
        this.failQueryTransaction(transaction.id, response, datasourceId);
      }
@ -776,9 +833,10 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
      datasourceLoading,
      datasourceMissing,
      exploreDatasources,
-      graphRange,
+      graphResult,
      history,
      initialQueries,
+      logsResult,
      queryTransactions,
      range,
      scanning,
@ -790,31 +848,14 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
      supportsGraph,
      supportsLogs,
      supportsTable,
+      tableResult,
    } = this.state;
    const graphHeight = showingGraph && showingTable ? '200px' : '400px';
    const exploreClass = split ? 'explore explore-split' : 'explore';
    const selectedDatasource = datasource ? exploreDatasources.find(d => d.label === datasource.name) : undefined;
-    const graphRangeIntervals = getIntervals(graphRange, datasource, this.el ? this.el.offsetWidth : 0);
    const graphLoading = queryTransactions.some(qt => qt.resultType === 'Graph' && !qt.done);
    const tableLoading = queryTransactions.some(qt => qt.resultType === 'Table' && !qt.done);
    const logsLoading = queryTransactions.some(qt => qt.resultType === 'Logs' && !qt.done);
-    // TODO don't recreate those on each re-render
-    const graphResult = _.flatten(
-      queryTransactions.filter(qt => qt.resultType === 'Graph' && qt.done && qt.result).map(qt => qt.result)
-    );
-    const tableResult = mergeTablesIntoModel(
-      new TableModel(),
-      ...queryTransactions.filter(qt => qt.resultType === 'Table' && qt.done && qt.result).map(qt => qt.result)
-    );
-    const logsResult =
-      datasource && datasource.mergeStreams
-        ? datasource.mergeStreams(
-            _.flatten(
-              queryTransactions.filter(qt => qt.resultType === 'Logs' && qt.done && qt.result).map(qt => qt.result)
-            ),
-            graphRangeIntervals.intervalMs
-          )
-        : undefined;
    const loading = queryTransactions.some(qt => !qt.done);

    return (
@ -919,7 +960,7 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
                          height={graphHeight}
                          id={`explore-graph-${position}`}
                          onChangeTime={this.onChangeTime}
-                          range={graphRange}
+                          range={range}
                          split={split}
                        />
                      </Panel>
--- a/public/app/features/explore/Logs.tsx
+++ b/public/app/features/explore/Logs.tsx
@ -1,5 +1,5 @@
 import _ from 'lodash';
-import React, { Fragment, PureComponent } from 'react';
+import React, { PureComponent } from 'react';
 import Highlighter from 'react-highlight-words';

 import * as rangeUtil from 'app/core/utils/rangeutil';
@ -12,12 +12,15 @@ import {
  LogLevel,
  LogsStreamLabels,
  LogsMetaKind,
+  LogRow,
 } from 'app/core/logs_model';
 import { findHighlightChunksInText } from 'app/core/utils/text';
 import { Switch } from 'app/core/components/Switch/Switch';

 import Graph from './Graph';

+const RENDER_LIMIT = 100;
+
 const graphOptions = {
  series: {
    bars: {
@ -77,6 +80,58 @@ class Labels extends PureComponent<{
  }
 }

+interface RowProps {
+  row: LogRow;
+  showLabels: boolean | null; // Tristate: null means auto
+  showLocalTime: boolean;
+  showUtc: boolean;
+  onClickLabel?: (label: string, value: string) => void;
+}
+
+function Row({ onClickLabel, row, showLabels, showLocalTime, showUtc }: RowProps) {
+  const needsHighlighter = row.searchWords && row.searchWords.length > 0;
+  return (
+    <div className="logs-row">
+      <div className={row.logLevel ? `logs-row-level logs-row-level-${row.logLevel}` : ''}>
+        {row.duplicates > 0 && (
+          <div className="logs-row-level__duplicates" title={`${row.duplicates} duplicates`}>
+            {Array.apply(null, { length: row.duplicates }).map((bogus, index) => (
+              <div className="logs-row-level__duplicate" key={`${index}`} />
+            ))}
+          </div>
+        )}
+      </div>
+      {showUtc && (
+        <div className="logs-row-time" title={`Local: ${row.timeLocal} (${row.timeFromNow})`}>
+          {row.timestamp}
+        </div>
+      )}
+      {showLocalTime && (
+        <div className="logs-row-time" title={`${row.timestamp} (${row.timeFromNow})`}>
+          {row.timeLocal}
+        </div>
+      )}
+      {showLabels && (
+        <div className="logs-row-labels">
+          <Labels labels={row.uniqueLabels} onClickLabel={onClickLabel} />
+        </div>
+      )}
+      <div className="logs-row-message">
+        {needsHighlighter ? (
+          <Highlighter
+            textToHighlight={row.entry}
+            searchWords={row.searchWords}
+            findChunks={findHighlightChunksInText}
+            highlightClassName="logs-row-match-highlight"
+          />
+        ) : (
+          row.entry
+        )}
+      </div>
+    </div>
+  );
+}
+
 interface LogsProps {
  className?: string;
  data: LogsModel;
@ -93,21 +148,51 @@ interface LogsProps {

 interface LogsState {
  dedup: LogsDedupStrategy;
+  deferLogs: boolean;
  hiddenLogLevels: Set<LogLevel>;
+  renderAll: boolean;
  showLabels: boolean | null; // Tristate: null means auto
  showLocalTime: boolean;
  showUtc: boolean;
 }

 export default class Logs extends PureComponent<LogsProps, LogsState> {
+  deferLogsTimer: NodeJS.Timer;
+  renderAllTimer: NodeJS.Timer;
+
  state = {
    dedup: LogsDedupStrategy.none,
+    deferLogs: true,
    hiddenLogLevels: new Set(),
+    renderAll: false,
    showLabels: null,
    showLocalTime: true,
    showUtc: false,
  };

+  componentWillReceiveProps(nextProps) {
+    // Reset to render minimal only
+    if (nextProps.data !== this.props.data) {
+      this.setState({ deferLogs: true, renderAll: false });
+    }
+  }
+
+  componentDidUpdate(prevProps, prevState) {
+    // Staged rendering
+    if (prevProps.data !== this.props.data && this.state.deferLogs) {
+      clearTimeout(this.deferLogsTimer);
+      this.deferLogsTimer = setTimeout(() => this.setState({ deferLogs: false }), 1000);
+    } else if (prevState.deferLogs && !this.state.deferLogs) {
+      clearTimeout(this.renderAllTimer);
+      this.renderAllTimer = setTimeout(() => this.setState({ renderAll: true }), 2000);
+    }
+  }
+
+  componentWillUnmount() {
+    clearTimeout(this.deferLogsTimer);
+    clearTimeout(this.renderAllTimer);
+  }
+
  onChangeDedup = (dedup: LogsDedupStrategy) => {
    this.setState(prevState => {
      if (prevState.dedup === dedup) {
@ -155,7 +240,7 @@ export default class Logs extends PureComponent<LogsProps, LogsState> {

  render() {
    const { className = '', data, loading = false, onClickLabel, position, range, scanning, scanRange } = this.props;
-    const { dedup, hiddenLogLevels, showLocalTime, showUtc } = this.state;
+    const { dedup, deferLogs, hiddenLogLevels, renderAll, showLocalTime, showUtc } = this.state;
    let { showLabels } = this.state;
    const hasData = data && data.rows && data.rows.length > 0;

@ -172,26 +257,19 @@ export default class Logs extends PureComponent<LogsProps, LogsState> {
      });
    }

+    // Staged rendering
+    const firstRows = dedupedData.rows.slice(0, RENDER_LIMIT);
+    const lastRows = dedupedData.rows.slice(RENDER_LIMIT);
+
    // Check for labels
-    if (showLabels === null && hasData) {
-      showLabels = data.rows.some(row => _.size(row.uniqueLabels) > 0);
+    if (showLabels === null) {
+      if (hasData) {
+        showLabels = data.rows.some(row => _.size(row.uniqueLabels) > 0);
+      } else {
+        showLabels = true;
+      }
    }

-    // Grid options
-    const cssColumnSizes = ['3px']; // Log-level indicator line
-    if (showUtc) {
-      cssColumnSizes.push('minmax(100px, max-content)');
-    }
-    if (showLocalTime) {
-      cssColumnSizes.push('minmax(100px, max-content)');
-    }
-    if (showLabels) {
-      cssColumnSizes.push('minmax(100px, 25%)');
-    }
-    cssColumnSizes.push('1fr');
-    const logEntriesStyle = {
-      gridTemplateColumns: cssColumnSizes.join(' '),
-    };
    const scanText = scanRange ? `Scanning ${rangeUtil.describeTimeRange(scanRange)}` : 'Scanning...';

    return (
@ -251,36 +329,33 @@ export default class Logs extends PureComponent<LogsProps, LogsState> {
          </div>
        </div>

-        <div className="logs-entries" style={logEntriesStyle}>
+        <div className="logs-entries">
          {hasData &&
-            dedupedData.rows.map(row => (
-              <Fragment key={row.key + row.duplicates}>
-                <div className={row.logLevel ? `logs-row-level logs-row-level-${row.logLevel}` : ''}>
-                  {row.duplicates > 0 && (
-                    <div className="logs-row-level__duplicates" title={`${row.duplicates} duplicates`}>
-                      {Array.apply(null, { length: row.duplicates }).map((bogus, index) => (
-                        <div className="logs-row-level__duplicate" key={`${index}`} />
-                      ))}
-                    </div>
-                  )}
-                </div>
-                {showUtc && <div title={`Local: ${row.timeLocal} (${row.timeFromNow})`}>{row.timestamp}</div>}
-                {showLocalTime && <div title={`${row.timestamp} (${row.timeFromNow})`}>{row.timeLocal}</div>}
-                {showLabels && (
-                  <div className="logs-row-labels">
-                    <Labels labels={row.uniqueLabels} onClickLabel={onClickLabel} />
-                  </div>
-                )}
-                <div>
-                  <Highlighter
-                    textToHighlight={row.entry}
-                    searchWords={row.searchWords}
-                    findChunks={findHighlightChunksInText}
-                    highlightClassName="logs-row-match-highlight"
-                  />
-                </div>
-              </Fragment>
+            !deferLogs &&
+            firstRows.map(row => (
+              <Row
+                key={row.key + row.duplicates}
+                row={row}
+                showLabels={showLabels}
+                showLocalTime={showLocalTime}
+                showUtc={showUtc}
+                onClickLabel={onClickLabel}
+              />
            ))}
+          {hasData &&
+            !deferLogs &&
+            renderAll &&
+            lastRows.map(row => (
+              <Row
+                key={row.key + row.duplicates}
+                row={row}
+                showLabels={showLabels}
+                showLocalTime={showLocalTime}
+                showUtc={showUtc}
+                onClickLabel={onClickLabel}
+              />
+            ))}
+          {hasData && deferLogs && <span>Rendering {dedupedData.rows.length} rows...</span>}
        </div>
        {!loading &&
          !hasData &&
--- a/public/app/types/explore.ts
+++ b/public/app/types/explore.ts
@ -1,6 +1,8 @@
 import { Value } from 'slate';

 import { DataQuery, RawTimeRange } from './series';
+import TableModel from 'app/core/table_model';
+import { LogsModel } from 'app/core/logs_model';

 export interface CompletionItem {
  /**
@ -158,9 +160,11 @@ export interface ExploreState {
  datasourceMissing: boolean;
  datasourceName?: string;
  exploreDatasources: ExploreDatasource[];
-  graphRange: RawTimeRange;
+  graphInterval: number; // in ms
+  graphResult?: any[];
  history: HistoryItem[];
  initialQueries: DataQuery[];
+  logsResult?: LogsModel;
  queryTransactions: QueryTransaction[];
  range: RawTimeRange;
  scanning?: boolean;
@ -172,6 +176,7 @@ export interface ExploreState {
  supportsGraph: boolean | null;
  supportsLogs: boolean | null;
  supportsTable: boolean | null;
+  tableResult?: TableModel;
 }

 export interface ExploreUrlState {
--- a/public/sass/pages/_explore.scss
+++ b/public/sass/pages/_explore.scss
@ -244,15 +244,6 @@

 .explore {
  .logs {
-    .logs-entries {
-      display: grid;
-      grid-column-gap: 1rem;
-      grid-row-gap: 0.1rem;
-      grid-template-columns: 4px minmax(100px, max-content) minmax(100px, 25%) 1fr;
-      font-family: $font-family-monospace;
-      font-size: 12px;
-    }
-
    .logs-controls {
      display: flex;
      background-color: $page-bg;
@ -302,6 +293,32 @@
      top: 4px;
    }

+    .logs-entries {
+      font-family: $font-family-monospace;
+      font-size: 12px;
+    }
+
+    .logs-row {
+      display: flex;
+      flex-direction: row;
+
+      > div + div {
+        margin-left: 0.5rem;
+      }
+    }
+
+    .logs-row-level {
+      width: 3px;
+    }
+
+    .logs-row-labels {
+      flex: 0 0 25%;
+    }
+
+    .logs-row-message {
+      flex: 1;
+    }
+
    .logs-row-match-highlight {
      // Undoing mark styling
      background: inherit;