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 a95b625800.

* complete revert

* ok it works now
pull/16128/head
Rich Harris 3 months ago committed by GitHub
parent 292af8d38a
commit 438349eb88
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194

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

@ -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,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;

@ -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];

@ -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;
}
}

@ -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 {

@ -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);
}
}
}
}

@ -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';

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

@ -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 } }
]);
}
});

@ -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}

@ -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 },

Loading…
Cancel
Save