Trace logs when derivation is not run and with wrong stale dependency.

[jheeffer]

Mobx trace is triggered on POSSIBLE staleness of dependencies. If a possibly stale dependency turns out to resolve to the old value, trace in observers was already triggered but the observer is not executed. This can be confusing as a whole dependency tree can be trace-logged even if nothing changes/gets rerun.
Moreover, if the observer becomes actually stale because of some other dependency, this is not traced anymore. This can be confusing as the actual reason for staleness/rerunning stays unknown.

Intended outcome:

Trace only logging when the derivation (computed/autorun/reaction) is actually stale.
Trace logging which (if possible even multiple) dependencies actually caused the derivation to be stale.

Actual outcome:

Trace logs the first time a derivation becomes possibly stale.
Trace logs which dependency was first to make it possibly stale.

How to reproduce the issue:

See console and comments in this jsfiddle:
https://jsfiddle.net/jasperh/apgwjsm8/38/

Versions

Mobx 4, 5 & 6

[iChenLei]

Thanks for your bug report and reproduce code. We will investigate it later.

[urugator]

(if possible even multiple)

I think it's possible, but it would affect perf in devel mode, even when you don't trace anything.
There is an optimization that skips visiting all observers on every state change, but we would have to visit them anyway just to find out whether they have tracing enabled.

[jheeffer]

Thanks @urugator !

I just applied this to my local mobx 5 lib and noticed a possible improvement.
A derivation that becomes unobserved, and possibly later observed again will not given any trace output. It leads to a run of the derivation without a trace log. This can be confusing.

A fix might be to add

if (derivation.isTracing !== TraceMode$$1.NONE) {
    console.log("[mobx] '" + derivation.name + "' is not observed anymore")
}

here
https://github.com/mobxjs/mobx/blob/main/packages/mobx/src/core/derivation.ts#L275

and

case exports.IDerivationState.NOT_TRACKING:
    if (derivation.isTracing !== TraceMode$$1.NONE) {
        console.log("[mobx] '" + derivation.name + "' is observed again.")
    }
case exports.IDerivationState.STALE:

here
https://github.com/mobxjs/mobx/blob/main/packages/mobx/src/core/derivation.ts#L88-L89

I don't know enough about mobx internals to be sure these would be the right changes. And you'd probably want to forward it to the existing tracelog fn instead. Should I try to make a PR?

[urugator]

Could you setup fiddle/sandbox for illustration?

Should I try to make a PR?

You can try, it's trial and error to me as well.

Just for clarification: by "derivation that becomes untracked"/"is not observed anymore" you mean derivation that isn't observing any observables. I am just a bit confused since observables are observed and derivations are observing/tracking ... but you can also mean it in the context of computeds, that are both derivation and observable.

EDIT: I also wonder is this a regression - in a sense that you no longer get some information that trace provided prior the fix or is this more like additional improvement/feature?

[jheeffer]

Hi! Yeah, I'll set something up tomorrow. Sorry for the lingo mix up. Still getting familiar with the exact DSL you use. Hope my edits make it clearer.

I guess my proposal is limited to computeds; it doesn't apply to autorun/reaction. When computeds become completely unobserved their cache result is cleared. Next time they become observed again they run, but this execution is not trace logged.

Is the current fix a regression: I don't think so. There's less trace logs now but that's good. We don't want logs for possible staleness that doesn't result in actual staleness (for reasons in OP). I can't imagine a use case where that is useful info? Then again, I'm not all knowing :).

So my proposal is not meant to fix a regression introduced by your fix. It's an improvement so that all reruns are traced. Not just from staleness but also from becoming re-observed (maybe you call this "tracked"?). That didn't happen before your fix either.

I do now wonder if the trace(true) API is affected by your fix, specifically the stack trace you get. The debugger is now triggered in a different part of the "derivationStatus lifecycle". I haven't really used it before. Worth a check.

[jheeffer]

Here's an example: https://jsfiddle.net/jasperh/u1bxvk2o/8/

I would expect trace to notify me on every occassion that person.name is recomputed. It does so when a dependency changes (person.nick). It does not when it becomes unobserved and then reobserved (tracked?) again (by autorun, due to change in person.isMyFriend).

Maybe we can even add the observer that made it become observed/tracked again. Like is done with dependency changes.
And on becoming unobserved/untracked, the name of the last observer that stopped observing.

Here's a version with proposed trace logs faked.
https://jsfiddle.net/jasperh/u1bxvk2o/13/
I slightly altered the messages; am I using the right tracked/untracked/observing terminology?

[urugator]

One idea would be to log on every state transition:
<DerivationName> state changed from <DerivationState> to <DerivationState> due to <reason>
However I dunno:
a) if it's always possible to provide "reasonable" reason (without complicating the code).
b) if it's usefull - it may log too many possibly uninteresting information.
c) how to cover all possible situations in tests.

I think it could suffice to log something like:
Computed value <name> was suspended (unobserved) and will recompute on next access
in

mobx/packages/mobx/src/core/computedvalue.ts

Line 254 in 5c7320f

suspend_() {

What do you think?

[jheeffer]

Thanks for finishing this up @urugator and apologies for not following up; seems like a good solution to just log on suspension : )