Merge pull request #103 from SuperFlyTV/fix/better-trace-resolving

Add tracing of resolve, for troubleshooting

src/__tests__/basic.spec.ts

@@ -1,6 +1,7 @@
 /* eslint-disable jest/no-standalone-expect */
 
 import { EventType, ResolvedTimelineObject, TimelineObjectInstance, getResolvedState, resolveTimeline } from '..'
+
 import { baseInstances } from '../resolver/lib/instance'
 import { describeVariants } from './testlib'
 
@@ -1695,6 +1696,7 @@ describeVariants(
 				resolvedKeyframeCount: 0,
 				resolvingObjectCount: 0,
 				resolvingCount: 0,
+				resolveTrace: [],
 			})
 		})
 		test('Class state overrides', () => {

src/__tests__/index.spec.ts

@@ -7,6 +7,7 @@ import {
 	resolveTimeline,
 	getResolvedState,
 	applyKeyframeContent,
+	ResolveError,
 } from '../index'
 import { baseInstances } from '../resolver/lib/instance'
 import { clone } from '../resolver/lib/lib'
@@ -879,4 +880,68 @@ describe('index', () => {
 
 		expect(state1.layers['layerA']).toEqual(state1NoCache.layers['layerA'])
 	})
+	test('traceResolving', () => {
+		const timeline: TimelineObject<any>[] = [
+			{
+				id: 'A',
+				layer: 'L',
+				enable: { start: 100, duration: 1 },
+				content: {},
+				priority: 0,
+			},
+		]
+
+		const resolved = resolveTimeline(timeline, {
+			cache: {},
+			time: 0,
+			traceResolving: true,
+		})
+
+		// Note: The exact content of the trace isn't that important, since it's for troubleshooting purposes
+		expect(resolved.statistics.resolveTrace).toMatchObject([
+			'init',
+			'resolveTimeline start',
+			'timeline object count 1',
+			'objects: 1',
+			'using cache',
+			'cache: init',
+			'cache: canUseIncomingCache: false',
+			'cache: cached objects: []',
+			'cache: object "A" is new',
+			'Resolver: Step 1a',
+			'Resolver: Resolve object "A"',
+			'Resolver: object "A" resolved.instances: [{"id":"@A_0","start":100,"end":101,"references":[]}]',
+			'Resolver: object "A" directReferences: []',
+			'Resolver: Step 1b',
+			'Resolver: Resolve conflicts for layers: ["L"]',
+			'LayerState: Resolve conflicts for layer "L", objects: A',
+			'Resolver: Step 2',
+			'resolveTimeline done!',
+		])
+	})
+	test('thrown errors should be ResolveError', () => {
+		const timeline: TimelineObject<any>[] = [
+			{
+				id: 'A',
+				layer: 'L',
+				enable: { start: 'badexpression((' },
+				content: {},
+				priority: 0,
+			},
+		]
+
+		{
+			let error: any = null
+			try {
+				resolveTimeline(timeline, {
+					time: 0,
+					traceResolving: true,
+				})
+			} catch (e) {
+				error = e
+			}
+			expect(error).toBeInstanceOf(ResolveError)
+			expect(error.resolvedTimeline).toBeTruthy()
+		}
+	})
 })

src/api/resolvedTimeline.ts

@@ -48,6 +48,9 @@ export interface ResolvedTimeline<TContent extends Content = Content> {
 		 * (is affected when using cache)
 		 */
 		resolvingCount: number
+
+		/** If traceResolving option is enabled, will contain a trace of the steps the resolver did while resolving */
+		resolveTrace: string[]
 	}
 	/** Is set if there was an error during Resolving and options.dontThrowOnError is set. */
 	error?: Error

src/api/resolver.ts

@@ -37,6 +37,12 @@ export interface ResolveOptions {
 	 */
 	debug?: boolean
 
+	/**
+	 * If true, will store traces of the resolving into resolvedTimeline.statistics.resolveTrace.
+	 * This decreases performance slightly.
+	 */
+	traceResolving?: boolean
+
 	/**
 	 * Skip timeline validation.
 	 * This improves performance slightly, but will not catch errors in the input timeline so use with caution.
@@ -46,7 +52,7 @@ export interface ResolveOptions {
 	/** Skip generating statistics, this improves performance slightly. */
 	skipStatistics?: boolean
 
-	/** Don't throw when an error (such as circular dependency) occurs. The Error will instead be written to resolvedTimeline.error */
+	/** Don't throw when a timeline-error (such as circular dependency) occurs. The Error will instead be written to resolvedTimeline.error */
 	dontThrowOnError?: boolean
 }
 export interface ResolverCache<TContent extends Content = Content> {

src/index.ts

@@ -11,6 +11,7 @@ import {
 	TimelineObject,
 } from './api'
 export * from './api'
+export { ResolveError } from './resolver/lib/Error'
 
 import { StateHandler } from './resolver/StateHandler'
 import { ExpressionHandler } from './resolver/ExpressionHandler'

src/resolver/CacheHandler.ts

@@ -17,22 +17,26 @@ export class CacheHandler {
 
 		if (!cache.canBeUsed) {
 			// Reset the cache:
-			cache.objHashes = {}
-			cache.objects = {}
+			CacheHandler.resetCache(cache)
 
 			this.canUseIncomingCache = false
 		} else {
 			this.canUseIncomingCache = true
 		}
 
+		if (this.resolvedTimeline.traceResolving) {
+			this.resolvedTimeline.addResolveTrace(`cache: init`)
+			this.resolvedTimeline.addResolveTrace(`cache: canUseIncomingCache: ${this.canUseIncomingCache}`)
+			this.resolvedTimeline.addResolveTrace(
+				`cache: cached objects: ${JSON.stringify(Object.keys(cache.objects))}`
+			)
+		}
+
 		// cache.canBeUsed will be set in this.persistData()
 		cache.canBeUsed = false
 
 		this.cache = cache as ResolverCache
 	}
-	private debug(...args: any[]) {
-		if (this.resolvedTimeline.options.debug) console.log(...args)
-	}
 	public determineChangedObjects(): void {
 		const toc = tic('  cache.determineChangedObjects')
 		// Go through all new objects, and determine whether they have changed:
@@ -45,8 +49,15 @@ export class CacheHandler {
 			const newHash = hashTimelineObject(obj)
 			allNewObjects[obj.id] = true
 
-			if (!oldHash) this.debug(`Cache: Object "${obj.id}" is new`)
-			else if (oldHash !== newHash) this.debug(`Cache: Object "${obj.id}" has changed`)
+			if (!oldHash) {
+				if (this.resolvedTimeline.traceResolving) {
+					this.resolvedTimeline.addResolveTrace(`cache: object "${obj.id}" is new`)
+				}
+			} else if (oldHash !== newHash) {
+				if (this.resolvedTimeline.traceResolving) {
+					this.resolvedTimeline.addResolveTrace(`cache: object "${obj.id}" has changed`)
+				}
+			}
 			if (
 				// Object is new:
 				!oldHash ||
@@ -61,16 +72,20 @@ export class CacheHandler {
 			} else {
 				// No timing-affecting changes detected
 				/* istanbul ignore if */
-				if (!oldHash) this.debug(`Cache: Object "${obj.id}" is similar`)
+				if (!oldHash) {
+					if (this.resolvedTimeline.traceResolving) {
+						this.resolvedTimeline.addResolveTrace(`cache: object "${obj.id}" is similar`)
+					}
+				}
 
 				// Even though the timeline-properties hasn't changed,
 				// the content (and other properties) might have:
 				const oldObj = this.cache.objects[obj.id]
 
 				/* istanbul ignore if */
 				if (!oldObj) {
-					console.error('oldHash', oldHash)
-					console.error('ids', Object.keys(this.cache.objects))
+					console.error(`oldHash: "${oldHash}"`)
+					console.error(`ids: ${JSON.stringify(Object.keys(this.cache.objects))}`)
 					throw new Error(`Internal Error: obj "${obj.id}" not found in cache, even though hashes match!`)
 				}
 
@@ -149,15 +164,28 @@ export class CacheHandler {
 			for (const reference of changedTracker.listChanged()) {
 				invalidator.invalidateObjectsWithReference(reference)
 			}
+			if (this.resolvedTimeline.traceResolving) {
+				this.resolvedTimeline.addResolveTrace(
+					`cache: changed references: ${JSON.stringify(Array.from(changedTracker.listChanged()))}`
+				)
+				this.resolvedTimeline.addResolveTrace(
+					`cache: invalidated objects: ${JSON.stringify(Array.from(invalidator.getInValidObjectIds()))}`
+				)
+				this.resolvedTimeline.addResolveTrace(
+					`cache: unchanged objects: ${JSON.stringify(invalidator.getValidObjects().map((o) => o.id))}`
+				)
+			}
 
 			// At this point, the objects that are left in validObjects are still valid (ie has not changed or is affected by any others).
 			// We can reuse the old resolving for those:
 			for (const obj of invalidator.getValidObjects()) {
-				if (!this.cache.objects[obj.id])
+				if (!this.cache.objects[obj.id]) {
 					/* istanbul ignore next */
 					throw new Error(
-						`Something went wrong: "${obj.id}" does not exist in cache.resolvedTimeline.objects`
+						`Internal Error: Something went wrong: "${obj.id}" does not exist in cache.resolvedTimeline.objects`
 					)
+				}
+
 				this.resolvedTimeline.objectsMap.set(obj.id, this.cache.objects[obj.id])
 			}
 		}
@@ -179,6 +207,12 @@ export class CacheHandler {
 
 		toc()
 	}
+	/** Resets / Clears the cache */
+	static resetCache(cache: Partial<ResolverCache>): void {
+		delete cache.canBeUsed
+		cache.objHashes = {}
+		cache.objects = {}
+	}
 }
 /** Return a "hash-string" which changes whenever anything that affects timing of a timeline-object has changed. */
 export function hashTimelineObject(obj: ResolvedTimelineObject): string {
@@ -210,21 +244,26 @@ function getAllReferencesThisObjectAffects(newObj: ResolvedTimelineObject): Refe
 	}
 	return references
 }
+/**
+ * Keeps track of which timeline object have been changed
+ */
 class ChangedTracker {
 	private changedReferences = new Set<Reference>()
 
+	/**
+	 * Mark an object as "has changed".
+	 * Will store all references that are affected by this object.
+	 */
 	public addChangedObject(obj: ResolvedTimelineObject) {
-		const references = getAllReferencesThisObjectAffects(obj)
-		for (const ref of references) {
+		for (const ref of getAllReferencesThisObjectAffects(obj)) {
 			this.changedReferences.add(ref)
 		}
-		if (objHasLayer(obj)) {
-			this.changedReferences.add(`$${obj.layer}`)
-		}
 	}
+	/** Returns true if a reference has changed */
 	public isChanged(ref: Reference): boolean {
 		return this.changedReferences.has(ref)
 	}
+	/** Returns a list of all changed references */
 	public listChanged(): IterableIterator<Reference> {
 		return this.changedReferences.keys()
 	}
@@ -236,6 +275,7 @@ class Invalidator {
 	/** All references that depend on another reference (ie objects, class or layers): */
 	private affectReferenceMap: { [ref: Reference]: Reference[] } = {}
 	private validObjects: ResolvedTimelineObjects = {}
+	private inValidObjectIds: string[] = []
 	/** Map of which objects can be affected by any other object, per layer */
 	private objectLayerMap: { [layer: string]: string[] } = {}
 
@@ -245,6 +285,9 @@ class Invalidator {
 	public getValidObjects(): ResolvedTimelineObject[] {
 		return Object.values<ResolvedTimelineObject>(this.validObjects)
 	}
+	public getInValidObjectIds(): string[] {
+		return this.inValidObjectIds
+	}
 	public addObjectOnLayer(layer: string, obj: ResolvedTimelineObject) {
 		if (!this.objectLayerMap[layer]) this.objectLayerMap[layer] = []
 		this.objectLayerMap[layer].push(obj.id)
@@ -263,6 +306,7 @@ class Invalidator {
 			const objId = getRefObjectId(reference)
 			if (this.validObjects[objId]) {
 				delete this.validObjects[objId]
+				this.inValidObjectIds.push(objId)
 			}
 		}
 		if (isLayerReference(reference)) {