Explore: fixes log entries sorting - changes milliseconds to nanoseconds (#24303)

* Chore: adds timeEpochNs to LogRowModel in @grafana/data

* Chore: updates explore utils ResultProcessor getLogsResult and explore utils tests

* Chore: updates core/logs_model to include nanoseconds

* Chore: updates LogRowModel sorting key from milliseconds to nanoseconds and adds timeEpochNs to tests

* Chore: adds timeEpochNs to LogRowModel mock in Explore LiveLogs test

* Chore: fixes logs model timeEpochNs padding

* Chore: updates timeEpochNs padding in tests

* Chore: updates LogRowModel mocks

* Chore: changes isLoki to datasourceId

* Chore: adds hasFieldWithNameAndType method to FieldCache in grafana-data dataframe

* Chore: changes timeEpochNs from number to string as it can overflow Number.MAX_SAFE_INTEGER

* Chore: updates LogRowModel sorting to use milliseconds and nanoseconds

* Chore: removes datasourceId from logSeriesToLogsModel method

* Chore: updates ResultProcessor tests to include nanosecond-level precision log rows sorting

packages/grafana-data/src/dataframe/FieldCache.ts

@@ -67,6 +67,10 @@ export class FieldCache {
     return !!this.fieldByName[name];
   }
 
+  hasFieldWithNameAndType(name: string, type: FieldType): boolean {
+    return !!this.fieldByName[name] && this.fieldByType[type].filter(field => field.name === name).length > 0;
+  }
+
   /**
    * Returns the first field with the given name.
    */

packages/grafana-data/src/types/logs.ts

@@ -60,6 +60,9 @@ export interface LogRowModel {
   searchWords?: string[];
   timeFromNow: string;
   timeEpochMs: number;
+  // timeEpochNs stores time with nanosecond-level precision,
+  // as millisecond-level precision is usually not enough for proper sorting of logs
+  timeEpochNs: string;
   timeLocal: string;
   timeUtc: string;
   uid: string;

packages/grafana-ui/src/components/Logs/LogDetails.test.tsx

@@ -15,6 +15,7 @@ const setup = (propOverrides?: Partial<Props>, rowOverrides?: Partial<LogRowMode
       logLevel: 'error' as LogLevel,
       timeFromNow: '',
       timeEpochMs: 1546297200000,
+      timeEpochNs: '1546297200000000000',
       timeLocal: '',
       timeUtc: '',
       hasAnsi: false,

packages/grafana-ui/src/components/Logs/LogRowContextProvider.test.ts

@@ -94,6 +94,7 @@ const row: LogRowModel = {
   raw: '4',
   logLevel: LogLevel.info,
   timeEpochMs: 4,
+  timeEpochNs: '4000000',
   timeFromNow: '',
   timeLocal: '',
   timeUtc: '',

packages/grafana-ui/src/components/Logs/LogRows.test.tsx

@@ -111,6 +111,7 @@ const makeLog = (overrides: Partial<LogRowModel>): LogRowModel => {
     raw: entry,
     timeFromNow: '',
     timeEpochMs: 1,
+    timeEpochNs: '1000000',
     timeLocal: '',
     timeUtc: '',
     searchWords: [],

public/app/core/logs_model.ts

@@ -257,6 +257,7 @@ interface LogFields {
 
   timeField: FieldWithIndex;
   stringField: FieldWithIndex;
+  timeNanosecondField?: FieldWithIndex;
   logLevelField?: FieldWithIndex;
   idField?: FieldWithIndex;
 }
@@ -284,6 +285,9 @@ export function logSeriesToLogsModel(logSeries: DataFrame[]): LogsModel | undefi
     return {
       series,
       timeField: fieldCache.getFirstFieldOfType(FieldType.time),
+      timeNanosecondField: fieldCache.hasFieldWithNameAndType('tsNs', FieldType.time)
+        ? fieldCache.getFieldByName('tsNs')
+        : undefined,
       stringField,
       logLevelField: fieldCache.getFieldByName('level'),
       idField: getIdField(fieldCache),
@@ -296,7 +300,7 @@ export function logSeriesToLogsModel(logSeries: DataFrame[]): LogsModel | undefi
   let hasUniqueLabels = false;
 
   for (const info of allSeries) {
-    const { timeField, stringField, logLevelField, idField, series } = info;
+    const { timeField, timeNanosecondField, stringField, logLevelField, idField, series } = info;
     const labels = stringField.labels;
     const uniqueLabels = findUniqueLabels(labels, commonLabels);
     if (Object.keys(uniqueLabels).length > 0) {
@@ -311,6 +315,8 @@ export function logSeriesToLogsModel(logSeries: DataFrame[]): LogsModel | undefi
     for (let j = 0; j < series.length; j++) {
       const ts = timeField.values.get(j);
       const time = dateTime(ts);
+      const tsNs = timeNanosecondField ? timeNanosecondField.values.get(j) : undefined;
+      const timeEpochNs = tsNs ? tsNs : time.valueOf() + '000000';
 
       const messageValue: unknown = stringField.values.get(j);
       // This should be string but sometimes isn't (eg elastic) because the dataFrame is not strongly typed.
@@ -327,7 +333,6 @@ export function logSeriesToLogsModel(logSeries: DataFrame[]): LogsModel | undefi
       } else {
         logLevel = getLogLevel(message);
       }
-
       rows.push({
         entryFieldIndex: stringField.index,
         rowIndex: j,
@@ -335,6 +340,7 @@ export function logSeriesToLogsModel(logSeries: DataFrame[]): LogsModel | undefi
         logLevel,
         timeFromNow: dateTimeFormatTimeAgo(ts),
         timeEpochMs: time.valueOf(),
+        timeEpochNs,
         timeLocal: dateTimeFormat(ts, { timeZone: 'browser' }),
         timeUtc: dateTimeFormat(ts, { timeZone: 'utc' }),
         uniqueLabels,

public/app/core/utils/explore.test.ts

@@ -391,6 +391,7 @@ describe('sortLogsResult', () => {
     logLevel: LogLevel.info,
     raw: '',
     timeEpochMs: 0,
+    timeEpochNs: '0',
     timeFromNow: '',
     timeLocal: '',
     timeUtc: '',
@@ -407,6 +408,7 @@ describe('sortLogsResult', () => {
     logLevel: LogLevel.info,
     raw: '',
     timeEpochMs: 10,
+    timeEpochNs: '10000000',
     timeFromNow: '',
     timeLocal: '',
     timeUtc: '',

public/app/core/utils/explore.ts

@@ -482,6 +482,7 @@ export const getRefIds = (value: any): string[] => {
 };
 
 export const sortInAscendingOrder = (a: LogRowModel, b: LogRowModel) => {
+  // compare milliseconds
   if (a.timeEpochMs < b.timeEpochMs) {
     return -1;
   }
@@ -490,10 +491,20 @@ export const sortInAscendingOrder = (a: LogRowModel, b: LogRowModel) => {
     return 1;
   }
 
+  // if milliseonds are equal, compare nanoseconds
+  if (a.timeEpochNs < b.timeEpochNs) {
+    return -1;
+  }
+
+  if (a.timeEpochNs > b.timeEpochNs) {
+    return 1;
+  }
+
   return 0;
 };
 
 const sortInDescendingOrder = (a: LogRowModel, b: LogRowModel) => {
+  // compare milliseconds
   if (a.timeEpochMs > b.timeEpochMs) {
     return -1;
   }
@@ -502,6 +513,15 @@ const sortInDescendingOrder = (a: LogRowModel, b: LogRowModel) => {
     return 1;
   }
 
+  // if milliseonds are equal, compare nanoseconds
+  if (a.timeEpochNs > b.timeEpochNs) {
+    return -1;
+  }
+
+  if (a.timeEpochNs < b.timeEpochNs) {
+    return 1;
+  }
+
   return 0;
 };
 

public/app/features/explore/LiveLogs.test.tsx

@@ -72,6 +72,7 @@ const makeLog = (overides: Partial<LogRowModel>): LogRowModel => {
     raw: entry,
     timeFromNow: '',
     timeEpochMs: 1,
+    timeEpochNs: '1000000',
     timeLocal: '',
     timeUtc: '',
     ...overides,

public/app/features/explore/utils/ResultProcessor.test.ts

@@ -26,7 +26,8 @@ const testContext = (options: any = {}) => {
     refId: 'A',
     fields: [
       { name: 'value', type: FieldType.number, values: [4, 5, 6] },
-      { name: 'time', type: FieldType.time, values: [100, 200, 300] },
+      { name: 'time', type: FieldType.time, values: [100, 100, 100] },
+      { name: 'tsNs', type: FieldType.time, values: ['100000002', undefined, '100000001'] },
       { name: 'message', type: FieldType.string, values: ['this is a message', 'second message', 'third'] },
     ],
   });
@@ -125,7 +126,8 @@ describe('ResultProcessor', () => {
 
         expect(theResult?.fields[0].name).toEqual('value');
         expect(theResult?.fields[1].name).toEqual('time');
-        expect(theResult?.fields[2].name).toEqual('message');
+        expect(theResult?.fields[2].name).toEqual('tsNs');
+        expect(theResult?.fields[3].name).toEqual('message');
         expect(theResult?.fields[1].display).not.toBeNull();
         expect(theResult?.length).toBe(3);
 
@@ -135,19 +137,21 @@ describe('ResultProcessor', () => {
             columns: [
               { text: 'value', type: 'number' },
               { text: 'time', type: 'time' },
+              { text: 'tsNs', type: 'time' },
               { text: 'message', type: 'string' },
             ],
             rows: [
-              [4, 100, 'this is a message'],
-              [5, 200, 'second message'],
-              [6, 300, 'third'],
+              [4, 100, '100000000', 'this is a message'],
+              [5, 200, '100000000', 'second message'],
+              [6, 300, '100000000', 'third'],
             ],
             type: 'table',
           })
         );
         expect(theResult.fields[0].name).toEqual('value');
         expect(theResult.fields[1].name).toEqual('time');
-        expect(theResult.fields[2].name).toEqual('message');
+        expect(theResult.fields[2].name).toEqual('tsNs');
+        expect(theResult.fields[3].name).toEqual('message');
         expect(theResult.fields[1].display).not.toBeNull();
         expect(theResult.length).toBe(3);
       });
@@ -166,54 +170,57 @@ describe('ResultProcessor', () => {
           meta: [],
           rows: [
             {
-              rowIndex: 2,
+              rowIndex: 0,
               dataFrame: logsDataFrame,
-              entry: 'third',
-              entryFieldIndex: 2,
+              entry: 'this is a message',
+              entryFieldIndex: 3,
               hasAnsi: false,
               labels: {},
               logLevel: 'unknown',
-              raw: 'third',
+              raw: 'this is a message',
               searchWords: [] as string[],
-              timeEpochMs: 300,
+              timeEpochMs: 100,
+              timeEpochNs: '100000002',
               timeFromNow: 'fromNow() jest mocked',
               timeLocal: 'format() jest mocked',
               timeUtc: 'format() jest mocked',
-              uid: '2',
+              uid: '0',
               uniqueLabels: {},
             },
             {
-              rowIndex: 1,
+              rowIndex: 2,
               dataFrame: logsDataFrame,
-              entry: 'second message',
-              entryFieldIndex: 2,
+              entry: 'third',
+              entryFieldIndex: 3,
               hasAnsi: false,
               labels: {},
               logLevel: 'unknown',
-              raw: 'second message',
+              raw: 'third',
               searchWords: [] as string[],
-              timeEpochMs: 200,
+              timeEpochMs: 100,
+              timeEpochNs: '100000001',
               timeFromNow: 'fromNow() jest mocked',
               timeLocal: 'format() jest mocked',
               timeUtc: 'format() jest mocked',
-              uid: '1',
+              uid: '2',
               uniqueLabels: {},
             },
             {
-              rowIndex: 0,
+              rowIndex: 1,
               dataFrame: logsDataFrame,
-              entry: 'this is a message',
-              entryFieldIndex: 2,
+              entry: 'second message',
+              entryFieldIndex: 3,
               hasAnsi: false,
               labels: {},
               logLevel: 'unknown',
-              raw: 'this is a message',
+              raw: 'second message',
               searchWords: [] as string[],
               timeEpochMs: 100,
+              timeEpochNs: '100000000',
               timeFromNow: 'fromNow() jest mocked',
               timeLocal: 'format() jest mocked',
               timeUtc: 'format() jest mocked',
-              uid: '0',
+              uid: '1',
               uniqueLabels: {},
             },
           ],