Merge pull request #14236 from grafana/davkal/explore-logging-rendeer

Explore: Logging render performance

public/app/core/logs_model.ts

@@ -58,6 +58,7 @@ export interface LogsMetaItem {
 }
 
 export interface LogsModel {
+  id: string; // Identify one logs result from another
   meta?: LogsMetaItem[];
   rows: LogRow[];
   series?: TimeSeries[];

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: [],

public/app/core/utils/explore.ts

@@ -1,7 +1,10 @@
+import _ from 'lodash';
+
 import { renderUrl } from 'app/core/utils/url';
-import { ExploreState, ExploreUrlState, HistoryItem } from 'app/types/explore';
+import { ExploreState, ExploreUrlState, HistoryItem, QueryTransaction } from 'app/types/explore';
 import { DataQuery, RawTimeRange } from 'app/types/series';
 
+import TableModel, { mergeTablesIntoModel } from 'app/core/table_model';
 import kbn from 'app/core/utils/kbn';
 import colors from 'app/core/utils/colors';
 import TimeSeries from 'app/core/time_series2';
@@ -133,6 +136,35 @@ export function hasNonEmptyQuery(queries: DataQuery[]): boolean {
   return queries.some(query => Object.keys(query).length > 2);
 }
 
+export function calculateResultsFromQueryTransactions(
+  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,
+  };
+}
+
 export function getIntervals(
   range: RawTimeRange,
   datasource,

public/app/features/explore/Explore.tsx

@@ -16,6 +16,7 @@ import { RawTimeRange, DataQuery } from 'app/types/series';
 import store from 'app/core/store';
 import {
   DEFAULT_RANGE,
+  calculateResultsFromQueryTransactions,
   ensureQueries,
   getIntervals,
   generateKey,
@@ -28,7 +29,7 @@ import ResetStyles from 'app/core/components/Picker/ResetStyles';
 import PickerOption from 'app/core/components/Picker/PickerOption';
 import IndicatorsContainer from 'app/core/components/Picker/IndicatorsContainer';
 import NoOptionsMessage from 'app/core/components/Picker/NoOptionsMessage';
-import TableModel, { mergeTablesIntoModel } from 'app/core/table_model';
+import TableModel from 'app/core/table_model';
 import { DatasourceSrv } from 'app/features/plugins/datasource_srv';
 
 import Panel from './Panel';
@@ -115,6 +116,8 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
       const { datasource, queries, range } = props.urlState as ExploreUrlState;
       initialQueries = ensureQueries(queries);
       const initialRange = range || { ...DEFAULT_RANGE };
+      // Millies step for helper bar charts
+      const initialGraphInterval = 15 * 1000;
       this.state = {
         datasource: null,
         datasourceError: null,
@@ -122,9 +125,11 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
         datasourceMissing: false,
         datasourceName: datasource,
         exploreDatasources: [],
-        graphRange: initialRange,
+        graphInterval: initialGraphInterval,
+        graphResult: [],
         initialQueries,
         history: [],
+        logsResult: null,
         queryTransactions: [],
         range: initialRange,
         scanning: false,
@@ -135,6 +140,7 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
         supportsGraph: null,
         supportsLogs: null,
         supportsTable: null,
+        tableResult: new TableModel(),
       };
     }
     this.modifiedQueries = initialQueries.slice();
@@ -176,6 +182,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 +228,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 +237,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 +426,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 = calculateResultsFromQueryTransactions(
+          nextQueryTransactions,
+          state.datasource,
+          state.graphInterval
+        );
+
+        return { ...results, queryTransactions: nextQueryTransactions, showingTable };
       },
       () => {
         if (this.state.showingTable) {
@@ -500,8 +519,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 = calculateResultsFromQueryTransactions(
+          nextQueryTransactions,
+          state.datasource,
+          state.graphInterval
+        );
 
         return {
+          ...results,
           initialQueries: nextQueries,
           queryTransactions: nextQueryTransactions,
         };
@@ -609,7 +634,14 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
       // Append new transaction
       const nextQueryTransactions = [...remainingTransactions, transaction];
 
+      const results = calculateResultsFromQueryTransactions(
+        nextQueryTransactions,
+        state.datasource,
+        state.graphInterval
+      );
+
       return {
+        ...results,
         queryTransactions: nextQueryTransactions,
         showingStartPage: false,
       };
@@ -660,6 +692,12 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
         return qt;
       });
 
+      const results = calculateResultsFromQueryTransactions(
+        nextQueryTransactions,
+        state.datasource,
+        state.graphInterval
+      );
+
       const nextHistory = updateHistory(history, datasourceId, queries);
 
       // Keep scanning for results if this was the last scanning transaction
@@ -671,19 +709,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 +778,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 +807,10 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
       datasourceLoading,
       datasourceMissing,
       exploreDatasources,
-      graphRange,
+      graphResult,
       history,
       initialQueries,
+      logsResult,
       queryTransactions,
       range,
       scanning,
@@ -790,31 +822,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 +934,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>
@@ -938,6 +953,7 @@ export class Explore extends React.PureComponent<ExploreProps, ExploreState> {
                       <Panel label="Logs" loading={logsLoading} isOpen={showingLogs} onToggle={this.onClickLogsButton}>
                         <Logs
                           data={logsResult}
+                          key={logsResult.id}
                           loading={logsLoading}
                           position={position}
                           onChangeTime={this.onChangeTime}

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 PREVIEW_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,
   };
 
+  componentDidMount() {
+    // Staged rendering
+    if (this.state.deferLogs) {
+      const { data } = this.props;
+      const rowCount = data && data.rows ? data.rows.length : 0;
+      // Render all right away if not too far over the limit
+      const renderAll = rowCount <= PREVIEW_LIMIT * 2;
+      this.deferLogsTimer = setTimeout(() => this.setState({ deferLogs: false, renderAll }), rowCount);
+    }
+  }
+
+  componentDidUpdate(prevProps, prevState) {
+    // Staged rendering
+    if (prevState.deferLogs && !this.state.deferLogs && !this.state.renderAll) {
+      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, PREVIEW_LIMIT);
+    const lastRows = dedupedData.rows.slice(PREVIEW_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 &&

public/app/plugins/datasource/logging/result_transformer.ts

@@ -140,6 +140,9 @@ export function processEntry(
 }
 
 export function mergeStreamsToLogs(streams: LogsStream[], limit = DEFAULT_LIMIT): LogsModel {
+  // Unique model identifier
+  const id = streams.map(stream => stream.labels).join();
+
   // Find unique labels for each stream
   streams = streams.map(stream => ({
     ...stream,
@@ -184,6 +187,7 @@ export function mergeStreamsToLogs(streams: LogsStream[], limit = DEFAULT_LIMIT)
   }
 
   return {
+    id,
     meta,
     rows: sortedRows,
   };

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 {

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;