fix: better $inspect.trace() output (#16131)

* remove code thatcan't be reached and would error if it could

* tidy up types, fix duplication

* this seems needless

* better naming

* tidy up

* reorder

* this code doesn't appear to do anything useful, and no tests fail without it

* unused

* WIP

* revert part of #14811. it makes no sense to show the initial value, it just makes things inconsistent with deriveds. personally i find it more confusing anyway

* explanatory comment on both sides

* make things a bit more self-explanatory

* simplify

* missing type

* only log UpdatedAt for dirty signals

* changeset

* lint

* Revert "unused"

This reverts commit a95b625.

* complete revert

* ok it works now

Author: Rich-Harris

.changeset/strong-clouds-switch.md

@@ -0,0 +1,5 @@
+---
+'svelte': patch
+---
+
+fix: better `$inspect.trace()` output

packages/svelte/src/internal/client/dev/tracing.js

@@ -6,40 +6,26 @@ import { DERIVED, PROXY_PATH_SYMBOL, STATE_SYMBOL } from '#client/constants';
 import { effect_tracking } from '../reactivity/effects.js';
 import { active_reaction, captured_signals, set_captured_signals, untrack } from '../runtime.js';
 
-/** @type { any } */
+/**
+ * @typedef {{
+ *   traces: Error[];
+ * }} TraceEntry
+ */
+
+/** @type {{ reaction: Reaction | null, entries: Map<Value, TraceEntry> } | null} */
 export let tracing_expressions = null;
 
 /**
- * @param { Value } signal
- * @param { { read: Error[] } } [entry]
+ * @param {Value} signal
+ * @param {TraceEntry} [entry]
  */
 function log_entry(signal, entry) {
-	const debug = signal.debug;
-	const value = signal.trace_need_increase ? signal.trace_v : signal.v;
+	const value = signal.v;
 
 	if (value === UNINITIALIZED) {
 		return;
 	}
 
-	if (debug) {
-		var previous_captured_signals = captured_signals;
-		var captured = new Set();
-		set_captured_signals(captured);
-		try {
-			untrack(() => {
-				debug();
-			});
-		} finally {
-			set_captured_signals(previous_captured_signals);
-		}
-		if (captured.size > 0) {
-			for (const dep of captured) {
-				log_entry(dep);
-			}
-			return;
-		}
-	}
-
 	const type = (signal.f & DERIVED) !== 0 ? '$derived' : '$state';
 	const current_reaction = /** @type {Reaction} */ (active_reaction);
 	const dirty = signal.wv > current_reaction.wv || current_reaction.wv === 0;
@@ -69,17 +55,15 @@ function log_entry(signal, entry) {
 		console.log(signal.created);
 	}
 
-	if (signal.updated) {
+	if (dirty && signal.updated) {
 		// eslint-disable-next-line no-console
 		console.log(signal.updated);
 	}
 
-	const read = entry?.read;
-
-	if (read && read.length > 0) {
-		for (var stack of read) {
+	if (entry) {
+		for (var trace of entry.traces) {
 			// eslint-disable-next-line no-console
-			console.log(stack);
+			console.log(trace);
 		}
 	}
 
@@ -94,46 +78,40 @@ function log_entry(signal, entry) {
  */
 export function trace(label, fn) {
 	var previously_tracing_expressions = tracing_expressions;
+
 	try {
 		tracing_expressions = { entries: new Map(), reaction: active_reaction };
 
 		var start = performance.now();
 		var value = fn();
 		var time = (performance.now() - start).toFixed(2);
 
+		var prefix = untrack(label);
+
 		if (!effect_tracking()) {
 			// eslint-disable-next-line no-console
-			console.log(`${label()} %cran outside of an effect (${time}ms)`, 'color: grey');
+			console.log(`${prefix} %cran outside of an effect (${time}ms)`, 'color: grey');
 		} else if (tracing_expressions.entries.size === 0) {
 			// eslint-disable-next-line no-console
-			console.log(`${label()} %cno reactive dependencies (${time}ms)`, 'color: grey');
+			console.log(`${prefix} %cno reactive dependencies (${time}ms)`, 'color: grey');
 		} else {
 			// eslint-disable-next-line no-console
-			console.group(`${label()} %c(${time}ms)`, 'color: grey');
+			console.group(`${prefix} %c(${time}ms)`, 'color: grey');
 
 			var entries = tracing_expressions.entries;
 
+			untrack(() => {
+				for (const [signal, traces] of entries) {
+					log_entry(signal, traces);
+				}
+			});
+
 			tracing_expressions = null;
 
-			for (const [signal, entry] of entries) {
-				log_entry(signal, entry);
-			}
 			// eslint-disable-next-line no-console
 			console.groupEnd();
 		}
 
-		if (previously_tracing_expressions !== null && tracing_expressions !== null) {
-			for (const [signal, entry] of tracing_expressions.entries) {
-				var prev_entry = previously_tracing_expressions.get(signal);
-
-				if (prev_entry === undefined) {
-					previously_tracing_expressions.set(signal, entry);
-				} else {
-					prev_entry.read.push(...entry.read);
-				}
-			}
-		}
-
 		return value;
 	} finally {
 		tracing_expressions = previously_tracing_expressions;

packages/svelte/src/internal/client/dom/blocks/each.js

@@ -527,7 +527,7 @@ function create_item(
 	if (DEV && reactive) {
 		// For tracing purposes, we need to link the source signal we create with the
 		// collection + index so that tracing works as intended
-		/** @type {Value} */ (v).debug = () => {
+		/** @type {Value} */ (v).trace = () => {
 			var collection_index = typeof i === 'number' ? index : i.v;
 			// eslint-disable-next-line @typescript-eslint/no-unused-expressions
 			get_collection()[collection_index];

packages/svelte/src/internal/client/reactivity/sources.js

@@ -37,6 +37,8 @@ import { proxy } from '../proxy.js';
 import { execute_derived } from './deriveds.js';
 
 export let inspect_effects = new Set();
+
+/** @type {Map<Source, any>} */
 export const old_values = new Map();
 
 /**
@@ -66,7 +68,9 @@ export function source(v, stack) {
 
 	if (DEV && tracing_mode_flag) {
 		signal.created = stack ?? get_stack('CreatedAt');
-		signal.debug = null;
+		signal.updated = null;
+		signal.set_during_effect = false;
+		signal.trace = null;
 	}
 
 	return signal;
@@ -168,9 +172,9 @@ export function internal_set(source, value) {
 
 		if (DEV && tracing_mode_flag) {
 			source.updated = get_stack('UpdatedAt');
-			if (active_effect != null) {
-				source.trace_need_increase = true;
-				source.trace_v ??= old_value;
+
+			if (active_effect !== null) {
+				source.set_during_effect = true;
 			}
 		}
 

packages/svelte/src/internal/client/reactivity/types.d.ts

@@ -16,13 +16,21 @@ export interface Value<V = unknown> extends Signal {
 	rv: number;
 	/** The latest value for this signal */
 	v: V;
-	/** Dev only */
+
+	// dev-only
+	/** A label (e.g. the `foo` in `let foo = $state(...)`) used for `$inspect.trace()` */
+	label?: string;
+	/** An error with a stack trace showing when the source was created */
 	created?: Error | null;
+	/** An error with a stack trace showing when the source was last updated */
 	updated?: Error | null;
-	trace_need_increase?: boolean;
-	trace_v?: V;
-	label?: string;
-	debug?: null | (() => void);
+	/**
+	 * Whether or not the source was set while running an effect — if so, we need to
+	 * increment the write version so that it shows up as dirty when the effect re-runs
+	 */
+	set_during_effect?: boolean;
+	/** A function that retrieves the underlying source, used for each block item signals */
+	trace?: null | (() => void);
 }
 
 export interface Reaction extends Signal {

packages/svelte/src/internal/client/runtime.js

@@ -39,6 +39,7 @@ import {
 	set_dev_current_component_function
 } from './context.js';
 import { handle_error, invoke_error_boundary } from './error-handling.js';
+import { snapshot } from '../shared/clone.js';
 
 let is_flushing = false;
 
@@ -447,19 +448,13 @@ export function update_effect(effect) {
 		effect.teardown = typeof teardown === 'function' ? teardown : null;
 		effect.wv = write_version;
 
-		var deps = effect.deps;
-
-		// In DEV, we need to handle a case where $inspect.trace() might
-		// incorrectly state a source dependency has not changed when it has.
-		// That's beacuse that source was changed by the same effect, causing
-		// the versions to match. We can avoid this by incrementing the version
-		if (DEV && tracing_mode_flag && (effect.f & DIRTY) !== 0 && deps !== null) {
-			for (let i = 0; i < deps.length; i++) {
-				var dep = deps[i];
-				if (dep.trace_need_increase) {
+		// In DEV, increment versions of any sources that were written to during the effect,
+		// so that they are correctly marked as dirty when the effect re-runs
+		if (DEV && tracing_mode_flag && (effect.f & DIRTY) !== 0 && effect.deps !== null) {
+			for (var dep of effect.deps) {
+				if (dep.set_during_effect) {
 					dep.wv = increment_write_version();
-					dep.trace_need_increase = undefined;
-					dep.trace_v = undefined;
+					dep.set_during_effect = false;
 				}
 			}
 		}
@@ -775,22 +770,33 @@ export function get(signal) {
 	if (
 		DEV &&
 		tracing_mode_flag &&
+		!untracking &&
 		tracing_expressions !== null &&
 		active_reaction !== null &&
 		tracing_expressions.reaction === active_reaction
 	) {
 		// Used when mapping state between special blocks like `each`
-		if (signal.debug) {
-			signal.debug();
-		} else if (signal.created) {
-			var entry = tracing_expressions.entries.get(signal);
-
-			if (entry === undefined) {
-				entry = { read: [] };
-				tracing_expressions.entries.set(signal, entry);
-			}
+		if (signal.trace) {
+			signal.trace();
+		} else {
+			var trace = get_stack('TracedAt');
 
-			entry.read.push(get_stack('TracedAt'));
+			if (trace) {
+				var entry = tracing_expressions.entries.get(signal);
+
+				if (entry === undefined) {
+					entry = { traces: [] };
+					tracing_expressions.entries.set(signal, entry);
+				}
+
+				var last = entry.traces[entry.traces.length - 1];
+
+				// traces can be duplicated, e.g. by `snapshot` invoking both
+				// both `getOwnPropertyDescriptor` and `get` traps at once
+				if (trace.stack !== last?.stack) {
+					entry.traces.push(trace);
+				}
+			}
 		}
 	}
 

packages/svelte/tests/runtime-legacy/shared.ts

@@ -3,7 +3,7 @@ import { setImmediate } from 'node:timers/promises';
 import { globSync } from 'tinyglobby';
 import { createClassComponent } from 'svelte/legacy';
 import { proxy } from 'svelte/internal/client';
-import { flushSync, hydrate, mount, unmount } from 'svelte';
+import { flushSync, hydrate, mount, unmount, untrack } from 'svelte';
 import { render } from 'svelte/server';
 import { afterAll, assert, beforeAll } from 'vitest';
 import { compile_directory, fragments } from '../helpers.js';

packages/svelte/tests/runtime-runes/samples/inspect-trace-each/Entry.svelte

@@ -0,0 +1,8 @@
+<script>
+	let { entry } = $props();
+
+	$effect(() => {
+		$inspect.trace('effect');
+		entry;
+	});
+</script>

packages/svelte/tests/runtime-runes/samples/inspect-trace-each/_config.js

@@ -0,0 +1,40 @@
+import { flushSync } from 'svelte';
+import { test } from '../../test';
+import { normalise_trace_logs } from '../../../helpers.js';
+
+export default test({
+	compileOptions: {
+		dev: true
+	},
+
+	test({ assert, target, logs }) {
+		assert.deepEqual(normalise_trace_logs(logs), [
+			{ log: 'effect' },
+			{ log: '$state', highlighted: true },
+			{ log: 'array', highlighted: false },
+			{ log: [{ id: 1, hi: true }] },
+			// this _doesn't_ appear in the browser, but it does appear during tests
+			// and i cannot for the life of me figure out why. this does at least
+			// test that we don't log `array[0].id` etc
+			{ log: '$state', highlighted: true },
+			{ log: 'array[0]', highlighted: false },
+			{ log: { id: 1, hi: true } }
+		]);
+
+		logs.length = 0;
+
+		const button = target.querySelector('button');
+		button?.click();
+		flushSync();
+
+		assert.deepEqual(normalise_trace_logs(logs), [
+			{ log: 'effect' },
+			{ log: '$state', highlighted: true },
+			{ log: 'array', highlighted: false },
+			{ log: [{ id: 1, hi: false }] },
+			{ log: '$state', highlighted: false },
+			{ log: 'array[0]', highlighted: false },
+			{ log: { id: 1, hi: false } }
+		]);
+	}
+});

packages/svelte/tests/runtime-runes/samples/inspect-trace-each/main.svelte

@@ -0,0 +1,11 @@
+<script>
+	import Entry from './Entry.svelte';
+
+	let array = $state([{ id: 1, hi: true }]);
+</script>
+
+<button onclick={() => array = [{ id: 1, hi: false}]}>update</button>
+
+{#each array as entry (entry.id)}
+	<Entry {entry} />
+{/each}