Added support for Papyrus profiles (#428)

Fixed #427

sample/profiles/papyrus/script.log

@@ -0,0 +1,16 @@
+Script_abc_example_quest log opened (PC)
+500:PUSH:3053:1:abcExampleQuest (24021278):abc_example_quest..exampleFunction1
+1500:POP:3053:1:abcExampleQuest (24021278):abc_example_quest..exampleFunction1
+1700:PUSH:3053:2:abcExampleQuest (24021278):abc_example_quest..exampleFunction2
+1750:POP:3053:2:abcExampleQuest (24021278):abc_example_quest..exampleFunction2
+2000:PUSH:3208:2:abcExampleQuest (24021278):abc_example_quest..exampleFunction3
+2000:PUSH:3053:3:None:abc_example_quest..exampleFunction4
+2000:POP:3208:2:abcExampleQuest (24021278):abc_example_quest..exampleFunction3
+2000:POP:3053:3:None:abc_example_quest..exampleFunction4
+2000:PUSH:3947:1:None:abc_example_quest..exampleFunction5
+2250:PUSH:3949:1:None:abc_example_quest..exampleFunction6
+2500:POP:3949:1:None:abc_example_quest..exampleFunction6
+3000:POP:3947:1:None:abc_example_quest..exampleFunction5
+3450:PUSH:3947:1:abcExampleQuest (24021278):abc_example_quest..exampleFunction1
+3500:POP:3947:1:abcExampleQuest (24021278):abc_example_quest..exampleFunction1
+Log closed

sample/profiles/papyrus/stack.log

@@ -0,0 +1,24 @@
+Stack_3185 log opened (PC)
+50002:START:3185
+50002:POP:3185:3:None:Debug..StartStackProfiling
+50002:QUEUE_PUSH:3185:3: (00018A56):Location.??.GetFormID
+50018:PUSH:3185:3: (00018A56):Form..GetFormID
+50018:POP:3185:3: (00018A56):Form..GetFormID
+50018:PUSH:3185:3:None:abc_example_mod_quest..exampleFunction1
+50018:QUEUE_PUSH:3185:4: (00018A56):Location.??.GetFormID
+50035:PUSH:3185:4: (00018A56):Form..GetFormID
+50035:POP:3185:4: (00018A56):Form..GetFormID
+50035:PUSH:3185:4:None:Game..GetModName
+50035:POP:3185:4:None:Game..GetModName
+50035:POP:3185:3:None:abc_example_mod_quest..exampleFunction1
+50035:POP:3185:2:None:abc_example_mod_quest..exampleFunction2
+50035:QUEUE_PUSH:3185:2:WhiterunPLainsDistrict03 (0001A27A):Cell.??.IsInterior
+50051:PUSH:3185:2:WhiterunPLainsDistrict03 (0001A27A):Cell..IsInterior
+50051:POP:3185:2:WhiterunPLainsDistrict03 (0001A27A):Cell..IsInterior
+50051:POP:3185:1:abcExampleModQuest (24021278):abc_example_mod_quest..exampleFunction3
+50051:QUEUE_PUSH:3185:1:None:utility.??.WaitMenuMode
+50068:PUSH:3185:1:None:utility..WaitMenuMode
+50602:POP:3185:1:None:utility..WaitMenuMode
+50602:QUEUE_POP:3185:0:None:abc_example_mod_effect..OnEffectStart
+50619:POP:3185:0:None:abc_example_mod_effect..OnEffectStart
+Log closed

src/import/__snapshots__/papyrus.test.ts.snap

@@ -0,0 +1,196 @@
+// Jest Snapshot v1, https://goo.gl/fbAQLP
+
+exports[`importFromPapyrus script profile 1`] = `
+Object {
+  "frames": Array [
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "STACK 3053",
+      "line": undefined,
+      "name": "STACK 3053",
+      "selfWeight": 200,
+      "totalWeight": 1250,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "abc_example_quest..exampleFunction1",
+      "line": undefined,
+      "name": "abc_example_quest..exampleFunction1",
+      "selfWeight": 1050,
+      "totalWeight": 1050,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "abc_example_quest..exampleFunction2",
+      "line": undefined,
+      "name": "abc_example_quest..exampleFunction2",
+      "selfWeight": 50,
+      "totalWeight": 50,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "STACK 3208",
+      "line": undefined,
+      "name": "STACK 3208",
+      "selfWeight": 0,
+      "totalWeight": 0,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "abc_example_quest..exampleFunction3",
+      "line": undefined,
+      "name": "abc_example_quest..exampleFunction3",
+      "selfWeight": 0,
+      "totalWeight": 0,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "abc_example_quest..exampleFunction4",
+      "line": undefined,
+      "name": "abc_example_quest..exampleFunction4",
+      "selfWeight": 0,
+      "totalWeight": 0,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "STACK 3947",
+      "line": undefined,
+      "name": "STACK 3947",
+      "selfWeight": 450,
+      "totalWeight": 1500,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "abc_example_quest..exampleFunction5",
+      "line": undefined,
+      "name": "abc_example_quest..exampleFunction5",
+      "selfWeight": 750,
+      "totalWeight": 1000,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "STACK 3949",
+      "line": undefined,
+      "name": "STACK 3949",
+      "selfWeight": 0,
+      "totalWeight": 250,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "abc_example_quest..exampleFunction6",
+      "line": undefined,
+      "name": "abc_example_quest..exampleFunction6",
+      "selfWeight": 250,
+      "totalWeight": 250,
+    },
+  ],
+  "name": "script.log",
+  "stacks": Array [
+    "STACK 3053;abc_example_quest..exampleFunction1 1.00s",
+    "STACK 3053 200.00ms",
+    "STACK 3053;abc_example_quest..exampleFunction2 50.00ms",
+    " 250.00ms",
+    "STACK 3947;abc_example_quest..exampleFunction5 250.00ms",
+    "STACK 3947;abc_example_quest..exampleFunction5;STACK 3949;abc_example_quest..exampleFunction6 250.00ms",
+    "STACK 3947;abc_example_quest..exampleFunction5 500.00ms",
+    "STACK 3947 450.00ms",
+    "STACK 3947;abc_example_quest..exampleFunction1 50.00ms",
+  ],
+}
+`;
+
+exports[`importFromPapyrus script profile: indexToView 1`] = `0`;
+
+exports[`importFromPapyrus script profile: profileGroup.name 1`] = `"script.log"`;
+
+exports[`importFromPapyrus stack profile 1`] = `
+Object {
+  "frames": Array [
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "STACK 3185",
+      "line": undefined,
+      "name": "STACK 3185",
+      "selfWeight": 66,
+      "totalWeight": 617,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "Debug..StartStackProfiling",
+      "line": undefined,
+      "name": "Debug..StartStackProfiling",
+      "selfWeight": 0,
+      "totalWeight": 0,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "Form..GetFormID",
+      "line": undefined,
+      "name": "Form..GetFormID",
+      "selfWeight": 0,
+      "totalWeight": 0,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "abc_example_mod_quest..exampleFunction1",
+      "line": undefined,
+      "name": "abc_example_mod_quest..exampleFunction1",
+      "selfWeight": 17,
+      "totalWeight": 17,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "Game..GetModName",
+      "line": undefined,
+      "name": "Game..GetModName",
+      "selfWeight": 0,
+      "totalWeight": 0,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "Cell..IsInterior",
+      "line": undefined,
+      "name": "Cell..IsInterior",
+      "selfWeight": 0,
+      "totalWeight": 0,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "utility..WaitMenuMode",
+      "line": undefined,
+      "name": "utility..WaitMenuMode",
+      "selfWeight": 534,
+      "totalWeight": 534,
+    },
+  ],
+  "name": "stack.log",
+  "stacks": Array [
+    "STACK 3185 16.00ms",
+    "STACK 3185;abc_example_mod_quest..exampleFunction1 17.00ms",
+    "STACK 3185 33.00ms",
+    "STACK 3185;utility..WaitMenuMode 534.00ms",
+    "STACK 3185 17.00ms",
+  ],
+}
+`;
+
+exports[`importFromPapyrus stack profile: indexToView 1`] = `0`;
+
+exports[`importFromPapyrus stack profile: profileGroup.name 1`] = `"stack.log"`;

src/import/index.ts

@@ -23,6 +23,7 @@ import {decodeBase64} from '../lib/utils'
 import {importFromChromeHeapProfile} from './v8heapalloc'
 import {isTraceEventFormatted, importTraceEvents} from './trace-event'
 import {importFromCallgrind} from './callgrind'
+import {importFromPapyrus} from "./papyrus";
 
 export async function importProfileGroupFromText(
   fileName: string,
@@ -188,6 +189,11 @@ async function _importProfileGroup(dataSource: ProfileDataSource): Promise<Profi
       return toGroup(importFromInstrumentsDeepCopy(contents))
     }
 
+    if (/^(Stack_|Script_|Obj_)\S+ log opened \(PC\)\n/.exec(contents.firstChunk())){
+      console.log("Importing as Papyrus profile")
+      return toGroup(importFromPapyrus(contents))
+    }
+
     const fromLinuxPerf = importFromLinuxPerf(contents)
     if (fromLinuxPerf) {
       console.log('Importing from linux perf script output')

src/import/papyrus.test.ts

@@ -0,0 +1,9 @@
+import {checkProfileSnapshot} from '../lib/test-utils'
+
+test('importFromPapyrus script profile', async () => {
+  await checkProfileSnapshot('./sample/profiles/papyrus/script.log')
+})
+
+test('importFromPapyrus stack profile', async () => {
+  await checkProfileSnapshot('./sample/profiles/papyrus/stack.log')
+})

src/import/papyrus.ts

@@ -0,0 +1,187 @@
+// This importer is for Papyrus, a proprietary DSL written by Bethesda for Skyrim and FO4. It is used both for the base
+// games and for mods. You can find documentation (such as the language reference) here:
+// https://ck.uesp.net/wiki/Category:Papyrus
+//
+// For mod authors: you can find documentation on how to start profiling from the console here:
+// https://ck.uesp.net/wiki/StartPapyrusScriptProfile
+// and you can also start from your script:
+// https://ck.uesp.net/wiki/StartScriptProfiling_-_Debug
+// If you want to profile an entire mod, it is often helpful to use `StartFormProfile` on your "main quest". This will
+// then profile all scripts attached to that Form.
+//
+// Papyrus works with a queue system, because it is multithreaded, but only one thread can exist per script.
+// (And we can only profile one script at a time.) We parse most "QUEUE_PUSH" events, specifically those that come
+// directly before their corresponding "PUSH" event. Other "QUEUE_PUSH" (and all "QUEUE_POP") events come, as far as I
+// can tell, from Events and are thus asynchronous. They are ignored.
+//
+// Stack profiling also puts a "START" operation at the top and a "STOP" operation at the bottom of the file. These are
+// completely useless to us.
+//
+// Stack profiling also logs the Form a method is run on. For those that are not familiar with
+// Papyrus terminology, a "Form" is an instance of a type defined by a script. E.g. a quest is a form that extends
+// the "Quest" script, and thus it has certain methods, like "CompleteQuest()". This information would be useful
+// for Debugging, but for profiling, it would hinder meaningful output in left heavy mode.
+
+import {CallTreeProfileBuilder, Frame, Profile} from '../lib/profile'
+import {KeyedSet, lastOf} from '../lib/utils'
+import {TimeFormatter} from '../lib/value-formatters'
+import {TextFileContent} from './utils'
+
+type ParsedLine = {
+  at: number
+  event: string
+  stackInt: number
+  name: string
+}
+
+export function importFromPapyrus(papyrusProfile: TextFileContent): Profile {
+  const profile = new CallTreeProfileBuilder()
+  profile.setValueFormatter(new TimeFormatter('milliseconds'))
+
+  const papyrusProfileLines = papyrusProfile
+    .splitLines()
+    .filter(line => !/^$|^Log closed$|log opened/.exec(line))
+
+  let startValue = -1
+  const firstLineParsed = parseLine(papyrusProfileLines[0])
+  if (firstLineParsed === null) throw Error
+  startValue = firstLineParsed.at
+  const lastLine = lastOf(papyrusProfileLines)
+  if (lastLine === null) throw Error
+  const lastLineParsed = parseLine(lastLine)
+  if (lastLineParsed === null) throw Error
+  const endValue = lastLineParsed.at
+
+  const nameSet = new KeyedSet<Frame>()
+  const frameStack: string[] = []
+  let lastEventAt = 0
+
+  let lastQueueFrameName: string
+  let lastQueueFrameAt: number = -1
+
+  function enterFrame(stackInt: number, at: number, frameName: string) {
+    function enterFrameHelper(at: number, frameName: string) {
+      frameStack.push(frameName)
+      profile.enterFrame(Frame.getOrInsert(nameSet, {name: frameName, key: frameName}), at)
+      lastEventAt = at
+    }
+    // Check if the last event was "QUEUE_PUSH"
+    if (lastQueueFrameAt > -1) {
+      lastQueueFrameAt = -1
+      // If the queue from last event matches our current frame,
+      if (lastQueueFrameName === frameName && lastQueueFrameAt >= lastEventAt) {
+        // first enter the queue frame at its earlier time
+        enterFrame(stackInt, lastQueueFrameAt, `QUEUE ${frameName}`)
+      }
+    }
+    const stackFrameStr = `STACK ${stackInt}`
+    // If the uppermost STACK frame on the frameStack isn't stackFrameStr
+    if (
+      [...frameStack].reverse().find(frameName => frameName.startsWith('STACK ')) !== stackFrameStr
+    ) {
+      // If we're at the bottom of the frameStack, STACK frames are kept open as long as functions only run in that
+      // specific stack and closed with the function's end if the next function runs on a different stack.
+      if (frameStack.length === 1) leaveFrame(lastEventAt)
+      enterFrameHelper(at, stackFrameStr)
+    }
+    enterFrameHelper(at, frameName)
+  }
+
+  function leaveFrame(at: number) {
+    const frame = frameStack.pop()
+    if (frame === undefined) throw Error('Tried to leave frame when nothing was on stack.')
+    profile.leaveFrame(Frame.getOrInsert(nameSet, {name: frame, key: frame}), at)
+    let topOfStack = lastOf(frameStack)
+    // Technically, the frame is popped from queue once it is pushed onto the stack (once we have "entered the frame")
+    // but since we want to visualize meaningfully, we count from QUEUE_PUSH to POP and prefix with "QUEUE ".
+    if (topOfStack !== null && topOfStack.startsWith('QUEUE ')) {
+      leaveFrame(at)
+      topOfStack = lastOf(frameStack)
+    }
+    if (frameStack.length > 1 && topOfStack !== null && topOfStack.startsWith('STACK ')) {
+      leaveFrame(at)
+    }
+    lastEventAt = at
+  }
+
+  function tryToLeaveFrame(stackInt: number, at: number, frameName: string) {
+    if (lastOf(frameStack) === frameName) {
+      leaveFrame(at)
+    } else {
+      if (lastEventAt === 0) {
+        console.log(
+          `Tried to leave frame "${frameName}" which was never entered. Assuming it has been running since the start.`,
+        )
+        enterFrame(stackInt, 0, frameName)
+        leaveFrame(at)
+      } else {
+        console.log(
+          `Tried to leave frame "${frameName}" which was never entered. Other events have happened since the start, ignoring line.`,
+        )
+      }
+    }
+  }
+
+  function parseLine(lineStr: string): ParsedLine | null {
+    if (lineStr === undefined) throw Error('Probably tried to import empty file.')
+    const lineArr = lineStr.split(':')
+    if (lineArr.length < 3) return null
+    if (startValue !== -1) {
+      return {
+        at: parseInt(lineArr[0]) - startValue,
+        event: lineArr[1],
+        stackInt: parseInt(lineArr[2]),
+        name: lineArr[5],
+      }
+    } else {
+      // When parsing the first line, we return an absolute `at` value to initialize `startValue`
+      return {
+        at: parseInt(lineArr[0]),
+        event: lineArr[1],
+        stackInt: parseInt(lineArr[2]),
+        name: lineArr[5],
+      }
+    }
+  }
+
+  papyrusProfileLines.forEach((lineStr, i, papyrusProfileLines) => {
+    const parsedLine = parseLine(lineStr)
+    if (parsedLine === null) return // continue
+    if (parsedLine.event === 'PUSH') {
+      enterFrame(parsedLine.stackInt, parsedLine.at, parsedLine.name)
+      i += 1
+      let parsedNextLine = parseLine(papyrusProfileLines[i])
+      // Search all future events in the current event for one that leaves the current frame. If it exists, leave now.
+      // This way, we avoid speedscope choking on the possibly wrong order of events. The changed order is still
+      // functionally correct, as the function took less than a millisecond to execute, which is measured as 0 (ms).
+      while (parsedNextLine !== null && parsedNextLine.at === parsedLine.at) {
+        if (
+          parsedNextLine.name === parsedLine.name &&
+          parsedNextLine.stackInt === parsedLine.stackInt &&
+          parsedNextLine.event === 'POP'
+        ) {
+          tryToLeaveFrame(parsedNextLine.stackInt, parsedNextLine.at, parsedNextLine.name)
+          // Delete the line that we successfully parsed and imported such that it is not processed twice
+          papyrusProfileLines.splice(i, 1)
+          parsedNextLine = null
+        } else {
+          i += 1
+          if (i < papyrusProfileLines.length) parsedNextLine = parseLine(papyrusProfileLines[i])
+        }
+      }
+    } else if (parsedLine.event === 'POP') {
+      tryToLeaveFrame(parsedLine.stackInt, parsedLine.at, parsedLine.name)
+    } else if (parsedLine.event === 'QUEUE_PUSH') {
+      lastQueueFrameName = parsedLine.name.replace(/\?/g, '')
+      lastQueueFrameAt = parsedLine.at
+      return
+    }
+  })
+
+  // Close frames that are still open
+  while (frameStack.length > 0) {
+    leaveFrame(endValue)
+  }
+
+  return profile.build()
+}