Error: Invalid task timing data

[mbalabash]

Hello

Tracium started to fail during trace content parsing.

Error:

Error: Invalid task timing data
    at Function.getMainThreadTasks (/Users/mbalabash/Projects/opensource/estimo/node_modules/tracium/lib/main-thread-tasks.js:259:15)
    at Function.compute (/Users/mbalabash/Projects/opensource/estimo/node_modules/tracium/lib/main-thread-tasks.js:272:28)
    at Object.computeMainThreadTasks (/Users/mbalabash/Projects/opensource/estimo/node_modules/tracium/index.js:13:36)
    at generateTasksReport (/Users/mbalabash/Projects/opensource/estimo/src/reporter.js:10:18)

Code which generates this error:

async function generateTasksReport(pathToTraceFile) {
  const content = JSON.parse(await readFile(pathToTraceFile))
  return tracium.computeMainThreadTasks(content, {
    flatten: true,
  })
}

Gist with the full content of trace file where error happened: chrome-tracing.json.

Strange thing is that sometimes it works, but sometimes it doesn’t.

UPD: seems like it happens not only on latest Chrome version.

[mbalabash]

Here is events where getMainThreadTasks error happened:

const eventsWithErrors = [
  {
    event: {
      args: {},
      cat: "disabled-by-default-devtools.timeline",
      name: "RunTask",
      ph: "B",
      pid: 8851,
      tid: 775,
      ts: 464722084052,
      tts: 1164284
    },
    startTime: 1483.986,
    endTime: NaN,
    parent: undefined,
    children: [
      {
        event: [Object],
        startTime: 464722084056,
        endTime: NaN,
        parent: [Circular],
        children: [Array],
        attributableURLs: [],
        group: [Object],
        duration: NaN,
        selfTime: NaN
      }
    ],
    attributableURLs: [],
    group: {
      id: "other",
      label: "Other",
      traceEventNames: [
        "MessageLoop::RunTask",
        "TaskQueueManager::ProcessTaskFromWorkQueue",
        "ThreadControllerImpl::DoWork"
      ]
    },
    duration: NaN,
    selfTime: NaN
  },
  {
    event: {
      args: {
        src_file: "../../mojo/public/cpp/system/simple_watcher.cc",
        src_func: "Notify"
      },
      cat: "toplevel",
      name: "ThreadControllerImpl::RunTask",
      ph: "B",
      pid: 8851,
      tid: 775,
      ts: 464722084056,
      tts: 1164287
    },
    startTime: 1483.99,
    endTime: NaN,
    parent: {
      event: {
        args: {},
        cat: "disabled-by-default-devtools.timeline",
        name: "RunTask",
        ph: "B",
        pid: 8851,
        tid: 775,
        ts: 464722084052,
        tts: 1164284
      },
      startTime: 1483.986,
      endTime: NaN,
      parent: undefined,
      children: [[Circular]],
      attributableURLs: [],
      group: { id: "other", label: "Other", traceEventNames: [Array] },
      duration: NaN,
      selfTime: NaN
    },
    children: [
      {
        event: [Object],
        startTime: 464722084059,
        endTime: NaN,
        parent: [Circular],
        children: [Array],
        attributableURLs: [],
        group: [Object],
        duration: NaN,
        selfTime: NaN
      }
    ],
    attributableURLs: [],
    group: {
      id: "other",
      label: "Other",
      traceEventNames: [
        "MessageLoop::RunTask",
        "TaskQueueManager::ProcessTaskFromWorkQueue",
        "ThreadControllerImpl::DoWork"
      ]
    },
    duration: NaN,
    selfTime: NaN
  },
  {
    event: {
      args: {},
      cat: "toplevel",
      name: "unknown interface",
      ph: "B",
      pid: 8851,
      tid: 775,
      ts: 464722084059,
      tts: 1164291
    },
    startTime: 1483.993,
    endTime: NaN,
    parent: {
      event: {
        args: [Object],
        cat: "toplevel",
        name: "ThreadControllerImpl::RunTask",
        ph: "B",
        pid: 8851,
        tid: 775,
        ts: 464722084056,
        tts: 1164287
      },
      startTime: 1483.99,
      endTime: NaN,
      parent: {
        event: [Object],
        startTime: 1483.986,
        endTime: NaN,
        parent: undefined,
        children: [Array],
        attributableURLs: [],
        group: [Object],
        duration: NaN,
        selfTime: NaN
      },
      children: [[Circular]],
      attributableURLs: [],
      group: { id: "other", label: "Other", traceEventNames: [Array] },
      duration: NaN,
      selfTime: NaN
    },
    children: [
      {
        event: [Object],
        startTime: 464722084156,
        endTime: NaN,
        parent: [Circular],
        children: [Array],
        attributableURLs: [Array],
        group: [Object],
        duration: NaN,
        selfTime: NaN
      }
    ],
    attributableURLs: [],
    group: {
      id: "other",
      label: "Other",
      traceEventNames: [
        "MessageLoop::RunTask",
        "TaskQueueManager::ProcessTaskFromWorkQueue",
        "ThreadControllerImpl::DoWork"
      ]
    },
    duration: NaN,
    selfTime: NaN
  },
  {
    event: {
      args: { data: [Object] },
      cat: "devtools.timeline",
      name: "FunctionCall",
      ph: "B",
      pid: 8851,
      tid: 775,
      ts: 464722084156,
      tts: 1164388
    },
    startTime: 1484.09,
    endTime: NaN,
    parent: {
      event: {
        args: {},
        cat: "toplevel",
        name: "unknown interface",
        ph: "B",
        pid: 8851,
        tid: 775,
        ts: 464722084059,
        tts: 1164291
      },
      startTime: 1483.993,
      endTime: NaN,
      parent: {
        event: [Object],
        startTime: 1483.99,
        endTime: NaN,
        parent: [Object],
        children: [Array],
        attributableURLs: [],
        group: [Object],
        duration: NaN,
        selfTime: NaN
      },
      children: [[Circular]],
      attributableURLs: [],
      group: { id: "other", label: "Other", traceEventNames: [Array] },
      duration: NaN,
      selfTime: NaN
    },
    children: [
      {
        event: [Object],
        startTime: 464722088093,
        endTime: 464722088103,
        parent: [Circular],
        children: [],
        attributableURLs: [Array],
        group: [Object],
        duration: 10,
        selfTime: 10
      },
      {
        event: [Object],
        startTime: 464722088168,
        endTime: 464722088212,
        parent: [Circular],
        children: [],
        attributableURLs: [Array],
        group: [Object],
        duration: 44,
        selfTime: 44
      },
      {
        event: [Object],
        startTime: 464722088271,
        endTime: 464722088296,
        parent: [Circular],
        children: [],
        attributableURLs: [Array],
        group: [Object],
        duration: 25,
        selfTime: 25
      },
      {
        event: [Object],
        startTime: 464722088328,
        endTime: 464722088334,
        parent: [Circular],
        children: [],
        attributableURLs: [Array],
        group: [Object],
        duration: 6,
        selfTime: 6
      },
      {
        event: [Object],
        startTime: 464722088401,
        endTime: 464722088408,
        parent: [Circular],
        children: [],
        attributableURLs: [Array],
        group: [Object],
        duration: 7,
        selfTime: 7
      }
    ],
    attributableURLs: [
      "https://apis.google.com/_/scs/abc-static/_/js/k=gapi.gapi.en.Sj5LKyeUKoE.O/m=gapi_iframes,googleapis_client,plusone/rt=j/sv=1/d=1/ed=1/rs=AHpOoo9ToCtoaz0mr9IKXAop6Eq9AIpSlw/cb=gapi.loaded_0"
    ],
    group: {
      id: "scriptEvaluation",
      label: "Script Evaluation",
      traceEventNames: [
        "EventDispatch",
        "EvaluateScript",
        "v8.evaluateModule",
        "FunctionCall",
        "TimerFire",
        "FireIdleCallback",
        "FireAnimationFrame",
        "RunMicrotasks",
        "V8.Execute"
      ]
    },
    duration: NaN,
    selfTime: NaN
  }
];