Add `trace` functionality #244

CrescentonC · 2024-11-30T15:57:34Z

~~TODO:~~

~~avoid obscure tracing outputs like here, which is caused by the toString() methods, which are called to compose tracing messages.~~
~~cleanup~~

The to avoid obscure tracing outputs and non-termination caused by toString(), I currently use util.inspect to show the argument and return result info in the tracing messages.

* how to compose tracelog with sanitycheck * where to put tracelog object * toString method infinite loop

bettern calling msg

…t block

need to fix: avoid "toString()"

… current block is set * add tests this make sure the indents are correct

…e tests

hkmc2/shared/src/test/mlscript-compile/Predef.mls

LPTK · 2024-12-02T03:46:56Z

Obviously you shouldn't pollute every single diff test block with a useless call to this.Predef.TraceLogger.resetIndent(0). Why is that call even necessary, when we do enable tracing?

LPTK · 2024-12-02T03:53:10Z

There is no need to use :sjs on so many test cases. Just pick one representative example and leave the others without the command. So you realize that the more useless noise you add to the difftests, the more work it I will be for us to review future changes?

CrescentonC · 2024-12-02T05:54:23Z

Obviously you shouldn't pollute every single diff test block with a useless call to this.Predef.TraceLogger.resetIndent(0). Why is that call even necessary, when we do enable tracing?

Thanks, I just realized that I could have done this better without polluting every single diff test block by using try/finally in the instrumentation, such that in the finally block the indentation level is always reset regardless of whether there is an uncaught error. I will try to make the change now.

I originally wrote this to reset indentation at the beginning of every diff test block because if a previous block throws an error at a higher indent level, blocks after that will start the trace log at a wrong level (this is because functions are instrumented when they are declared in blocks with flag traceJS, so the log will be printed no matter whether at call site traceJS is on).

There is no need to use :sjs on so many test cases. Just pick one representative example and leave the others without the command. So you realize that the more useless noise you add to the difftests, the more work it I will be for us to review future changes?

Thanks I see, I will also make the change to remove unnecessary :sjss.

CrescentonC · 2024-12-02T07:22:43Z

I have made the changes to cleanup :sjs in tests and use try/finally to avoid polluting diff test blocks. I also made a minor improvement for multiline trace messages.

LPTK

Thanks, great work.

Some remarks, though:

I actually preferred the way without finally, as it's much less invasive and likely to add much less runtime overhead. Can we move back to it? Before a block that contains tracing, in JSBackendDiffMaker you could always just host.send a nodeJS command to manually reset the indent, as in host.send("globalThis.Predef.TraceLogger.indent = 0")
I'd prefer it if tracing was disabled in non-tracing blocks, even when the block's execution involves functions that were instrumented. You could simply add a Boolean flag to Predef.TraceLogger (or set the indent to -1, tho I don't like sentinel values) which is always false unless we're tracing.
I don't like the "calling"/"return" pair. Repetitive but not very easy to parse visually. Have you considered using something like the following syntax?
```
f(1,1)(-2)
//│ > CALL g(-2)
//│ > | CALL g(-1)
//│ > | => 42
//│ > => 42
//│ = 44
```

hkmc2/shared/src/test/mlscript/codegen/TraceLog.mls

…ion level in the output logs)

… blocks calling functions defined in traced blocks will show trace by adding an `enabled` flag to predef.tracelogger

… print

CrescentonC · 2024-12-02T19:23:15Z

Some remarks, though

Thanks for your suggestions and instructions! I have pushed the changes to avoid try/finally, and in JSBackendDifftest use host.execute to directly reset the indentation level for those diff test blocks that are marked with traceJS flag. I added a flag in Predef.TraceLog so that all functionalities of tracelog is disabled when traceJS is not set for a given block, even if it calls some instrumented functions. And now CALL/=> is used.

hkmc2/jvm/src/test/scala/hkmc2/JSBackendDiffMaker.scala

LPTK · 2024-12-03T00:00:41Z

hkmc2/shared/src/test/mlscript/codegen/TraceLogIndent.mls

+:traceJS
+:re
+h(3)
+//│ ═══[RUNTIME ERROR] Error: Function 'plus' expected 2 arguments but got 1


Any idea why we're not seeing the trace up to the runtime error?

Yes, because when the ReplHost encounters an error, only the error messages are kept in its replies (

mlscript/hkmc2/jvm/src/test/scala/hkmc2/ReplHost.scala

Lines 197 to 205 in 9986302

final case class Error(syntax: Bool, message: Str) extends Reply {

override def map(f: Str => Reply): Reply = this

override def toString(): Str =

if syntax then

s"[syntax error] $message"

else

s"[runtime error] $message"

}

}

), maybe I can also make a patch to this in this PR?

Sure, that would be great, if you don't mind.

Thanks! I have pushed a commit to address this.

Great!

One last tweak, though: can we get the runtime error message after the output? Currently, it appears out of logical order:

//│ ═══[RUNTIME ERROR] Error: Function 'plus' expected 2 arguments but got 1 //│ CALL h(3) //│ | CALL g(3) //│ | | CALL g(2) //│ | | | CALL g(1) //│ | | | | CALL g(0)

It should be:

//│ CALL h(3) //│ | CALL g(3) //│ | | CALL g(2) //│ | | | CALL g(1) //│ | | | | CALL g(0) //│ ═══[RUNTIME ERROR] Error: Function 'plus' expected 2 arguments but got 1

Thanks, I have pushed the change. I also added the missing ">" at the start of each line of the output, so that now it's:

//│ > CALL h(3) //│ > | CALL g(3) //│ > | | CALL g(2) //│ > | | | CALL g(1) //│ > | | | | CALL g(0) //│ ═══[RUNTIME ERROR] Error: Function 'plus' expected 2 arguments but got 1

LPTK · 2024-12-03T11:10:34Z

hkmc2/jvm/src/test/scala/hkmc2/JSBackendDiffMaker.scala

@@ -108,6 +108,10 @@ abstract class JSBackendDiffMaker extends MLsDiffMaker:
              // Otherwise, it is considered a simple runtime error.
              raise(ErrorReport(msg"${message}" -> N :: Nil,
                source = Diagnostic.Source.Runtime))
+            if traceJS.isSet then
+              output("All outputs:")


What's with this weird "All outputs" thing? Why would the logging output preceding an error only appear when traceJS.isSet? I don't understand how you make this sort of decisions. Is there a relevant rationale, from the point of view of the user of the system?

PS: Implementation or historical details are not relevant rationales.

I guess you were not thinking about the fact that the output is useful even when no tracing is ongoing. Indeed, that's the output of printing stuff, which is currently being silenced when errors occurs (very annoying).

I previously chose to only show all outputs when traceJS is set because I found out that in most of the tests, "all output"s are just the duplicates of the error messages:

But indeed I now see that the output is useful even when no tracing is ongoing, I think maybe I can just not print out the lines showing duplicated messages and "undefined"? Or maybe I can another flag which controls whether to print all output when error?

Or maybe I can another flag which controls whether to print all output when error?

No, please! Not another flag. Again, I ask you to think about the semantics of what we're implementing here. How could adding a flag like this that controls low-level details in surprising ways be any good?

Rather, you should figure out why the runtime error appears part of the retrieved output. I believe errors are actually guarded by some invisible unicode characters. Just check how this part of the code works and simply fix it. It's not very complicated at all, as far as I remember.

And of course we should also not print the final undefined. I'm confident you can figure it out.

Thanks, I have just pushed the changes to filter error messages and final undefined in the retrieved output for ReplHost.Error. Following the implementation in ReplHost.scala I realized that uncaught errors are not guarded by special invisible characters, so I just filter them using the index of substring "Uncaught " (here and here); And others are filtered out by using the invisible character

CrescentonC and others added 13 commits November 25, 2024 17:04

wip

134dd18

* how to compose tracelog with sanitycheck * where to put tracelog object * toString method infinite loop

add test file

e0617fa

wip: more lightweight?

0e88918

more lightweight by changing how return works

a6b2958

Make minor fix

4ef68ec

Merge remote-tracking branch 'origin/hkmc2' into hkmc2-tracelog

09863fd

update after merge

6a2359b

wip

e5f2432

make trait

6a63e41

cleaner code

115efff

bettern calling msg

always restore indent level to zero at the beginning of each workshee…

aedc488

…t block

wip: add missing trace for methods

179862d

need to fix: avoid "toString()"

Merge remote-tracking branch 'origin/hkmc2' into hkmc2-tracelog

e302925

CrescentonC force-pushed the hkmc2-tracelog branch 2 times, most recently from d6a43aa to 124f84d Compare November 30, 2024 16:03

cleanup

23cbac2

CrescentonC force-pushed the hkmc2-tracelog branch from 124f84d to 23cbac2 Compare November 30, 2024 16:04

CrescentonC added 2 commits December 1, 2024 02:10

use util.inspect to avoid untermination when tracing toString methods

7fd8476

further cleanup

ea53e2c

CrescentonC marked this pull request as ready for review November 30, 2024 18:53

CrescentonC added 2 commits December 1, 2024 03:14

* reset indentlvl to 0 regardless of whether the trace flag for the…

80f2d02

… current block is set * add tests this make sure the indents are correct

modify nofib tests to enable the nofibPrelude to access predef; updat…

3176c28

…e tests

CrescentonC changed the title ~~WIP: add trace functionality~~ Add trace functionality Dec 1, 2024

LPTK reviewed Dec 2, 2024

View reviewed changes

hkmc2/shared/src/test/mlscript-compile/Predef.mls Outdated Show resolved Hide resolved

use indentLvl = prev + 1

b3651cf

CrescentonC added 2 commits December 2, 2024 15:09

use try/finally to avoid polluting every single test block

90981d9

improvement for multiline trace messages

839a573

LPTK requested changes Dec 2, 2024

View reviewed changes

hkmc2/shared/src/test/mlscript/codegen/TraceLog.mls Show resolved Hide resolved

CrescentonC added 4 commits December 3, 2024 03:08

move back to instrumentation without try/finally (with wrong indentat…

5ee3768

…ion level in the output logs)

reset tracelog indent using repl host directly; only traced diff test…

21d0ff4

… blocks calling functions defined in traced blocks will show trace by adding an `enabled` flag to predef.tracelogger

use CALL/=>

ce8c769

make one difftest output less noisy while showing multiline trace msg…

2d51d85

… print

LPTK reviewed Dec 2, 2024

View reviewed changes

hkmc2/jvm/src/test/scala/hkmc2/JSBackendDiffMaker.scala Outdated Show resolved Hide resolved

LPTK reviewed Dec 3, 2024

View reviewed changes

CrescentonC added 3 commits December 3, 2024 14:14

Merge remote-tracking branch 'origin/hkmc2' into hkmc2-tracelog

d1a1817

send command once instead of twice

8d2749b

show all tracelog outputs when error

d3ff324

LPTK reviewed Dec 3, 2024

View reviewed changes

CrescentonC added 2 commits December 4, 2024 01:34

filter out error msgs and undefined for ReplHost.Error

4f4083b

tweak the order of output; add ">" before output for errors

e6a150c

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add `trace` functionality #244

Add `trace` functionality #244

CrescentonC commented Nov 30, 2024 •

edited

Loading

LPTK commented Dec 2, 2024

LPTK commented Dec 2, 2024

CrescentonC commented Dec 2, 2024

CrescentonC commented Dec 2, 2024

LPTK left a comment •

edited by CrescentonC

Loading

CrescentonC commented Dec 2, 2024

LPTK Dec 3, 2024

CrescentonC Dec 3, 2024

LPTK Dec 3, 2024

CrescentonC Dec 3, 2024

LPTK Dec 3, 2024

CrescentonC Dec 3, 2024 •

edited

Loading

LPTK Dec 3, 2024 •

edited

Loading

LPTK Dec 3, 2024

LPTK Dec 3, 2024

CrescentonC Dec 3, 2024 •

edited

Loading

LPTK Dec 3, 2024

CrescentonC Dec 3, 2024

	final case class Error(syntax: Bool, message: Str) extends Reply {
	override def map(f: Str => Reply): Reply = this
	override def toString(): Str =
	if syntax then
	s"[syntax error] $message"
	else
	s"[runtime error] $message"
	}
	}

Add trace functionality #244

Are you sure you want to change the base?

Add trace functionality #244

Conversation

CrescentonC commented Nov 30, 2024 • edited Loading

LPTK commented Dec 2, 2024

LPTK commented Dec 2, 2024

CrescentonC commented Dec 2, 2024

CrescentonC commented Dec 2, 2024

LPTK left a comment • edited by CrescentonC Loading

Choose a reason for hiding this comment

CrescentonC commented Dec 2, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

CrescentonC Dec 3, 2024 • edited Loading

Choose a reason for hiding this comment

LPTK Dec 3, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

CrescentonC Dec 3, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Add `trace` functionality #244

Add `trace` functionality #244

CrescentonC commented Nov 30, 2024 •

edited

Loading

LPTK left a comment •

edited by CrescentonC

Loading

CrescentonC Dec 3, 2024 •

edited

Loading

LPTK Dec 3, 2024 •

edited

Loading

CrescentonC Dec 3, 2024 •

edited

Loading