Two function calls but only one trace displayed

Question

With GHC version 8.0.2 the following program:

import Debug.Trace

f=trace("f was called")$(+1)

main = do
    print $ f 1
    print $ f 2

outputs:

f was called
2
3

Is it the expected behaviour? If yes, why? I expected the string f was called to be printed twice, one before 2 and one before 3.

Same result on TIO: Try it online!

EDIT But this program:

import Debug.Trace

f n=trace("f was called:"++show n)$n+1

main = do
    print $ f 1
    print $ f 2

outputs:

f was called:1
2
f was called:2
3

Try it online!

I suspect those behaviours have something to do with laziness, but my questions remain: is this the expected behaviour and, if yes, why?

Hackage asserts this:

The trace function outputs the trace message given as its first argument, before returning the second argument as its result.

I don't see it in the first example.

EDIT 2 Third example based on @amalloy comments:

import Debug.Trace

f n=trace "f was called"$n+1

main = do
    print $ f 1
    print $ f 2

outputs:

f was called
2
f was called
3

Answer 1

Your trace prints when defining f, not when calling it. If you want the trace to happen as part of the call, you should make sure it is not evaluated until a parameter is received:

f x = trace "f was called" $ x + 1

Also, when I run your TIO I don't see the trace appearing at all. trace is not really a reliable way to print things, because it cheats the IO model that the language is built on. The most subtle changes in evaluation order can disturb it. Of course for debugging you can use it, but as even this simple example demonstrates it is not guaranteed to help much.

In your edit, you quote the documentation of trace:

The trace function outputs the trace message given as its first argument, before returning the second argument as its result.

And indeed this is exactly what happens in your program! When defining f,

trace "f was called" $ (+ 1)

needs to be evaluated. First, "f was called" is printed. Then, trace evaluates to, and returns, (+ 1). This is the final value of the trace expression, and therefore (+ 1) is what f is defined as. The trace has vanished, see?

Answer 2

It is indeed a result of laziness.

Laziness means that merely defining a value doesn't mean it will be evaluated; that will only happen if it's needed for something. If it's not needed, the code that would actually produce it doesn't "do anything". If a particular value is needed the code is run, but only the first time it would be needed; if there are other references to the same value and it is used again, those uses will just directly use the value that was produced the first time.

You have to remember that functions are values in every sense of the term; everything that applies to ordinary values also applies to functions. So your definition of f is simply writing an expression for a value, the expression's evaluation will be deferred until the value of f is actually needed, and as it's needed twice the value (function) the expression computes will be saved and reused the second time.

Lets look at it in more detail:

f=trace("f was called")$(+1)

You're defining a value f with a simple equation (not using any syntactic sugar for writing arguments on the left hand side of the equation, or providing cases via multiple equations). So we can simply take the right hand side as a single expression that defines the value f. Just defining it does nothing, it sits there until you call:

print $ f 1

Now print needs its argument evaluated, so this is forcing the expression f 1. But we can't apply f to 1 without first forcing f. So we need to figure out what function the expression trace "f was called" $ (+1) evaluates to. So trace is actually called, does its unsafe IO printing and f was called appears at the terminal, and then trace returns its second argument: (+1).

So now we know what function f is: (+1). f will now be a direct reference to that function, with no need to evaluate the original code trace("f was called")$(+1) if f is called again. Which is why the second print does nothing.

This case is quite different, even though it might look similar:

f n=trace("f was called:"++show n)$n+1

Here we are using the syntactic sugar for defining functions by writing arguments on the left hand side. Let's desugar that to lambda notation to see more clearly what the actual value being bound to f is:

f = \n -> trace ("f was called:" ++ show n) $ n + 1

Here we've written a function value directly, rather than an expression that can be evaluated to result in a function. So when f needs to be evaluated before it can be called on 1, the value of f is that whole function; the trace call is inside the function instead of being the thing that is called to result in a function. So trace isn't called as part of evaluating f, it's called as part of evaluating the application f 1. If you saved the result of that (say by doing let x = f 1) and then printed it multiple times, you'd only see the one trace. But the when we come to evaluate f 2, the trace call is still there inside the function that is the value of f, so when f is called again so is trace.