diff --git a/.changeset/strong-clouds-switch.md b/.changeset/strong-clouds-switch.md new file mode 100644 index 000000000000..9444d3f16406 --- /dev/null +++ b/.changeset/strong-clouds-switch.md @@ -0,0 +1,5 @@ +--- +'svelte': patch +--- + +fix: better `$inspect.trace()` output diff --git a/packages/svelte/src/internal/client/dev/tracing.js b/packages/svelte/src/internal/client/dev/tracing.js index 18b99c31b0cf..5834f5bffd0e 100644 --- a/packages/svelte/src/internal/client/dev/tracing.js +++ b/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 } | 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,6 +78,7 @@ 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 }; @@ -101,39 +86,32 @@ export function trace(label, fn) { 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; diff --git a/packages/svelte/src/internal/client/dom/blocks/each.js b/packages/svelte/src/internal/client/dom/blocks/each.js index 2997664fa259..954dcb221461 100644 --- a/packages/svelte/src/internal/client/dom/blocks/each.js +++ b/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]; diff --git a/packages/svelte/src/internal/client/reactivity/sources.js b/packages/svelte/src/internal/client/reactivity/sources.js index ad7566f77218..40a3e4e77f14 100644 --- a/packages/svelte/src/internal/client/reactivity/sources.js +++ b/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} */ 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; } } diff --git a/packages/svelte/src/internal/client/reactivity/types.d.ts b/packages/svelte/src/internal/client/reactivity/types.d.ts index c445ade8468d..756bb98f09ac 100644 --- a/packages/svelte/src/internal/client/reactivity/types.d.ts +++ b/packages/svelte/src/internal/client/reactivity/types.d.ts @@ -16,13 +16,21 @@ export interface Value 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 { diff --git a/packages/svelte/src/internal/client/runtime.js b/packages/svelte/src/internal/client/runtime.js index 51402ac88c53..954406095904 100644 --- a/packages/svelte/src/internal/client/runtime.js +++ b/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); + } + } } } diff --git a/packages/svelte/tests/runtime-legacy/shared.ts b/packages/svelte/tests/runtime-legacy/shared.ts index c0d1177a823e..11ea9f6dda89 100644 --- a/packages/svelte/tests/runtime-legacy/shared.ts +++ b/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'; diff --git a/packages/svelte/tests/runtime-runes/samples/inspect-trace-each/Entry.svelte b/packages/svelte/tests/runtime-runes/samples/inspect-trace-each/Entry.svelte new file mode 100644 index 000000000000..a22f006dcc41 --- /dev/null +++ b/packages/svelte/tests/runtime-runes/samples/inspect-trace-each/Entry.svelte @@ -0,0 +1,8 @@ + diff --git a/packages/svelte/tests/runtime-runes/samples/inspect-trace-each/_config.js b/packages/svelte/tests/runtime-runes/samples/inspect-trace-each/_config.js new file mode 100644 index 000000000000..94cd9d8aaffa --- /dev/null +++ b/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 } } + ]); + } +}); diff --git a/packages/svelte/tests/runtime-runes/samples/inspect-trace-each/main.svelte b/packages/svelte/tests/runtime-runes/samples/inspect-trace-each/main.svelte new file mode 100644 index 000000000000..e89ee7d9bc03 --- /dev/null +++ b/packages/svelte/tests/runtime-runes/samples/inspect-trace-each/main.svelte @@ -0,0 +1,11 @@ + + + + +{#each array as entry (entry.id)} + +{/each} diff --git a/packages/svelte/tests/runtime-runes/samples/inspect-trace-reassignment/_config.js b/packages/svelte/tests/runtime-runes/samples/inspect-trace-reassignment/_config.js index 683f55f32136..b4f2cf3691fd 100644 --- a/packages/svelte/tests/runtime-runes/samples/inspect-trace-reassignment/_config.js +++ b/packages/svelte/tests/runtime-runes/samples/inspect-trace-reassignment/_config.js @@ -36,14 +36,14 @@ export default test({ { log: true }, { log: '$state', highlighted: true }, { log: 'count', highlighted: false }, - { log: 1 }, + { log: 2 }, { log: 'effect' }, { log: '$state', highlighted: false }, { log: 'checked', highlighted: false }, { log: true }, { log: '$state', highlighted: true }, { log: 'count', highlighted: false }, - { log: 2 }, + { log: 3 }, { log: 'effect' }, { log: '$state', highlighted: false }, { log: 'checked', highlighted: false },